Jump to content

pedeathtrian

Member
  • Content Count

    284
  • Joined

  • Last visited

  • Medals

Posts posted by pedeathtrian


  1. Wrong line numbers in report.

    Detected == Could be changed to go faster on line 35. Search up relevant commands on BIS wiki.

    When in fact it's 18th line.

    Detected == Could be changed to go faster on line 67. Search up relevant commands on BIS wiki.
    is given for 34th line, i.e. 2n-1.

    File has \n line separators (LF, 0x0A).


  2. Exceptions in SQFanalysis tool

    1. Select folder with files.

    2. Click in empty space in list with files

    Exception text

    ************** Exception Text **************

    System.ArgumentOutOfRangeException: Index was out of range. Must be non-negative and less than the size of the collection.
    Parameter name: index
       at System.ThrowHelper.ThrowArgumentOutOfRangeException()
       at System.Collections.Generic.List`1.get_Item(Int32 index)
       at System.Collections.ObjectModel.Collection`1.get_Item(Int32 index)
       at arma3scriptgen.SQFanalysis.ListBox1_SelectedIndexChanged(Object sender, EventArgs e)
       at System.Windows.Forms.ListBox.OnSelectedIndexChanged(EventArgs e)
       at System.Windows.Forms.ListBox.WmReflectCommand(Message& m)
       at System.Windows.Forms.ListBox.WndProc(Message& m)
       at System.Windows.Forms.Control.ControlNativeWindow.OnMessage(Message& m)
       at System.Windows.Forms.Control.ControlNativeWindow.WndProc(Message& m)
       at System.Windows.Forms.NativeWindow.Callback(IntPtr hWnd, Int32 msg, IntPtr wparam, IntPtr lparam)

     
    Loaded assemblies

    ************** Loaded Assemblies **************
    mscorlib
        Assembly Version: 4.0.0.0
        Win32 Version: 4.0.30319.34209 built by: FX452RTMGDR
        CodeBase: file:///C:/Windows/Microsoft.NET/Framework/v4.0.30319/mscorlib.dll
    ----------------------------------------
    Arma 3 Editing Tool
        Assembly Version: 1.7.0.0
        Win32 Version: 1.7.0.0
        CodeBase: file:///D:/A3/AUSMD_Editing_Tool/Arma%203%20Editing%20Tool.exe
    ----------------------------------------
    Microsoft.VisualBasic
        Assembly Version: 10.0.0.0
        Win32 Version: 12.0.51209.34209 built by: FX452RTMGDR
        CodeBase: file:///C:/Windows/Microsoft.Net/assembly/GAC_MSIL/Microsoft.VisualBasic/v4.0_10.0.0.0__b03f5f7f11d50a3a/Microsoft.VisualBasic.dll
    ----------------------------------------
    System
        Assembly Version: 4.0.0.0
        Win32 Version: 4.0.30319.34238 built by: FX452RTMGDR
        CodeBase: file:///C:/Windows/Microsoft.Net/assembly/GAC_MSIL/System/v4.0_4.0.0.0__b77a5c561934e089/System.dll
    ----------------------------------------
    System.Core
        Assembly Version: 4.0.0.0
        Win32 Version: 4.0.30319.34209 built by: FX452RTMGDR
        CodeBase: file:///C:/Windows/Microsoft.Net/assembly/GAC_MSIL/System.Core/v4.0_4.0.0.0__b77a5c561934e089/System.Core.dll
    ----------------------------------------
    System.Windows.Forms
        Assembly Version: 4.0.0.0
        Win32 Version: 4.0.30319.34251 built by: FX452RTMGDR
        CodeBase: file:///C:/Windows/Microsoft.Net/assembly/GAC_MSIL/System.Windows.Forms/v4.0_4.0.0.0__b77a5c561934e089/System.Windows.Forms.dll
    ----------------------------------------
    System.Drawing
        Assembly Version: 4.0.0.0
        Win32 Version: 4.0.30319.34270 built by: FX452RTMGDR
        CodeBase: file:///C:/Windows/Microsoft.Net/assembly/GAC_MSIL/System.Drawing/v4.0_4.0.0.0__b03f5f7f11d50a3a/System.Drawing.dll
    ----------------------------------------
    System.Runtime.Remoting
        Assembly Version: 4.0.0.0
        Win32 Version: 4.0.30319.34245 built by: FX452RTMGDR
        CodeBase: file:///C:/Windows/Microsoft.Net/assembly/GAC_MSIL/System.Runtime.Remoting/v4.0_4.0.0.0__b77a5c561934e089/System.Runtime.Remoting.dll
    ----------------------------------------
    System.Configuration
        Assembly Version: 4.0.0.0
        Win32 Version: 4.0.30319.34209 built by: FX452RTMGDR
        CodeBase: file:///C:/Windows/Microsoft.Net/assembly/GAC_MSIL/System.Configuration/v4.0_4.0.0.0__b03f5f7f11d50a3a/System.Configuration.dll
    ----------------------------------------
    System.Xml
        Assembly Version: 4.0.0.0
        Win32 Version: 4.0.30319.34234 built by: FX452RTMGDR
        CodeBase: file:///C:/Windows/Microsoft.Net/assembly/GAC_MSIL/System.Xml/v4.0_4.0.0.0__b77a5c561934e089/System.Xml.dll
    ----------------------------------------

     

  3. Getting arrays of available headgears and uniforms.

    allwdHg = [];
    allwdUf = [];
    {
    	allwdUf pushBack getText(_x >> "uniformClass");
    	// if collecting headgears for all classes
    	if (isArray(_x >> "allowedHeadgear")) then {
    		allwdHg append getArray(_x >> "allowedHeadgear");
    	};
    	if (isArray(_x >> "allowedHeadgearB")) then {
    		allwdHg append getArray(_x >> "allowedHeadgearB");
    	};
    }
    // 1 is for WEST guerillas, i.e. B_G_* classes, which FIAs are
    count ("getNumber(_x >> 'side') == 1" configClasses (configFile >> "I_G_Soldier_base_F"));
    allwdHg = (allwdHg arrayIntersect allwdHg);
    allwdUf = (allwdUf arrayIntersect allwdUf);
    

    Non-guerilla units seem not to have allowedHeadgear* arrays.

    Hope that helps.


  4. A post of clarifications (I hope).

     

    When I write some code (mostly C/C++) I usually first write it, debug it and then profile when needed.

    I'm quite new to SQF, but the habit is strong, so I find lack of profiling tools kinda disappointing.

    So I wanted to write profiling tool for SQF, but first I investigate the possibility of such tool creation (here comes this topic).

    The tool that could produce output similar to gprof for example, with Flat profile, Call graphs and Annotated source (since I always know what __FILE__ script runs, on what __LINE__, and I can loadFile it for annotation). Line by line would require too much changes to source code, so I wasn't planning to impement it.

    Script writer would be able to put some marks in his code (just like diag_tickTime, but with collecting this info). Every time execution hit the mark, some info is stored somewhere for later analysis.

    After some (possibly a lot) of executions, analysis is done and information in one of the mentioned formats is logged. Then script writer reads it and eliminates bottle necks in his code; sees what functions call what and possible detect code that is not executed at all. Some coverage testing can be done also.

    If implemented using macros, this method would only affect performance in debug/profiling mode and only be used by script writer on development stage.

    It will always have some overhead on preprocessing stage though.

     

    Everyone in community could benefit from existence of such tool: developers create more effective code; players get missions that run faster; fps rises; everyone happy.

    SQF codebase and its complexity rises day by day. At some point in the future there will be definitely a necessity of having such tool.

    Ideally there would be built-in profiling capabilities for SQF (e.g. in prof build), which would not require much changes to source code, but I don't expect it to appear.

     

    The problem now is I cannot rely on diag_tickTime command for implementing such tool for the reasons provided in this topic earlier. Probably, on long runs this will not influence too much and stats will strive closer to real numbers, I dunno.

    Thx to MarkCode82 for mentioning diag_activeSQFScripts. I think it's possible to implement sampling profiling on top of it (though it's not very accurate and wasn't my goal initially).

     

    Thx to killzone_kid, I found those debug/prof branch builds with support for diag_*Frame commands. Will try it when prof build for hotfix is ready. For now, I'm still not sure if it porovides abilities to profile SQF code in the way I can get output in mentioned formats.

     

    If you have any information that can help me implement a profiler for SQF (or stop at once creating weird stuff), please share.

    Thank you.

     


  5. Thanks for reply, deadfast. 

    Since Arma 2 the script can be interrupted on any instruction. In case of your example that would be the assignment, the subtractions and the addition.

    That's what I thought it would do.

     

    You don't. This isn't information exposed to the script.

    And that too, unforutnately. Actually I don't care about context switches, only about times.

     

    And seems like I found sort-of answer for my 3rd question. In the place I should've been looked first. On sleep's page in comments section Sbsmac writes:

    To wait for the next frame, or give other scripts a chance to run, use Sleep 0.001

     


  6. I mean, if I had the "CPU clock" in addition to "wall clock" (diag_tickTime), that would be enough for me. I mean the ability to know how much time this script runs. The clock that stops when scheduler runs other scripts, and runs only when your script runs.

    Any OS has such clock for their processes (you can see it in task manager for example).

    Should require very small change to interpreter and insignificant overhead on execution.

     

    Then you can measure your code for the time it was really running, not some wall clock time.


  7. Check this article: addAction.

     

    Parameters array passed to the script upon activation in _this variable is: [target, caller, ID, arguments]

     

    on.sqf will look like:

    params ["_object", "", "_id", ["_args", [], [[]], [1,2]]];
    _args params [["_rgb", [1,1,1], [[]], [3]], ["_br", 0.12, [0]]]; // defaults are white light with brightness 0.12
    private ["_h", "_nom"]
    
    _h = getPosATL _object;
    _object removeAction _id;
    
    _nom = "#lightpoint" createVehicle position _object;
    _nom setposATL _h;
    _nom lightAttachObject [_object, [-0,0,0]];
    _nom setLightColor _rgb;
    _nom setLightAmbient _rgb;
    _nom setLightBrightness _br;
    
    _object addAction ["<t color='#2EFE64'>Eteindre.</t>",{0 = _this execVM "off.sqf"}, [_nom, _rgb, _br]]; 

    off.sqf:

    params ["_object", "", "_id", ["_args", [], [[]], [1,2,3]]];
    _args params [["_lightSource", objNull, [objNull]], ["_rgb", [1,1,1], [[]], [3]], ["_br", 0.12, [0]]];
    
    _object removeAction _id;
    deleteVehicle _lightSource;
    
    _object addAction ["<t color='#2EFE64'>Allumer.</t>",{0 = _this execVM "on.sqf"}, [_rgb, _br]];
    

    When you first add "On" action to object (ususally right after acreate),  specify light parameters manually:

    _rendre = _object addAction ["<t color='#2EFE64'>Allumer.</t>",{0 = _this execVM "on.sqf"}, [[1,0.1,0.1], 0.2]]; // for red light
    

    Later they will be kept in actions arguments. I also suggest you not use removeAllActions too much as it interferes with other actions being added to objects.

    • Like 1

  8. This ^^^ makes no sense for 2 reasons.

    1. To use waitUntil you have to use scheduled script, so why launch another scheduled script from already scheduled script if you can just call it?

    2. Returning _ret from scheduled script will return exactly nothing, because scheduled scripts cannot return value.

    Those are all (bad) decorations to the idea of my post: you can get value from spawned code other than through global variable.

    _arr = [];
    _sh = _arr spawn {
        _this pushBack (2+2);
    };
    
    // ... some time later
    // access
    _var = _arr select 0; // could become nil
    

  9. 1. assignAsCargo does not take array as right argument.

    2. moveInCargo's right argument's second element in array must be Number, i.e. cargoIndex, not Array (in your case turretPath)

    3. Even if you use _c_t3 instead of _c_t4 you might not sit all soldiers from squad on the same place (using same cargo index for all). Collect all free cargo indexes and move one soldier per one cargo index.

    • Like 1

  10. This post contains misinformation. See next post for details.

     

    Hello, here I am again, now with some numbers.

    I wrote some testing code to compare performance of different implementations of shuffle function. So this is the report.

     

    1. Testing environment

    CPU: Intel® Core i7-3770K CPU @ 3.40GHz

    RAM: 16 GiB DDR3 1600MHz

    OS: Windows 7 x64 Ultimate

    ArmA3: current stable version, main branch, 1.56.134787

    Loaded mods: CBA_A3 current version from Steam workshop, 2.3.1.160220

    Start parameters: -showScriptErrors -maxMem=2047 -cpuCount=8 -noPause

     

    2. Testing code

    I created empty mission in VR; put trigger there and a rifleman in its area. After few seconds testing procedure starts working.

    mission.sqm:



    version=12;
    class Mission
    {
    addOns[]=
    {
    "A3_Characters_F_OPFOR",
    "a3_characters_f",
    "map_vr"
    };
    addOnsAuto[]=
    {
    "A3_Characters_F_OPFOR",
    "a3_characters_f",
    "map_vr"
    };
    randomSeed=5632393;
    class Intel
    {
    timeOfChanges=1800.0002;
    startWeather=0;
    startWind=0.1;
    startWaves=0.1;
    forecastWeather=0;
    forecastWind=0.1;
    forecastWaves=0.1;
    forecastLightnings=0.1;
    year=2035;
    day=28;
    hour=13;
    minute=37;
    startFogDecay=0.0049999999;
    forecastFogDecay=0.0049999999;
    };
    class Groups
    {
    items=1;
    class Item0
    {
    side="EAST";
    class Vehicles
    {
    items=1;
    class Item0
    {
    position[]={1.3241079,5,0.91894531};
    id=0;
    side="EAST";
    vehicle="O_Soldier_F";
    player="PLAYER COMMANDER";
    leader=1;
    skill=0.60000002;
    init="this setPos [0,0,0]";
    };
    };
    };
    };
    class Sensors
    {
    items=1;
    class Item0
    {
    position[]={-2.7722609,5,2.7626953};
    activationBy="ANY";
    timeoutMin=3;
    timeoutMid=3;
    timeoutMax=3;
    interruptable=1;
    age="UNKNOWN";
    expActiv="call compile preprocessFileLineNumbers ""test_shuffle.sqf""";
    class Effects
    {
    sound="FD_Timer_F";
    };
    };
    };
    };
    class Intro
    {
    addOns[]=
    {
    "map_vr"
    };
    addOnsAuto[]=
    {
    "map_vr"
    };
    randomSeed=14954384;
    class Intel
    {
    timeOfChanges=1800.0002;
    startWeather=0;
    startWind=0.1;
    startWaves=0.1;
    forecastWeather=0;
    forecastWind=0.1;
    forecastWaves=0.1;
    forecastLightnings=0.1;
    year=2035;
    day=28;
    hour=13;
    minute=37;
    startFogDecay=0.0049999999;
    forecastFogDecay=0.0049999999;
    };
    };
    class OutroWin
    {
    addOns[]=
    {
    "map_vr"
    };
    addOnsAuto[]=
    {
    "map_vr"
    };
    randomSeed=5667227;
    class Intel
    {
    timeOfChanges=1800.0002;
    startWeather=0;
    startWind=0.1;
    startWaves=0.1;
    forecastWeather=0;
    forecastWind=0.1;
    forecastWaves=0.1;
    forecastLightnings=0.1;
    year=2035;
    day=28;
    hour=13;
    minute=37;
    startFogDecay=0.0049999999;
    forecastFogDecay=0.0049999999;
    };
    };
    class OutroLoose
    {
    addOns[]=
    {
    "map_vr"
    };
    addOnsAuto[]=
    {
    "map_vr"
    };
    randomSeed=424579;
    class Intel
    {
    timeOfChanges=1800.0002;
    startWeather=0;
    startWind=0.1;
    startWaves=0.1;
    forecastWeather=0;
    forecastWind=0.1;
    forecastWaves=0.1;
    forecastLightnings=0.1;
    year=2035;
    day=28;
    hour=13;
    minute=37;
    startFogDecay=0.0049999999;
    forecastFogDecay=0.0049999999;
    };
    };



     

    Testing code, "test_shuffle.sqf". Mostly functions to populate input arrays.



    #define DEF_MAX_DEPTH 5
    #define DEF_MAX_ELEMS 5
    #define DEF_MIN_STRLEN 7
    #define DEF_MAX_STRLEN 63
    #define DEF_SHUFFLE_RUNS 1000000

    {
    _x enableSimulation false;
    } forEach (entities "All");

    pdth_fnc_shuf = compile preprocessFileLineNumbers "pdth_fnc_shuffle.sqf";
    cba_fnc_shuf = CBA_fnc_shuffle;
    bis_fnc_shuf = compile preprocessFileLineNumbers "bis_fnc_shuffle.sqf";
    bis_fnc_shuf_v = BIS_fnc_shuffleArray;

    fnc_generate_bool = {
    0.5 > (random(1));
    };

    fnc_generate_scalar = {
    random (1e5) - 2e5;
    };

    fnc_generate_string = {
    private ["_arr", "_i", "_count"];
    _count = DEF_MIN_STRLEN + 1 + floor random(DEF_MAX_STRLEN-DEF_MIN_STRLEN);
    _arr = [];
    for "_i" from 1 to _count do {
    _arr pushBack (32 + floor random 95); // ascii, without 127
    };
    toString _arr;
    };

    fnc_generate_code = {
    compile (["if (true) then {2+2} else {5}", "{ _x = _x + 1 } forEach [1,2,3]", "a = 42"] call BIS_fnc_selectRandom);
    };

    fnc_generate_object = {
    (entities "All") call BIS_fnc_selectRandom;
    };

    fnc_generate_side = {
    [west, east, resistance] call BIS_fnc_selectRandom
    };

    generatedTypes = ["ARRAY", "BOOL", "CODE", "OBJECT", "SCALAR", "SIDE", "STRING", "NIL"];

    fnc_generate_type = {
    private "_type";
    _type = [_this, 2, generatedTypes call BIS_fnc_selectRandom, [""]] call BIS_fnc_param;
    switch _type do {
    case "ARRAY": {
    private ["_maxDepth", "_maxElems"];
    _maxDepth = [_this, 0, DEF_MAX_DEPTH, [0]] call BIS_fnc_param;
    _maxElems = [_this, 1, DEF_MAX_ELEMS, [0]] call BIS_fnc_param;
    if (_maxDepth < 1) then {
    _maxDepth = DEF_MAX_DEPTH;
    };
    if (_maxElems < 1) then {
    _maxElems = DEF_MAX_ELEMS;
    };
    [_maxDepth, _maxElems] call fnc_generate_array;
    };
    case "BOOL": {
    call fnc_generate_bool;
    };
    case "CODE": {
    call fnc_generate_code;
    };
    case "OBJECT": {
    call fnc_generate_object;
    };
    case "SCALAR": {
    call fnc_generate_scalar;
    };
    case "SIDE": {
    call fnc_generate_side;
    };
    case "STRING": {
    call fnc_generate_string;
    };
    default {nil};
    };
    };

    fnc_generate_array = {
    private ["_maxDepth", "_maxElems", "_ret", "_i", "_cnt", "_types"];
    _maxDepth = [_this, 0, DEF_MAX_DEPTH, [0]] call BIS_fnc_param;
    _maxElems = [_this, 1, DEF_MAX_ELEMS, [0]] call BIS_fnc_param;
    _types = [_this, 2, generatedTypes, [[]]] call BIS_fnc_param;
    _ret = [];
    if (_maxDepth < 1) then {
    _maxDepth = DEF_MAX_DEPTH;
    };
    if (_maxElems < 1) then {
    _maxElems = DEF_MAX_ELEMS;
    };
    _cnt = floor random (1+_maxElems);
    for "_i" from 1 to _cnt do {
    _ret pushBack ([_maxDepth-1, _maxElems, _types call BIS_fnc_selectRandom] call fnc_generate_type);
    };

    _ret
    };


    firstElem = "FirstElem";

    fnc_generate_array_for_shuffle = {
    private ["_i", "_cnt", "_types", "_push"];
    _cnt = [_this, 0, DEF_MAX_ELEMS, [0]] call BIS_fnc_param;
    _types = [_this, 1, generatedTypes, [[]]] call BIS_fnc_param;
    _ret = [];
    if (_cnt < 1) then {
    _cnt = DEF_MAX_ELEMS;
    };
    if ("STRING" in _types) then {
    _ret pushBack firstElem;
    } else {
    _push = [DEF_MAX_DEPTH, DEF_MAX_ELEMS, _types call BIS_fnc_selectRandom] call fnc_generate_type;
    if (isNil "_push") then {
    _ret set [0, nil];
    } else {
    _ret pushBack _push;
    };
    };
    for "_i" from 1 to (_cnt-1) do {
    _push = [DEF_MAX_DEPTH, DEF_MAX_ELEMS, _types call BIS_fnc_selectRandom] call fnc_generate_type;
    if (isNil "_push") then {
    _ret set [_i, nil];
    } else {
    _ret pushBack _push;
    };
    };

    _ret
    };

    private ["_arrForShuffle", /*"_arrShuffled",*/ "_numEls", "_k", "_func", "_st", "_en", "_step", "_times", "_sum", "_runs", "_avg", "_typs", "_usedTypes", "_csh", "_rep"];
    _usedTypes = [];
    {
    _usedTypes pushBack [_x]; // for each type separately
    } forEach generatedTypes;
    _usedTypes pushBack generatedTypes; // and for mixed arrays

    {
    _numEls = _x;
    diag_log format ["Running tests for arrays of size %1", _numEls];
    {
    _typs = _x;
    _arrForShuffle = [_numEls, _typs] call fnc_generate_array_for_shuffle;
    _times = [];
    _sum = 0;
    diag_log format [" Element types: %1", _typs];
    {
    _func = _x;
    _runs = ceil (DEF_SHUFFLE_RUNS / _numEls);
    _st = diag_tickTime;
    for "_k" from 1 to _runs do {
    private "_arrShuffled"; // making sure memory freed (?) after every shuffle, otherwise consequent calls can fail
    _arrShuffled = _arrForShuffle call _func;
    _csh = count _arrShuffled;
    };
    _en = diag_tickTime;
    _step = _en - _st;
    _avg = _step / _runs;
    _times pushBack _step;
    _sum = _sum + _step;
    if (isNil "_csh" && _forEachIndex == 3) then {
    _csh = count _arrForShuffle; // bis_fnc_shuf_v shuffles in-place
    };
    if (isNil "_csh") then {
    diag_log format [" %1 shuffles run; avg. time per one shuffle: %2", _runs, _avg];
    } else {
    diag_log format [" (last output %1) %2 shuffles run; avg. time per one shuffle: %3", _csh, _runs, _avg];
    };
    } forEach [pdth_fnc_shuf, cba_fnc_shuf, bis_fnc_shuf, bis_fnc_shuf_v];
    _arrForShuffle = nil; // release array, so memory will be collected (?)
    {
    _times set [_forEachIndex, 100*_x / _sum];
    } forEach _times;
    diag_log format [" Time passed during each call, %1: %2", "%", _times];
    } forEach _usedTypes;
    } forEach [3, 10, 30, 100, 301, 1000, 3010, 10000, 30103/*, 100000, 301030, 1000000, 3010300, 9999999*/];

    {
    _x enableSimulation true;
    } forEach (entities "All");

    endMission "END1";



    Tested functions defined in lines

    pdth_fnc_shuf = compile preprocessFileLineNumbers "pdth_fnc_shuffle.sqf";
    cba_fnc_shuf = CBA_fnc_shuffle;
    bis_fnc_shuf = compile preprocessFileLineNumbers "bis_fnc_shuffle.sqf";
    bis_fnc_shuf_v = BIS_fnc_shuffleArray;

    Testing output is produced in the same order.

    pdth_fnc_shuf is the function I wrote for this task, slightly changed since the first post, thx to Greenfist for useful tip on for loop; defined in "pdth_fnc_shuffle.sqf":



    /// --- validate general input
    #include "\A3\functions_f\paramsCheck.inc"
    paramsCheck(_this,isEqualType,[])

    private ["_cnt", "_result"];
    _cnt = count _this;
    _result = [];

    if (_cnt > 0) then {
    private ["_i", "_idxs"];
    _idxs = [];
    _idxs resize _cnt;
    for "_i" from 0 to (cnt-1) do {
    _idxs set [_i, _i];
    };

    _result resize _cnt;
    for "_i" from 0 to (cnt-2) do {
    _result set [_i, _this select (_idxs deleteAt floor random (_cnt-_i))];
    };
    _result set [_cnt-1, _this select (_idxs select 0)];
    };

    _result



    cba_fnc_shuf is unchanged function from CBA.

    bis_fnc_shuf is function based on BIS's BIS_fnc_shuffleArray with slight changes done by me to conform function specifications: produce new array, leave input array intact, fair shuffling (see first post).



    /// --- validate general input
    #include "\A3\functions_f\paramsCheck.inc"
    paramsCheck(_this,isEqualType,[])

    private ["_cnt", "_res"];
    _cnt = count _this;
    _res = +_this;
    for "_i" from 1 to (_cnt-1) do {
    _res pushBack (_res deleteAt floor random (_cnt+1-_i));
    };
    _res pushBack (_res deleteAt 0); // omit extra call to random selecting from single element.

    _res



    bis_fnc_shuf_v is unchanged version of BIS_fnc_shuffleArray. Works incorrectly therefore should be considered off competition. Only here for reference. Produces incorrect output (no fair shuffling), shuffles input array in-place (therefore shows good times).

     

    3. Test run

    All functions are given exactly the same input, generated randomly by functions in "test_shuffle.sqf". Vanilla BIS_fnc_shuffleArray shuffles in-place, therefore called last.

    Time measuring done using diag_tickTime scripting command. Since function call can be fully performed (especially for small arrays) in very short period of time, therefore not being able to be measured accurately, all functions called in loops of equal amount of repetitions so produce enough delay to be measured.

    Times measured in seconds.

    Array counts used in test: [3, 10, 30, 100, 301, 1000, 3010, 10000, 30103, 100000]. At lest DEF_SHUFFLE_RUNS array elements are shuffled by each function for each array count. Average time calculated for single shuffle run is logged in report.

    Types used for populating array: ["ARRAY", "BOOL", "CODE", "OBJECT", "SCALAR", "SIDE", "STRING", "NIL"]. For each of given type, array populated fully with only this type. After all types tested, test run for array populated with mix of mentioned  types.

    For "ARRAY" type, tested array is populated with arrays, in turn containing mixed types as their child types (should not affect the root). "ARRAY"s contain other "ARRAY"s too. Maximum tree depth is limited by DEF_MAX_DEPTH macro.

     

    4. Report output:



    17:15:44 "Running tests for arrays of size 3"
    17:15:44 "    Element types: ["ARRAY"]"
    17:15:51 "        (last output 3) 333334 shuffles run; avg. time per one shuffle: 2.0811e-005"
    17:16:10 "        (last output 3) 333334 shuffles run; avg. time per one shuffle: 5.74739e-005"
    17:16:17 "        (last output 3) 333334 shuffles run; avg. time per one shuffle: 2.1042e-005"
    17:16:18 "        (last output 3) 333334 shuffles run; avg. time per one shuffle: 3.44098e-006"
    17:16:18 "    Time passed during each call, %: [20.2505,55.926,20.4752,3.34831]"
    17:16:18 "    Element types: ["BOOL"]"
    17:16:25 "        (last output 3) 333334 shuffles run; avg. time per one shuffle: 2.0751e-005"
    17:16:41 "        (last output 3) 333334 shuffles run; avg. time per one shuffle: 4.70669e-005"
    17:16:47 "        (last output 3) 333334 shuffles run; avg. time per one shuffle: 1.9707e-005"
    17:16:49 "        (last output 3) 333334 shuffles run; avg. time per one shuffle: 3.447e-006"
    17:16:49 "    Time passed during each call, %: [22.8103,51.7379,21.6627,3.78908]"
    17:16:49 "    Element types: ["CODE"]"
    17:16:56 "        (last output 3) 333334 shuffles run; avg. time per one shuffle: 2.1012e-005"
    17:17:12 "        (last output 3) 333334 shuffles run; avg. time per one shuffle: 4.82039e-005"
    17:17:18 "        (last output 3) 333334 shuffles run; avg. time per one shuffle: 2.0142e-005"
    17:17:19 "        (last output 3) 333334 shuffles run; avg. time per one shuffle: 3.45002e-006"
    17:17:19 "    Time passed during each call, %: [22.6403,51.9395,21.7029,3.71738]"
    17:17:19 "    Element types: ["OBJECT"]"
    17:17:26 "        (last output 3) 333334 shuffles run; avg. time per one shuffle: 2.0928e-005"
    17:17:43 "        (last output 3) 333334 shuffles run; avg. time per one shuffle: 5.10539e-005"
    17:17:50 "        (last output 3) 333334 shuffles run; avg. time per one shuffle: 1.98539e-005"
    17:17:51 "        (last output 3) 333334 shuffles run; avg. time per one shuffle: 3.45899e-006"
    17:17:51 "    Time passed during each call, %: [21.9613,53.5747,20.8342,3.62978]"
    17:17:51 "    Element types: ["SCALAR"]"
    17:17:58 "        (last output 3) 333334 shuffles run; avg. time per one shuffle: 2.0883e-005"
    17:18:15 "        (last output 3) 333334 shuffles run; avg. time per one shuffle: 5.07209e-005"
    17:18:22 "        (last output 3) 333334 shuffles run; avg. time per one shuffle: 1.9377e-005"
    17:18:23 "        (last output 3) 333334 shuffles run; avg. time per one shuffle: 3.453e-006"
    17:18:23 "    Time passed during each call, %: [22.1138,53.7105,20.5191,3.65652]"
    17:18:23 "    Element types: ["SIDE"]"
    17:18:30 "        (last output 3) 333334 shuffles run; avg. time per one shuffle: 2.0991e-005"
    17:18:45 "        (last output 3) 333334 shuffles run; avg. time per one shuffle: 4.72109e-005"
    17:18:52 "        (last output 3) 333334 shuffles run; avg. time per one shuffle: 1.9719e-005"
    17:18:53 "        (last output 3) 333334 shuffles run; avg. time per one shuffle: 3.453e-006"
    17:18:53 "    Time passed during each call, %: [22.9726,51.6679,21.5805,3.77898]"
    17:18:53 "    Element types: ["STRING"]"
    17:19:00 "        (last output 3) 333334 shuffles run; avg. time per one shuffle: 2.0991e-005"
    17:19:16 "        (last output 3) 333334 shuffles run; avg. time per one shuffle: 4.88279e-005"
    17:19:23 "        (last output 3) 333334 shuffles run; avg. time per one shuffle: 1.9866e-005"
    17:19:24 "        (last output 3) 333334 shuffles run; avg. time per one shuffle: 3.46792e-006"
    17:19:24 "    Time passed during each call, %: [22.5339,52.417,21.3262,3.72283]"
    17:19:24 "    Element types: ["NIL"]"
    17:19:31 "        (last output 3) 333334 shuffles run; avg. time per one shuffle: 2.0919e-005"
    17:19:47 "        (last output 0) 333334 shuffles run; avg. time per one shuffle: 4.74269e-005"
    17:19:54 "        (last output 0) 333334 shuffles run; avg. time per one shuffle: 1.959e-005"
    17:19:55 "        (last output 3) 333334 shuffles run; avg. time per one shuffle: 3.453e-006"
    17:19:55 "    Time passed during each call, %: [22.8901,51.8957,21.4358,3.77836]"
    17:19:55 "    Element types: ["ARRAY","BOOL","CODE","OBJECT","SCALAR","SIDE","STRING","NIL"]"
    17:20:02 "        (last output 3) 333334 shuffles run; avg. time per one shuffle: 2.094e-005"
    17:20:18 "        (last output 3) 333334 shuffles run; avg. time per one shuffle: 4.87289e-005"
    17:20:25 "        (last output 3) 333334 shuffles run; avg. time per one shuffle: 1.9791e-005"
    17:20:26 "        (last output 3) 333334 shuffles run; avg. time per one shuffle: 3.453e-006"
    17:20:26 "    Time passed during each call, %: [22.5372,52.4458,21.3006,3.71638]"
    17:20:26 "Running tests for arrays of size 10"
    17:20:26 "    Element types: ["ARRAY"]"
    17:20:28 "        (last output 10) 100000 shuffles run; avg. time per one shuffle: 2.11099e-005"
    17:20:38 "        (last output 10) 100000 shuffles run; avg. time per one shuffle: 9.806e-005"
    17:20:42 "        (last output 10) 100000 shuffles run; avg. time per one shuffle: 4.71701e-005"
    17:20:43 "        (last output 10) 100000 shuffles run; avg. time per one shuffle: 3.45001e-006"
    17:20:43 "    Time passed during each call, %: [12.433,57.7537,27.7814,2.03193]"
    17:20:43 "    Element types: ["BOOL"]"
    17:20:45 "        (last output 10) 100000 shuffles run; avg. time per one shuffle: 2.08499e-005"
    17:20:52 "        (last output 10) 100000 shuffles run; avg. time per one shuffle: 7.07599e-005"
    17:20:56 "        (last output 10) 100000 shuffles run; avg. time per one shuffle: 4.30801e-005"
    17:20:56 "        (last output 10) 100000 shuffles run; avg. time per one shuffle: 3.44025e-006"
    17:20:56 "    Time passed during each call, %: [15.0944,51.227,31.1881,2.49058]"
    17:20:56 "    Element types: ["CODE"]"
    17:20:59 "        (last output 10) 100000 shuffles run; avg. time per one shuffle: 2.112e-005"
    17:21:06 "        (last output 10) 100000 shuffles run; avg. time per one shuffle: 7.64102e-005"
    17:21:11 "        (last output 10) 100000 shuffles run; avg. time per one shuffle: 4.48499e-005"
    17:21:11 "        (last output 10) 100000 shuffles run; avg. time per one shuffle: 3.46008e-006"
    17:21:11 "    Time passed during each call, %: [14.4816,52.3931,30.7527,2.37252]"
    17:21:11 "    Element types: ["OBJECT"]"
    17:21:13 "        (last output 10) 100000 shuffles run; avg. time per one shuffle: 2.11099e-005"
    17:21:21 "        (last output 10) 100000 shuffles run; avg. time per one shuffle: 8.05499e-005"
    17:21:26 "        (last output 10) 100000 shuffles run; avg. time per one shuffle: 4.36401e-005"
    17:21:26 "        (last output 10) 100000 shuffles run; avg. time per one shuffle: 3.45978e-006"
    17:21:26 "    Time passed during each call, %: [14.1906,54.1477,29.336,2.32575]"
    17:21:26 "    Element types: ["SCALAR"]"
    17:21:28 "        (last output 10) 100000 shuffles run; avg. time per one shuffle: 2.11002e-005"
    17:21:36 "        (last output 10) 100000 shuffles run; avg. time per one shuffle: 8.10498e-005"
    17:21:40 "        (last output 10) 100000 shuffles run; avg. time per one shuffle: 4.25e-005"
    17:21:41 "        (last output 10) 100000 shuffles run; avg. time per one shuffle: 3.43994e-006"
    17:21:41 "    Time passed during each call, %: [14.2482,54.7301,28.6988,2.32287]"
    17:21:41 "    Element types: ["SIDE"]"
    17:21:43 "        (last output 10) 100000 shuffles run; avg. time per one shuffle: 2.10501e-005"
    17:21:50 "        (last output 10) 100000 shuffles run; avg. time per one shuffle: 7.05399e-005"
    17:21:54 "        (last output 10) 100000 shuffles run; avg. time per one shuffle: 4.31e-005"
    17:21:55 "        (last output 10) 100000 shuffles run; avg. time per one shuffle: 3.42011e-006"
    17:21:55 "    Time passed during each call, %: [15.2415,51.0751,31.207,2.47636]"
    17:21:55 "    Element types: ["STRING"]"
    17:21:57 "        (last output 10) 100000 shuffles run; avg. time per one shuffle: 2.10999e-005"
    17:22:05 "        (last output 10) 100000 shuffles run; avg. time per one shuffle: 7.89301e-005"
    17:22:09 "        (last output 10) 100000 shuffles run; avg. time per one shuffle: 4.345e-005"
    17:22:09 "        (last output 10) 100000 shuffles run; avg. time per one shuffle: 3.46985e-006"
    17:22:09 "    Time passed during each call, %: [14.3585,53.7123,29.5679,2.36125]"
    17:22:09 "    Element types: ["NIL"]"
    17:22:11 "        (last output 10) 100000 shuffles run; avg. time per one shuffle: 2.099e-005"
    17:22:18 "        (last output 0) 100000 shuffles run; avg. time per one shuffle: 7.07202e-005"
    17:22:23 "        (last output 0) 100000 shuffles run; avg. time per one shuffle: 4.29199e-005"
    17:22:23 "        (last output 10) 100000 shuffles run; avg. time per one shuffle: 3.43994e-006"
    17:22:23 "    Time passed during each call, %: [15.2024,51.2205,31.0856,2.49145]"
    17:22:23 "    Element types: ["ARRAY","BOOL","CODE","OBJECT","SCALAR","SIDE","STRING","NIL"]"
    17:22:25 "        (last output 10) 100000 shuffles run; avg. time per one shuffle: 2.10098e-005"
    17:22:33 "        (last output 10) 100000 shuffles run; avg. time per one shuffle: 8.03201e-005"
    17:22:38 "        (last output 10) 100000 shuffles run; avg. time per one shuffle: 4.37e-005"
    17:22:38 "        (last output 10) 100000 shuffles run; avg. time per one shuffle: 3.42011e-006"
    17:22:38 "    Time passed during each call, %: [14.1528,54.1058,29.4375,2.30388]"
    17:22:38 "Running tests for arrays of size 30"
    17:22:38 "    Element types: ["ARRAY"]"
    17:22:39 "        (last output 30) 33334 shuffles run; avg. time per one shuffle: 2.11794e-005"
    17:22:47 "        (last output 30) 33334 shuffles run; avg. time per one shuffle: 0.000258745"
    17:22:51 "        (last output 30) 33334 shuffles run; avg. time per one shuffle: 0.000122938"
    17:22:51 "        (last output 30) 33334 shuffles run; avg. time per one shuffle: 3.41943e-006"
    17:22:51 "    Time passed during each call, %: [5.21298,63.686,30.2593,0.841639]"
    17:22:52 "    Element types: ["BOOL"]"
    17:22:52 "        (last output 30) 33334 shuffles run; avg. time per one shuffle: 2.1119e-005"
    17:22:57 "        (last output 30) 33334 shuffles run; avg. time per one shuffle: 0.000140547"
    17:23:01 "        (last output 30) 33334 shuffles run; avg. time per one shuffle: 0.000110279"
    17:23:01 "        (last output 30) 33334 shuffles run; avg. time per one shuffle: 3.44964e-006"
    17:23:01 "    Time passed during each call, %: [7.66863,51.0349,40.0439,1.25262]"
    17:23:01 "    Element types: ["CODE"]"
    17:23:01 "        (last output 30) 33334 shuffles run; avg. time per one shuffle: 2.14797e-005"
    17:23:07 "        (last output 30) 33334 shuffles run; avg. time per one shuffle: 0.000167967"
    17:23:11 "        (last output 30) 33334 shuffles run; avg. time per one shuffle: 0.000115198"
    17:23:11 "        (last output 30) 33334 shuffles run; avg. time per one shuffle: 3.42034e-006"
    17:23:11 "    Time passed during each call, %: [6.97247,54.5232,37.394,1.11027]"
    17:23:11 "    Element types: ["OBJECT"]"
    17:23:12 "        (last output 30) 33334 shuffles run; avg. time per one shuffle: 2.11199e-005"
    17:23:18 "        (last output 30) 33334 shuffles run; avg. time per one shuffle: 0.000175227"
    17:23:21 "        (last output 30) 33334 shuffles run; avg. time per one shuffle: 0.000110698"
    17:23:21 "        (last output 30) 33334 shuffles run; avg. time per one shuffle: 3.42034e-006"
    17:23:21 "    Time passed during each call, %: [6.80267,56.4401,35.6555,1.10168]"
    17:23:21 "    Element types: ["SCALAR"]"
    17:23:22 "        (last output 30) 33334 shuffles run; avg. time per one shuffle: 2.10897e-005"
    17:23:28 "        (last output 30) 33334 shuffles run; avg. time per one shuffle: 0.000168897"
    17:23:31 "        (last output 30) 33334 shuffles run; avg. time per one shuffle: 0.000108297"
    17:23:31 "        (last output 30) 33334 shuffles run; avg. time per one shuffle: 3.42034e-006"
    17:23:31 "    Time passed during each call, %: [6.99018,55.9809,35.8952,1.13367]"
    17:23:31 "    Element types: ["SIDE"]"
    17:23:32 "        (last output 30) 33334 shuffles run; avg. time per one shuffle: 2.10311e-005"
    17:23:37 "        (last output 30) 33334 shuffles run; avg. time per one shuffle: 0.000138416"
    17:23:40 "        (last output 30) 33334 shuffles run; avg. time per one shuffle: 0.000110698"
    17:23:40 "        (last output 30) 33334 shuffles run; avg. time per one shuffle: 3.42034e-006"
    17:23:40 "    Time passed during each call, %: [7.68778,50.597,40.4649,1.25028]"
    17:23:40 "    Element types: ["STRING"]"
    17:23:41 "        (last output 30) 33334 shuffles run; avg. time per one shuffle: 2.11794e-005"
    17:23:47 "        (last output 30) 33334 shuffles run; avg. time per one shuffle: 0.000181976"
    17:23:51 "        (last output 30) 33334 shuffles run; avg. time per one shuffle: 0.000111088"
    17:23:51 "        (last output 30) 33334 shuffles run; avg. time per one shuffle: 3.42034e-006"
    17:23:51 "    Time passed during each call, %: [6.66724,57.2857,34.9703,1.07672]"
    17:23:51 "    Element types: ["NIL"]"
    17:23:52 "        (last output 30) 33334 shuffles run; avg. time per one shuffle: 2.11794e-005"
    17:23:56 "        (last output 0) 33334 shuffles run; avg. time per one shuffle: 0.000138267"
    17:24:00 "        (last output 0) 33334 shuffles run; avg. time per one shuffle: 0.000109618"
    17:24:00 "        (last output 30) 33334 shuffles run; avg. time per one shuffle: 3.44964e-006"
    17:24:00 "    Time passed during each call, %: [7.77185,50.7377,40.2245,1.26586]"
    17:24:00 "    Element types: ["ARRAY","BOOL","CODE","OBJECT","SCALAR","SIDE","STRING","NIL"]"
    17:24:01 "        (last output 30) 33334 shuffles run; avg. time per one shuffle: 2.12691e-005"
    17:24:07 "        (last output 29) 33334 shuffles run; avg. time per one shuffle: 0.000179367"
    17:24:11 "        (last output 29) 33334 shuffles run; avg. time per one shuffle: 0.000113457"
    17:24:11 "        (last output 30) 33334 shuffles run; avg. time per one shuffle: 3.42034e-006"
    17:24:11 "    Time passed during each call, %: [6.69865,56.4911,35.7331,1.07723]"
    17:24:11 "Running tests for arrays of size 100"
    17:24:11 "    Element types: ["ARRAY"]"
    17:24:11 "        (last output 100) 10000 shuffles run; avg. time per one shuffle: 2.19971e-005"
    17:24:22 "        (last output 100) 10000 shuffles run; avg. time per one shuffle: 0.001072"
    17:24:26 "        (last output 100) 10000 shuffles run; avg. time per one shuffle: 0.000412994"
    17:24:26 "        (last output 100) 10000 shuffles run; avg. time per one shuffle: 3.40576e-006"
    17:24:26 "    Time passed during each call, %: [1.45637,70.9748,27.3434,0.225487]"
    17:24:26 "    Element types: ["BOOL"]"
    17:24:26 "        (last output 100) 10000 shuffles run; avg. time per one shuffle: 2.19971e-005"
    17:24:30 "        (last output 100) 10000 shuffles run; avg. time per one shuffle: 0.000417102"
    17:24:34 "        (last output 100) 10000 shuffles run; avg. time per one shuffle: 0.000373499"
    17:24:34 "        (last output 100) 10000 shuffles run; avg. time per one shuffle: 3.49731e-006"
    17:24:34 "    Time passed during each call, %: [2.69541,51.1095,45.7666,0.428543]"
    17:24:34 "    Element types: ["CODE"]"
    17:24:34 "        (last output 100) 10000 shuffles run; avg. time per one shuffle: 2.21985e-005"
    17:24:41 "        (last output 100) 10000 shuffles run; avg. time per one shuffle: 0.000655499"
    17:24:45 "        (last output 100) 10000 shuffles run; avg. time per one shuffle: 0.000361804"
    17:24:45 "        (last output 100) 10000 shuffles run; avg. time per one shuffle: 3.49731e-006"
    17:24:45 "    Time passed during each call, %: [2.12833,62.8475,34.6888,0.335313]"
    17:24:45 "    Element types: ["OBJECT"]"
    17:24:45 "        (last output 100) 10000 shuffles run; avg. time per one shuffle: 2.21008e-005"
    17:24:51 "        (last output 100) 10000 shuffles run; avg. time per one shuffle: 0.000632098"
    17:24:55 "        (last output 100) 10000 shuffles run; avg. time per one shuffle: 0.0003737"
    17:24:55 "        (last output 100) 10000 shuffles run; avg. time per one shuffle: 3.39966e-006"
    17:24:55 "    Time passed during each call, %: [2.14301,61.2915,36.2359,0.329648]"
    17:24:55 "    Element types: ["SCALAR"]"
    17:24:55 "        (last output 100) 10000 shuffles run; avg. time per one shuffle: 2.21008e-005"
    17:25:00 "        (last output 100) 10000 shuffles run; avg. time per one shuffle: 0.000537103"
    17:25:04 "        (last output 100) 10000 shuffles run; avg. time per one shuffle: 0.0003401"
    17:25:04 "        (last output 100) 10000 shuffles run; avg. time per one shuffle: 3.39966e-006"
    17:25:04 "    Time passed during each call, %: [2.44829,59.4994,37.6757,0.376608]"
    17:25:04 "    Element types: ["SIDE"]"
    17:25:04 "        (last output 100) 10000 shuffles run; avg. time per one shuffle: 2.21008e-005"
    17:25:08 "        (last output 100) 10000 shuffles run; avg. time per one shuffle: 0.000409296"
    17:25:12 "        (last output 100) 10000 shuffles run; avg. time per one shuffle: 0.000345703"
    17:25:12 "        (last output 100) 10000 shuffles run; avg. time per one shuffle: 3.39966e-006"
    17:25:12 "    Time passed during each call, %: [2.83163,52.4402,44.2926,0.435575]"
    17:25:12 "    Element types: ["STRING"]"
    17:25:12 "        (last output 100) 10000 shuffles run; avg. time per one shuffle: 2.19971e-005"
    17:25:20 "        (last output 100) 10000 shuffles run; avg. time per one shuffle: 0.000776599"
    17:25:23 "        (last output 100) 10000 shuffles run; avg. time per one shuffle: 0.000372205"
    17:25:24 "        (last output 100) 10000 shuffles run; avg. time per one shuffle: 3.39966e-006"
    17:25:24 "    Time passed during each call, %: [1.87337,66.1385,31.6986,0.28953]"
    17:25:24 "    Element types: ["NIL"]"
    17:25:24 "        (last output 100) 10000 shuffles run; avg. time per one shuffle: 2.18994e-005"
    17:25:28 "        (last output 0) 10000 shuffles run; avg. time per one shuffle: 0.000399701"
    17:25:31 "        (last output 0) 10000 shuffles run; avg. time per one shuffle: 0.000368298"
    17:25:31 "        (last output 100) 10000 shuffles run; avg. time per one shuffle: 3.39966e-006"
    17:25:31 "    Time passed during each call, %: [2.76055,50.3847,46.4262,0.428547]"
    17:25:31 "    Element types: ["ARRAY","BOOL","CODE","OBJECT","SCALAR","SIDE","STRING","NIL"]"
    17:25:32 "        (last output 100) 10000 shuffles run; avg. time per one shuffle: 2.21008e-005"
    17:25:38 "        (last output 86) 10000 shuffles run; avg. time per one shuffle: 0.000602802"
    17:25:41 "        (last output 86) 10000 shuffles run; avg. time per one shuffle: 0.000353198"
    17:25:41 "        (last output 100) 10000 shuffles run; avg. time per one shuffle: 3.39966e-006"
    17:25:41 "    Time passed during each call, %: [2.25174,61.4163,35.9855,0.346374]"
    17:25:41 "Running tests for arrays of size 301"
    17:25:42 "    Element types: ["ARRAY"]"
    17:25:42 "        (last output 301) 3323 shuffles run; avg. time per one shuffle: 2.43737e-005"
    17:26:03 "        (last output 301) 3323 shuffles run; avg. time per one shuffle: 0.00632982"
    17:26:07 "        (last output 301) 3323 shuffles run; avg. time per one shuffle: 0.00135269"
    17:26:07 "        (last output 301) 3323 shuffles run; avg. time per one shuffle: 3.60003e-006"
    17:26:07 "    Time passed during each call, %: [0.31611,82.0937,17.5435,0.04669]"
    17:26:07 "    Element types: ["BOOL"]"
    17:26:07 "        (last output 301) 3323 shuffles run; avg. time per one shuffle: 2.37675e-005"
    17:26:12 "        (last output 301) 3323 shuffles run; avg. time per one shuffle: 0.0014809"
    17:26:16 "        (last output 301) 3323 shuffles run; avg. time per one shuffle: 0.00104935"
    17:26:16 "        (last output 301) 3323 shuffles run; avg. time per one shuffle: 3.30615e-006"
    17:26:16 "    Time passed during each call, %: [0.929391,57.9081,41.0332,0.129282]"
    17:26:16 "    Element types: ["CODE"]"
    17:26:16 "        (last output 301) 3323 shuffles run; avg. time per one shuffle: 2.40798e-005"
    17:26:26 "        (last output 301) 3323 shuffles run; avg. time per one shuffle: 0.00320672"
    17:26:30 "        (last output 301) 3323 shuffles run; avg. time per one shuffle: 0.00114295"
    17:26:30 "        (last output 301) 3323 shuffles run; avg. time per one shuffle: 3.32452e-006"
    17:26:30 "    Time passed during each call, %: [0.550133,73.2617,26.1122,0.0759528]"
    17:26:30 "    Element types: ["OBJECT"]"
    17:26:30 "        (last output 301) 3323 shuffles run; avg. time per one shuffle: 2.40798e-005"
    17:26:40 "        (last output 301) 3323 shuffles run; avg. time per one shuffle: 0.00299307"
    17:26:44 "        (last output 301) 3323 shuffles run; avg. time per one shuffle: 0.00107824"
    17:26:44 "        (last output 301) 3323 shuffles run; avg. time per one shuffle: 3.30615e-006"
    17:26:44 "    Time passed during each call, %: [0.587497,73.0249,26.307,0.0806632]"
    17:26:44 "    Element types: ["SCALAR"]"
    17:26:44 "        (last output 301) 3323 shuffles run; avg. time per one shuffle: 2.40798e-005"
    17:26:51 "        (last output 301) 3323 shuffles run; avg. time per one shuffle: 0.00198134"
    17:26:54 "        (last output 301) 3323 shuffles run; avg. time per one shuffle: 0.00101293"
    17:26:54 "        (last output 301) 3323 shuffles run; avg. time per one shuffle: 3.61839e-006"
    17:26:54 "    Time passed during each call, %: [0.796825,65.5645,33.5189,0.119736]"
    17:26:54 "    Element types: ["SIDE"]"
    17:26:54 "        (last output 301) 3323 shuffles run; avg. time per one shuffle: 2.43737e-005"
    17:26:59 "        (last output 301) 3323 shuffles run; avg. time per one shuffle: 0.00142793"
    17:27:02 "        (last output 301) 3323 shuffles run; avg. time per one shuffle: 0.00105055"
    17:27:02 "        (last output 301) 3323 shuffles run; avg. time per one shuffle: 3.30615e-006"
    17:27:02 "    Time passed during each call, %: [0.972553,56.9768,41.9187,0.131921]"
    17:27:02 "    Element types: ["STRING"]"
    17:27:02 "        (last output 301) 3323 shuffles run; avg. time per one shuffle: 2.40614e-005"
    17:27:17 "        (last output 301) 3323 shuffles run; avg. time per one shuffle: 0.00448721"
    17:27:21 "        (last output 301) 3323 shuffles run; avg. time per one shuffle: 0.00105297"
    17:27:21 "        (last output 301) 3323 shuffles run; avg. time per one shuffle: 3.30615e-006"
    17:27:21 "    Time passed during each call, %: [0.432172,80.5958,18.9126,0.0593824]"
    17:27:21 "    Element types: ["NIL"]"
    17:27:21 "        (last output 301) 3323 shuffles run; avg. time per one shuffle: 2.43737e-005"
    17:27:25 "        (last output 0) 3323 shuffles run; avg. time per one shuffle: 0.0013551"
    17:27:29 "        (last output 0) 3323 shuffles run; avg. time per one shuffle: 0.00106952"
    17:27:29 "        (last output 301) 3323 shuffles run; avg. time per one shuffle: 3.30615e-006"
    17:27:29 "    Time passed during each call, %: [0.993911,55.2583,43.613,0.134818]"
    17:27:29 "    Element types: ["ARRAY","BOOL","CODE","OBJECT","SCALAR","SIDE","STRING","NIL"]"
    17:27:29 "        (last output 301) 3323 shuffles run; avg. time per one shuffle: 2.43737e-005"
    17:27:38 "        (last output 267) 3323 shuffles run; avg. time per one shuffle: 0.00267892"
    17:27:42 "        (last output 267) 3323 shuffles run; avg. time per one shuffle: 0.00107492"
    17:27:42 "        (last output 301) 3323 shuffles run; avg. time per one shuffle: 3.61839e-006"
    17:27:42 "    Time passed during each call, %: [0.644494,70.8365,28.4233,0.0956784]"
    17:27:42 "Running tests for arrays of size 1000"
    17:27:42 "    Element types: ["ARRAY"]"
    17:27:43 "        (last output 1000) 1000 shuffles run; avg. time per one shuffle: 3.20435e-005"
    17:28:38 "        (last output 1000) 1000 shuffles run; avg. time per one shuffle: 0.055978"
    17:28:43 "        (last output 1000) 1000 shuffles run; avg. time per one shuffle: 0.004492"
    17:28:43 "        (last output 1000) 1000 shuffles run; avg. time per one shuffle: 2.99072e-006"
    17:28:43 "    Time passed during each call, %: [0.05296,92.5179,7.42419,0.00494293]"
    17:28:43 "    Element types: ["BOOL"]"
    17:28:43 "        (last output 1000) 1000 shuffles run; avg. time per one shuffle: 3.19824e-005"
    17:28:51 "        (last output 1000) 1000 shuffles run; avg. time per one shuffle: 0.00840302"
    17:28:55 "        (last output 1000) 1000 shuffles run; avg. time per one shuffle: 0.00363098"
    17:28:55 "        (last output 1000) 1000 shuffles run; avg. time per one shuffle: 4.02832e-006"
    17:28:55 "    Time passed during each call, %: [0.264974,69.619,30.0827,0.0333746]"
    17:28:55 "    Element types: ["CODE"]"
    17:28:55 "        (last output 1000) 1000 shuffles run; avg. time per one shuffle: 3.19824e-005"
    17:29:23 "        (last output 1000) 1000 shuffles run; avg. time per one shuffle: 0.0276461"
    17:29:27 "        (last output 1000) 1000 shuffles run; avg. time per one shuffle: 0.00384998"
    17:29:27 "        (last output 1000) 1000 shuffles run; avg. time per one shuffle: 4.02832e-006"
    17:29:27 "    Time passed during each call, %: [0.101428,87.6761,12.2097,0.0127753]"
    17:29:27 "    Element types: ["OBJECT"]"
    17:29:27 "        (last output 1000) 1000 shuffles run; avg. time per one shuffle: 3.20435e-005"
    17:29:51 "        (last output 1000) 1000 shuffles run; avg. time per one shuffle: 0.023761"
    17:29:54 "        (last output 1000) 1000 shuffles run; avg. time per one shuffle: 0.00360297"
    17:29:54 "        (last output 1000) 1000 shuffles run; avg. time per one shuffle: 4.02832e-006"
    17:29:54 "    Time passed during each call, %: [0.116947,86.7188,13.1495,0.0147019]"
    17:29:54 "    Element types: ["SCALAR"]"
    17:29:54 "        (last output 1000) 1000 shuffles run; avg. time per one shuffle: 3.10059e-005"
    17:30:06 "        (last output 1000) 1000 shuffles run; avg. time per one shuffle: 0.01175"
    17:30:10 "        (last output 1000) 1000 shuffles run; avg. time per one shuffle: 0.00349896"
    17:30:10 "        (last output 1000) 1000 shuffles run; avg. time per one shuffle: 2.99072e-006"
    17:30:10 "    Time passed during each call, %: [0.202879,76.883,22.8945,0.019569]"
    17:30:10 "    Element types: ["SIDE"]"
    17:30:10 "        (last output 1000) 1000 shuffles run; avg. time per one shuffle: 3.19824e-005"
    17:30:18 "        (last output 1000) 1000 shuffles run; avg. time per one shuffle: 0.00796301"
    17:30:21 "        (last output 1000) 1000 shuffles run; avg. time per one shuffle: 0.00359198"
    17:30:21 "        (last output 1000) 1000 shuffles run; avg. time per one shuffle: 2.99072e-006"
    17:30:21 "    Time passed during each call, %: [0.275949,68.7061,30.9922,0.0258044]"
    17:30:21 "    Element types: ["STRING"]"
    17:30:21 "        (last output 1000) 1000 shuffles run; avg. time per one shuffle: 3.20435e-005"
    17:31:00 "        (last output 1000) 1000 shuffles run; avg. time per one shuffle: 0.038453"
    17:31:04 "        (last output 1000) 1000 shuffles run; avg. time per one shuffle: 0.00359796"
    17:31:04 "        (last output 1000) 1000 shuffles run; avg. time per one shuffle: 2.99072e-006"
    17:31:04 "    Time passed during each call, %: [0.076138,91.3677,8.54907,0.00710622]"
    17:31:04 "    Element types: ["NIL"]"
    17:31:04 "        (last output 1000) 1000 shuffles run; avg. time per one shuffle: 3.20435e-005"
    17:31:11 "        (last output 0) 1000 shuffles run; avg. time per one shuffle: 0.00702496"
    17:31:14 "        (last output 0) 1000 shuffles run; avg. time per one shuffle: 0.00353601"
    17:31:14 "        (last output 1000) 1000 shuffles run; avg. time per one shuffle: 4.02832e-006"
    17:31:14 "    Time passed during each call, %: [0.302381,66.2917,33.3679,0.0380136]"
    17:31:14 "    Element types: ["ARRAY","BOOL","CODE","OBJECT","SCALAR","SIDE","STRING","NIL"]"
    17:31:14 "        (last output 1000) 1000 shuffles run; avg. time per one shuffle: 3.20435e-005"
    17:31:38 "        (last output 880) 1000 shuffles run; avg. time per one shuffle: 0.023547"
    17:31:42 "        (last output 880) 1000 shuffles run; avg. time per one shuffle: 0.00370398"
    17:31:42 "        (last output 1000) 1000 shuffles run; avg. time per one shuffle: 2.99072e-006"
    17:31:42 "    Time passed during each call, %: [0.117435,86.297,13.5746,0.0109606]"
    17:31:42 "Running tests for arrays of size 3010"
    17:31:44 "    Element types: ["ARRAY"]"
    17:31:44 "        (last output 3010) 333 shuffles run; avg. time per one shuffle: 5.40702e-005"
    17:34:13 "        (last output 3010) 333 shuffles run; avg. time per one shuffle: 0.446438"
    17:34:18 "        (last output 3010) 333 shuffles run; avg. time per one shuffle: 0.0145766"
    17:34:18 "        (last output 3010) 333 shuffles run; avg. time per one shuffle: 2.93262e-006"
    17:34:18 "    Time passed during each call, %: [0.0117271,96.8262,3.16146,0.000636044]"
    17:34:18 "    Element types: ["BOOL"]"
    17:34:18 "        (last output 3010) 333 shuffles run; avg. time per one shuffle: 5.42535e-005"
    17:34:37 "        (last output 3010) 333 shuffles run; avg. time per one shuffle: 0.0565376"
    17:34:41 "        (last output 3010) 333 shuffles run; avg. time per one shuffle: 0.0118016"
    17:34:41 "        (last output 3010) 333 shuffles run; avg. time per one shuffle: 2.93262e-006"
    17:34:41 "    Time passed during each call, %: [0.0793221,82.6617,17.2547,0.00428768]"
    17:34:41 "    Element types: ["CODE"]"
    17:34:41 "        (last output 3010) 333 shuffles run; avg. time per one shuffle: 5.38869e-005"
    17:35:57 "        (last output 3010) 333 shuffles run; avg. time per one shuffle: 0.227495"
    17:36:01 "        (last output 3010) 333 shuffles run; avg. time per one shuffle: 0.0125677"
    17:36:01 "        (last output 3010) 333 shuffles run; avg. time per one shuffle: 2.93262e-006"
    17:36:01 "    Time passed during each call, %: [0.0224417,94.7424,5.23394,0.00122131]"
    17:36:01 "    Element types: ["OBJECT"]"
    17:36:01 "        (last output 3010) 333 shuffles run; avg. time per one shuffle: 5.42535e-005"
    17:37:04 "        (last output 3010) 333 shuffles run; avg. time per one shuffle: 0.189754"
    17:37:08 "        (last output 3010) 333 shuffles run; avg. time per one shuffle: 0.0119578"
    17:37:08 "        (last output 3010) 333 shuffles run; avg. time per one shuffle: 3.2992e-006"
    17:37:08 "    Time passed during each call, %: [0.0268889,94.045,5.92646,0.00163514]"
    17:37:08 "    Element types: ["SCALAR"]"
    17:37:08 "        (last output 3010) 333 shuffles run; avg. time per one shuffle: 5.38869e-005"
    17:37:35 "        (last output 3010) 333 shuffles run; avg. time per one shuffle: 0.0806577"
    17:37:39 "        (last output 3010) 333 shuffles run; avg. time per one shuffle: 0.0115465"
    17:37:39 "        (last output 3010) 333 shuffles run; avg. time per one shuffle: 3.2992e-006"
    17:37:39 "    Time passed during each call, %: [0.0584068,87.4231,12.5149,0.00357593]"
    17:37:39 "    Element types: ["SIDE"]"
    17:37:39 "        (last output 3010) 333 shuffles run; avg. time per one shuffle: 5.38869e-005"
    17:37:57 "        (last output 3010) 333 shuffles run; avg. time per one shuffle: 0.0521922"
    17:38:01 "        (last output 3010) 333 shuffles run; avg. time per one shuffle: 0.0118108"
    17:38:01 "        (last output 3010) 333 shuffles run; avg. time per one shuffle: 6.23182e-006"
    17:38:01 "    Time passed during each call, %: [0.0841154,81.47,18.4361,0.00972763]"
    17:38:01 "    Element types: ["STRING"]"
    17:38:01 "        (last output 3010) 333 shuffles run; avg. time per one shuffle: 5.42535e-005"
    17:39:52 "        (last output 3010) 333 shuffles run; avg. time per one shuffle: 0.331165"
    17:39:56 "        (last output 3010) 333 shuffles run; avg. time per one shuffle: 0.0118346"
    17:39:56 "        (last output 3010) 333 shuffles run; avg. time per one shuffle: 2.93262e-006"
    17:39:56 "    Time passed during each call, %: [0.0158147,96.5336,3.44974,0.000854849]"
    17:39:56 "    Element types: ["NIL"]"
    17:39:56 "        (last output 3010) 333 shuffles run; avg. time per one shuffle: 5.42535e-005"
    17:40:10 "        (last output 0) 333 shuffles run; avg. time per one shuffle: 0.0439757"
    17:40:14 "        (last output 0) 333 shuffles run; avg. time per one shuffle: 0.0109852"
    17:40:14 "        (last output 3010) 333 shuffles run; avg. time per one shuffle: 2.93262e-006"
    17:40:14 "    Time passed during each call, %: [0.0986101,79.9295,19.9666,0.00533028]"
    17:40:15 "    Element types: ["ARRAY","BOOL","CODE","OBJECT","SCALAR","SIDE","STRING","NIL"]"
    17:40:15 "        (last output 3010) 333 shuffles run; avg. time per one shuffle: 5.71861e-005"
    17:41:16 "        (last output 2622) 333 shuffles run; avg. time per one shuffle: 0.183207"
    17:41:20 "        (last output 2622) 333 shuffles run; avg. time per one shuffle: 0.0120512"
    17:41:20 "        (last output 3010) 333 shuffles run; avg. time per one shuffle: 5.86524e-006"
    17:41:20 "    Time passed during each call, %: [0.029278,93.7978,6.16995,0.00300287]"
    17:41:20 "Running tests for arrays of size 10000"
    17:41:27 "    Element types: ["ARRAY"]"
    17:41:27 "        (last output 10000) 100 shuffles run; avg. time per one shuffle: 0.000129395"
    17:49:20 "        (last output 10000) 100 shuffles run; avg. time per one shuffle: 4.72184"
    17:49:26 "        (last output 10000) 100 shuffles run; avg. time per one shuffle: 0.0633496"
    17:49:26 "        (last output 10000) 100 shuffles run; avg. time per one shuffle: 0"
    17:49:26 "    Time passed during each call, %: [0.00270399,98.6735,1.32383,0]"
    17:49:27 "    Element types: ["BOOL"]"
    17:49:27 "        (last output 10000) 100 shuffles run; avg. time per one shuffle: 0.000129395"
    17:50:22 "        (last output 10000) 100 shuffles run; avg. time per one shuffle: 0.549231"
    17:50:27 "        (last output 10000) 100 shuffles run; avg. time per one shuffle: 0.0519482"
    17:50:27 "        (last output 10000) 100 shuffles run; avg. time per one shuffle: 9.76562e-006"
    17:50:27 "    Time passed during each call, %: [0.0215185,91.3378,8.63906,0.00162404]"
    17:50:28 "    Element types: ["CODE"]"
    17:50:28 "        (last output 10000) 100 shuffles run; avg. time per one shuffle: 0.000131836"
    17:54:28 "        (last output 10000) 100 shuffles run; avg. time per one shuffle: 2.39852"
    17:54:33 "        (last output 10000) 100 shuffles run; avg. time per one shuffle: 0.056311"
    17:54:33 "        (last output 10000) 100 shuffles run; avg. time per one shuffle: 0"
    17:54:33 "    Time passed during each call, %: [0.00537018,97.7009,2.29377,0]"
    17:54:34 "    Element types: ["OBJECT"]"
    17:54:34 "        (last output 10000) 100 shuffles run; avg. time per one shuffle: 0.000141602"
    17:57:53 "        (last output 10000) 100 shuffles run; avg. time per one shuffle: 1.98791"
    17:57:58 "        (last output 10000) 100 shuffles run; avg. time per one shuffle: 0.0525586"
    17:57:58 "        (last output 10000) 100 shuffles run; avg. time per one shuffle: 0"
    17:57:58 "    Time passed during each call, %: [0.00693918,97.4174,2.57563,0]"
    17:57:59 "    Element types: ["SCALAR"]"
    17:57:59 "        (last output 10000) 100 shuffles run; avg. time per one shuffle: 0.000129395"
    17:59:18 "        (last output 10000) 100 shuffles run; avg. time per one shuffle: 0.793972"
    17:59:23 "        (last output 10000) 100 shuffles run; avg. time per one shuffle: 0.0513281"
    17:59:23 "        (last output 10000) 100 shuffles run; avg. time per one shuffle: 0"
    17:59:23 "    Time passed during each call, %: [0.0153052,93.9134,6.07125,0]"
    17:59:24 "    Element types: ["SIDE"]"
    17:59:24 "        (last output 10000) 100 shuffles run; avg. time per one shuffle: 0.000129395"
    18:00:14 "        (last output 10000) 100 shuffles run; avg. time per one shuffle: 0.501999"
    18:00:20 "        (last output 10000) 100 shuffles run; avg. time per one shuffle: 0.0521606"
    18:00:20 "        (last output 10000) 100 shuffles run; avg. time per one shuffle: 0"
    18:00:20 "    Time passed during each call, %: [0.0233442,90.5663,9.41036,0]"
    18:00:21 "    Element types: ["STRING"]"
    18:00:21 "        (last output 10000) 100 shuffles run; avg. time per one shuffle: 0.000141602"
    18:06:24 "        (last output 10000) 100 shuffles run; avg. time per one shuffle: 3.62747"
    18:06:29 "        (last output 10000) 100 shuffles run; avg. time per one shuffle: 0.0530005"
    18:06:29 "        (last output 10000) 100 shuffles run; avg. time per one shuffle: 9.76562e-006"
    18:06:29 "    Time passed during each call, %: [0.00384722,98.5559,1.43999,0.000265326]"
    18:06:30 "    Element types: ["NIL"]"
    18:06:30 "        (last output 10000) 100 shuffles run; avg. time per one shuffle: 0.00013916"
    18:07:12 "        (last output 0) 100 shuffles run; avg. time per one shuffle: 0.41541"
    18:07:16 "        (last output 0) 100 shuffles run; avg. time per one shuffle: 0.041311"
    18:07:16 "        (last output 10000) 100 shuffles run; avg. time per one shuffle: 0"
    18:07:16 "    Time passed during each call, %: [0.0304601,90.9272,9.04238,0]"
    18:07:18 "    Element types: ["ARRAY","BOOL","CODE","OBJECT","SCALAR","SIDE","STRING","NIL"]"
    18:07:18 "        (last output 10000) 100 shuffles run; avg. time per one shuffle: 0.00013916"
    18:10:28 "        (last output 8770) 100 shuffles run; avg. time per one shuffle: 1.90115"
    18:10:33 "        (last output 8770) 100 shuffles run; avg. time per one shuffle: 0.0533008"
    18:10:33 "        (last output 10000) 100 shuffles run; avg. time per one shuffle: 0"
    18:10:33 "    Time passed during each call, %: [0.00711966,97.2659,2.72695,0]"
    18:10:33 "Running tests for arrays of size 30103"
    18:10:56 "    Element types: ["ARRAY"]"
    18:10:56 "        (last output 30103) 34 shuffles run; avg. time per one shuffle: 0.00035903"
    18:35:23 "        (last output 30103) 34 shuffles run; avg. time per one shuffle: 43.1455"
    18:35:34 "        (last output 30103) 34 shuffles run; avg. time per one shuffle: 0.311739"
    18:35:34 "        (last output 30103) 34 shuffles run; avg. time per one shuffle: 0"
    18:35:34 "    Time passed during each call, %: [0.000826163,99.2818,0.717341,0]"
    19:21:36 "    Element types: ["BOOL"]"
    19:21:36 "        (last output 30103) 34 shuffles run; avg. time per one shuffle: 0.000352972"
    19:24:20 "        (last output 30103) 34 shuffles run; avg. time per one shuffle: 4.82397"
    19:24:30 "        (last output 30103) 34 shuffles run; avg. time per one shuffle: 0.282117"
    19:24:30 "        (last output 30103) 34 shuffles run; avg. time per one shuffle: 0"
    19:24:30 "    Time passed during each call, %: [0.00691228,94.4684,5.52473,0]"
    19:24:32 "    Element types: ["CODE"]"
    19:24:32 "        (last output 30103) 34 shuffles run; avg. time per one shuffle: 0.000352747"
    19:36:47 "        (last output 30103) 34 shuffles run; avg. time per one shuffle: 21.615"
    19:36:58 "        (last output 30103) 34 shuffles run; avg. time per one shuffle: 0.318264"
    19:36:58 "        (last output 30103) 34 shuffles run; avg. time per one shuffle: 2.87224e-005"
    19:36:58 "    Time passed during each call, %: [0.00160825,98.5472,1.45103,0.000130951]"
    19:37:01 "    Element types: ["OBJECT"]"
    19:37:01 "        (last output 30103) 34 shuffles run; avg. time per one shuffle: 0.00035185"
    19:47:10 "        (last output 30103) 34 shuffles run; avg. time per one shuffle: 17.9152"
    19:47:19 "        (last output 30103) 34 shuffles run; avg. time per one shuffle: 0.279616"
    19:47:19 "        (last output 30103) 34 shuffles run; avg. time per one shuffle: 0"
    19:47:19 "    Time passed during each call, %: [0.00193376,98.4613,1.53676,0]"
    19:47:22 "    Element types: ["SCALAR"]"
    19:47:22 "        (last output 30103) 34 shuffles run; avg. time per one shuffle: 0.00035185"
    19:51:19 "        (last output 30103) 34 shuffles run; avg. time per one shuffle: 6.98556"
    19:51:28 "        (last output 30103) 34 shuffles run; avg. time per one shuffle: 0.274766"
    19:51:28 "        (last output 30103) 34 shuffles run; avg. time per one shuffle: 0"
    19:51:28 "    Time passed during each call, %: [0.00484596,96.2108,3.7843,0]"
    19:51:31 "    Element types: ["SIDE"]"
    19:51:31 "        (last output 30103) 34 shuffles run; avg. time per one shuffle: 0.00035185"
    19:54:01 "        (last output 30103) 34 shuffles run; avg. time per one shuffle: 4.40068"
    19:54:10 "        (last output 30103) 34 shuffles run; avg. time per one shuffle: 0.275175"
    19:54:10 "        (last output 30103) 34 shuffles run; avg. time per one shuffle: 3.23127e-005"
    19:54:10 "    Time passed during each call, %: [0.00752421,94.1072,5.88454,0.000690999]"
    19:54:15 "    Element types: ["STRING"]"
    19:54:15 "        (last output 30103) 34 shuffles run; avg. time per one shuffle: 0.00035544"
    20:12:58 "        (last output 30103) 34 shuffles run; avg. time per one shuffle: 33.0156"
    20:13:07 "        (last output 30103) 34 shuffles run; avg. time per one shuffle: 0.279555"
    20:13:07 "        (last output 30103) 34 shuffles run; avg. time per one shuffle: 0"
    20:13:07 "    Time passed during each call, %: [0.00106753,99.1593,0.839618,0]"
    20:13:10 "    Element types: ["NIL"]"
    20:13:10 "        (last output 30103) 34 shuffles run; avg. time per one shuffle: 0.00035185"
    20:15:11 "        (last output 0) 34 shuffles run; avg. time per one shuffle: 3.55742"
    20:15:16 "        (last output 0) 34 shuffles run; avg. time per one shuffle: 0.164702"
    20:15:16 "        (last output 30103) 34 shuffles run; avg. time per one shuffle: 0"
    20:15:16 "    Time passed during each call, %: [0.00945205,95.566,4.42452,0]"
    20:15:22 "    Element types: ["ARRAY","BOOL","CODE","OBJECT","SCALAR","SIDE","STRING","NIL"]"
    20:15:22 "        (last output 30103) 34 shuffles run; avg. time per one shuffle: 0.00035185"
    20:25:05 "        (last output 26457) 34 shuffles run; avg. time per one shuffle: 17.1633"
    20:25:15 "        (last output 26457) 34 shuffles run; avg. time per one shuffle: 0.279268"
    20:25:15 "        (last output 30103) 34 shuffles run; avg. time per one shuffle: 0"
    20:25:15 "    Time passed during each call, %: [0.00201715,98.3969,1.60104,0]"


     

    5. Details on report output

    For each combination of array count, used element types, and tested function report contains a log line describing said parameters, count of elements in the output (some functions fail to shuffle arrays with nils correctly), how many times loop was run for given array count and how much time it took for average run of shuffle function.

    On big arrays some functions fail to do the task, probably because of insufficient memory for operation of their algorithm, I dunno. Those calls report 0 time, which of course os not correct.

    Also, I had to partially rerun tests because ArmA3 ran out of memory (on CBA's shuffle of 30k array of "CODE"). You can see it in timestamps. Still all functions were in fairly equal conditions.

     

    6. Conclusions

    CBA shuffle sucks (sorry guys, but I've got numbers). Shuffles array of 30k "ARRAY" elements in 43 seconds. U WOT M8??? I had to limit test to 30k elements because of it.

    BIS shuffle does not work properly, but at least does it fast.

    When final array size is known, resize+sets work on par with pushBack on small arrays and better on big arrays. Much better. The bigger the array the better. Or, more precisely, it's pushBack who starts to work bad. The bigger the array, the worse.

    That doesn't mean biki lies about set and pushBack performance. It only considers single element insertion to the array's end position, not population of entire array.

    You can shuffle array in average O(N) time if use proper method.

     

    7. Any questions?

  11. If performance is a concern, you should replace sets with pushbacks and for loops with

    for "_i" from 0 to (cnt-1)

    And the resize is redundant, since set can add to array on its own.

    Also, you can measure the execution time in the debug console to compare different functions.

    Thanks for the tip on loops. Looks reasonable: for with three Code blocks which could be any code should generally be slower then hardcoded iterated form.

    On others I kinda disagree. I need resize to make sure there's only one reallocation for all elements of array. Since I fill array consequently I can't rely on resize done by sets for the same reason: there can be multiple reallocations. For the same reason I cannot use pushBacks. They simply cannot work faster than one resize + multiple sets.

     

    Now writing script to measure performance of scripts for different types of elements in arrays, for different sizes, etc.

     

    UPD. I'm going to set up empty mission in VR and disable simulation for player. What else can I do to minimize side effects?


  12. Hello everyone.

     

    1. Where in script scheduler can kick in and stop execution? Can it be on + in this expression: _a = (_b - _c) + (_d - _e); ?

    2. How do I know if there were context switches within some code? How many?



    _start = diag_tickTime;
    //
    some code;
    //
    _end = diag_tickTime;
    _diff = _end - _start;


    How do I know if _diff shows actual time 'some code;' was executing and not 'some code;' + other scripts times?

    3. Does  sleep 0;  cause voluntary preemption?

     

    Thanks.


  13. Update 2: Found the error, in the condition, because I'm refering to non existant units, the condition gets no return to "myUnit in thisList" and thus cannot conclude wether the condition is true or false, is there some kind of command that simply returns false otherwise or something?

    Simply check for existance/non-existance of units before checking if they're in list:

    (!isNil "unit01") && (!isNull unit01) && (unit01 in thisList)
    

  14. Cba_fnc_shuffle works a way better,i didnt even know about this bis func.

    Checked their code. Still (probably) inefficient. Although they don't have two BIS_fnc_arrayShuffle's issues I mentioned in theme start post, they have some flaws:

    • Creating a full copy of input array which is (probably) not actually necessary, causing huge memory overhead for complex element types and big elements counts.
    • Using deleteAt on this copy which can lead to up to N*(N-1)/2 single element shifts (in worst case).
    • Building up an output array from empty to full using pushBack, possibly causing multiple reallocations, whereas final elements count is known from the beginning.

    Again, I don't know how BIS array's guts work. Whether they have reallocations (shrinking block) after multiple deleteAt's (if so, one more disadvantage for CBA's way; if not, they have memory overhead, so no win there anyway). Or how operations-consuming deleteAt and pushBack are. Whether shifting element depends on element type complexity or not... Unless they use something special under the hood, abovementioned list negatively affects CBA's shuffle as well.

    OK, let's guess. Element type can be anything, so most likely some smart pointer to some variant class, and actual data stored somewhere else in heap. And array is some kind of vector. That way first flaw from my list diminishes since all elements from the copy go to output array without any reallocations or movements of actual data. Array reallocations will apply to smart pointer class type, so quite cheap (but still present).

    If only some BIS employees could give us some precious insider information on how to work extremely effectively with their arrays...  :)

    • Like 1
×