fred41 42 Posted June 10, 2013 (edited) ... ok i decided to make a new thread to be not to much off topic ... this was the original thread started by killzone_kid: http://forums.bistudio.com/showthread.php?156402-callExtension-can-cripple-main-process-even-if-spawned/page2 At the end of the day, the VM is going to be pretty simple - you got a queue of instructions that are executed one by one in a blocking manner ("blocking" meaning it won't move onto the next one until the current one has returned). @Deadfast, thanks for clarification, that is what i assumed. I did some performance "research" with the current script interpreter. My intention was, to find "the rules" how to optimize .sqf code. This way i found some "strange" behavoirs of the script interpreter. Especially the scheduled part seems to be not optimal and i think there is a lot of potential to accelerate the processing by adapting it to the current load situation. The following is the output of a .fsm, specialized to measure the throughput of the script interpreter (non scheduled, scheduled and condition evaluation in .fsm): "_FCEF_Logger.fsm started" "Non Scheduled Frequence Calibration 960225 Statements/sec" "Scripts = Num of scripts; SSF = Spec Sched Freq [statements/sec]; FCEF: FSM Cond Eval Freq [Conditions/sec]" "Scripts: 1 SSF: 135259 S/s FCEF: 50.085 C/s Ratio: 2700.58 TimeDiff: 10.003 s" "Scripts: 2 SSF: 68786.6 S/s FCEF: 16.8226 C/s Ratio: 4088.94 TimeDiff: 10.046 s" "Scripts: 3 SSF: 45486.6 S/s FCEF: 14.0438 C/s Ratio: 3238.91 TimeDiff: 10.04 s" "Scripts: 4 SSF: 34449.4 S/s FCEF: 11.3309 C/s Ratio: 3040.31 TimeDiff: 10.061 s" "Scripts: 5 SSF: 27301.4 S/s FCEF: 9.20792 C/s Ratio: 2964.99 TimeDiff: 10.1 s" "Scripts: 6 SSF: 22401.1 S/s FCEF: 7.62376 C/s Ratio: 2938.33 TimeDiff: 10.1 s" "Scripts: 7 SSF: 19569.7 S/s FCEF: 6.73201 C/s Ratio: 2906.96 TimeDiff: 10.101 s" "Scripts: 8 SSF: 17080.7 S/s FCEF: 5.87649 C/s Ratio: 2906.61 TimeDiff: 10.04 s" "Scripts: 9 SSF: 15256.5 S/s FCEF: 5.26786 C/s Ratio: 2896.15 TimeDiff: 10.061 s" "Scripts: 10 SSF: 13651.1 S/s FCEF: 4.76191 C/s Ratio: 2866.74 TimeDiff: 10.08 s" ... "Scripts: 20 SSF: 6683.51 S/s FCEF: 2.40848 C/s Ratio: 2775 TimeDiff: 10.38 s" ... "Scripts: 30 SSF: 4619.26 S/s FCEF: 1.6441 C/s Ratio: 2809.6 TimeDiff: 10.34 s" ... "Scripts: 40 SSF: 3447.2 S/s FCEF: 1.24521 C/s Ratio: 2768.36 TimeDiff: 10.44 s" ... "Scripts: 50 SSF: 2754.6 S/s FCEF: 0.998002 C/s Ratio: 2760.12 TimeDiff: 10.02 s" ... "Scripts: 60 SSF: 2321.39 S/s FCEF: 0.831792 C/s Ratio: 2790.83 TimeDiff: 10.82 s" ... "Scripts: 70 SSF: 1969.84 S/s FCEF: 0.710479 C/s Ratio: 2772.55 TimeDiff: 11.26 s" ... "Scripts: 80 SSF: 1714.68 S/s FCEF: 0.624999 C/s Ratio: 2743.49 TimeDiff: 11.2 s" ... ... as you can see at the top of the log, the interpreter is able to process ~1 Million simple statements per second (non scheduled on dedicated server) at a 4.00GHz CPU. The scheduled processing seems to be limited to ~ 135000 simple statements per second. This are only 13.5% of what is theoretical possible. The condition evaluations per second are degraded at the same scale like the scheduled statements per second (AI seems to be stupid, because of delayed condition evaluation) even at 50 server FPS. This is measured at constant 50 FPS without any non scheduled load in an empty mission with only one client connected! At the surface this scenario seems to be synthetical or constructed, but it isnt that simple. The scheduler, as it currently works, tends to accumulate scripts and as a result scheduled script processing can significantly slow down (FSM condition evaluation too)! My question is: Couldnt this be optimized a bit? For example by making the scheduler frequence dynamical adapted to current load? Here is my specialized .fsm for reproducing my experience: /*%FSM<COMPILE "scriptedFSM.cfg, FCEF_Logger">*/ /*%FSM<HEAD>*/ /* item0[] = {"reset",2,250,-75.000000,-350.000000,25.000000,-300.000000,0.000000,"reset"}; item1[] = {"measure",4,218,-75.000000,-275.000000,25.000000,-225.000000,0.000000,"measure"}; item2[] = {"init",0,250,-75.000000,-500.000000,25.000000,-450.000000,0.000000,"init"}; item3[] = {"settle",4,218,-75.000000,-425.000000,25.000000,-375.000000,0.000000,"settle"}; item4[] = {"spawn",2,4346,-200.000000,-350.000000,-100.000000,-300.000000,0.000000,"spawn"}; link0[] = {0,1}; link1[] = {1,4}; link2[] = {2,3}; link3[] = {3,0}; link4[] = {4,3}; globals[] = {25.000000,1,0,0,0,640,480,1,12,6316128,1,-252.080170,80.852798,-120.290154,-595.128967,671,957,1}; window[] = {2,-1,-1,-32000,-32000,880,88,1528,88,3,688}; *//*%FSM</HEAD>*/ class FSM { fsmName = "FCEF_Logger"; class States { /*%FSM<STATE "reset">*/ class reset { name = "reset"; init = /*%FSM<STATEINIT""">*/"_i = 0;" \n "SchedCount = 0;" \n "_startTime = diag_tickTime;" \n "_NextLogTime = _startTime + _MinLogInterval;" \n ""/*%FSM</STATEINIT""">*/; precondition = /*%FSM<STATEPRECONDITION""">*/"_i = _i + 1;" \n ""/*%FSM</STATEPRECONDITION""">*/; class Links { /*%FSM<LINK "measure">*/ class measure { priority = 0.000000; to="spawn"; precondition = /*%FSM<CONDPRECONDITION""">*/""/*%FSM</CONDPRECONDITION""">*/; condition=/*%FSM<CONDITION""">*/"(diag_tickTime >= _NextLogTime);"/*%FSM</CONDITION""">*/; action=/*%FSM<ACTION""">*/"_TimeSec = diag_tickTime - _startTime;" \n "_SchedCountLoc = SchedCount;" \n "_FSMConditionFrequence = _i / _TimeSec;" \n "_SchedulerFrequence = _SchedCountLoc / SchedScriptsCount / _TimeSec;" \n "diag_log format[""Scripts: %3 SSF: %1 S/s FCEF: %2 C/s Ratio: %4 TimeDiff: %5 s"", _SchedulerFrequence, _FSMConditionFrequence, SchedScriptsCount, _SchedulerFrequence / _FSMConditionFrequence, _TimeSec];" \n ""/*%FSM</ACTION""">*/; }; /*%FSM</LINK>*/ }; }; /*%FSM</STATE>*/ /*%FSM<STATE "init">*/ class init { name = "init"; init = /*%FSM<STATEINIT""">*/"diag_log (""_FCEF_Logger.fsm started"");" \n "//Number of LoadFSM.fsm instances to use" \n "NumberOfLoadFSM = 256;" \n "LoadFSMCount = 0;" \n "LoadFSMStatArray = [];" \n "LoadFSMStatArray resize NumberOfLoadFSM + 1;" \n "" \n "// number of scripts currently SPAWNED (scheduled execution)" \n "SchedScriptsCount = 0;" \n "// counter for counting the ""scheduler rounds"" " \n "SchedCount = 0;" \n "" \n "// globale variable for incrementing inside the generic test schripts" \n "globalVar = 0;" \n "" \n "// local copy of the global ""SchedCount""" \n "_SchedCountLoc = SchedCount;" \n "" \n "// define the minimal time interval in seconds to avoid flooding the log file at low load" \n "_MinLogInterval = 10;" \n "" \n "// result variable for the statements per second calculation" \n "_SchedulerFrequence = 0;" \n "// result variable for the FSM conditions per second calculation" \n "_FSMConditionFrequence = 0;" \n "" \n "// result variable to store result from time difference calculation" \n "_TimeSec = 0;" \n "// variable for counting the number of condition evaluations" \n "_i = 0;" \n "" \n "// additional running simple FSMs with 8 conditions each just to test the impact" \n "for ""_j"" from 1 to NumberOfLoadFSM do {" \n " [_j] execFSM(""loadFSM.fsm"");" \n "};" \n "" \n "// measure the speed of non scheduled script execution to have a reference, 4096*64 globalVar increments" \n "_calibrateStart = diag_Ticktime;" \n "for ""_x"" from 1 to 4096 do {" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n "};" \n "_FullSpeedFrequence = 4096 * 64 / (diag_Ticktime -_calibrateStart);" \n "diag_log format[""Non Scheduled Frequence Calibration %1 Statements/sec"", _FullSpeedFrequence];" \n "" \n "// scheduled reference load for measure the scheduler period, 64 identic statements to reduce the impact from the while statement it self" \n "SchedLoad = {" \n " SchedScriptsCount = SchedScriptsCount + 1;" \n " while {true} do {" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " SchedCount = SchedCount + 1;" \n " };" \n "};" \n "" \n "SchedScriptsCountBefore = SchedScriptsCount;" \n "SchedCount = 0;" \n "[] spawn SchedLoad;" \n "" \n "diag_log (""Scripts = Num of scripts; SSF = Spec Sched Freq [statements/sec]; FCEF: FSM Cond Eval Freq [Conditions/sec]"");" \n "" \n ""/*%FSM</STATEINIT""">*/; precondition = /*%FSM<STATEPRECONDITION""">*/""/*%FSM</STATEPRECONDITION""">*/; class Links { /*%FSM<LINK "settle">*/ class settle { priority = 0.000000; to="reset"; precondition = /*%FSM<CONDPRECONDITION""">*/""/*%FSM</CONDPRECONDITION""">*/; condition=/*%FSM<CONDITION""">*/"// waiting for the spawned reference script" \n "( SchedScriptsCount > SchedScriptsCountBefore) "/*%FSM</CONDITION""">*/; action=/*%FSM<ACTION""">*/""/*%FSM</ACTION""">*/; }; /*%FSM</LINK>*/ }; }; /*%FSM</STATE>*/ /*%FSM<STATE "spawn">*/ class spawn { name = "spawn"; init = /*%FSM<STATEINIT""">*/"SchedScriptsCountBefore = SchedScriptsCount;" \n "[] spawn SchedLoad;" \n ""/*%FSM</STATEINIT""">*/; precondition = /*%FSM<STATEPRECONDITION""">*/"_i = _i + 1;" \n ""/*%FSM</STATEPRECONDITION""">*/; class Links { /*%FSM<LINK "settle">*/ class settle { priority = 0.000000; to="reset"; precondition = /*%FSM<CONDPRECONDITION""">*/""/*%FSM</CONDPRECONDITION""">*/; condition=/*%FSM<CONDITION""">*/"// waiting for the spawned reference script" \n "( SchedScriptsCount > SchedScriptsCountBefore) "/*%FSM</CONDITION""">*/; action=/*%FSM<ACTION""">*/""/*%FSM</ACTION""">*/; }; /*%FSM</LINK>*/ }; }; /*%FSM</STATE>*/ }; initState="init"; finalStates[] = { }; }; /*%FSM</COMPILE>*/ Thanks :) Edited June 10, 2013 by Fred41 Share this post Link to post Share on other sites
Deadfast 43 Posted June 10, 2013 Thanks, good idea moving the post. I've also moved this thread to what I think is a more appropriate location (we don't want to bore everybody with fancy techno babble) :). First of all, I should probably point out that I'm not actually speaking in any official capacity, I'm just a volunteer forum moderator and a long-time tinkerer, which is where all my knowledge assumptions come from. FSM is possibly a bit unideal way to measure this, since its conditions aren't subject to script interruption. In any case, the way the VM works in non-scheduled environment, it only gets 3ms to do its thing each frame. This is why you see things being processed in batches. Share this post Link to post Share on other sites
fred41 42 Posted June 10, 2013 (edited) Thanks for your answer. ... a long-time tinkerer, which is where all my knowledge assumptions come from ... ... like me :) FSM is possibly a bit unideal way to measure this, since its conditions aren't subject to script interruption. ... i did my best to consider the specific behavior of .fsm, by using diag_tickTime as reference and just counting everything in global vars (see the attached FSM). By using large time intervals (10sec) i got very precise averaged results. But i got no info about the distribution inside the simulation frame, right. In any case, the way the VM works in non-scheduled environment, it only gets 3ms to do its thing each frame. This is why you see things being processed in batches. ... this is the info i was searching for! A fixed time slice of 3ms. That explains something. I think i generally understand the reason for limiting the scheduler, but i guess it cant be optimal to do it in this inflexible manner (a fixed time window). The first obviously disadvantage of this simple solution is that the scheduled part of script processing is not using the whole potential in low load situations (less players, less events). There is time left in the standard 20ms frame (on server) which could be used for scheduled processing if nessecary. The second more important obviously disadvantage is the discrimination of scheduled processing in high load situations. Here the length of simulation frame is extended (e.g. 100ms for 10FPS) and the scheduler VM gets still only 3ms. In result we see sometimes heavy delayed AI even at 50FPS and the whole scheduled part tends to accumulate schripts in high load situations, where the timing will be streched at all. Is it possible for you to ask the responsible developer(s) my question for optimizing this? Thanks ... EDIT: An possible first idea improvement could be the following: Lets introduce a new sqf command like setSchedulerRatio( ), where the argument is the ratio of SCHEDULER_TIME_WINDOW/CURRENT_FRAME_LENGTH expressed in percent and in the range from 10 to 90. That way, mission developer could optimize this value for a specific mission or better adapting it dynamical ingame dependent of current load. I am sure the community will find very soon an optimal algorithm to adapt this value dynamical. At this point this algorithm could be implemented in the engine and the setSchedulerRatio( ) command is no longer nessecary. Edited June 11, 2013 by Fred41 clarification Share this post Link to post Share on other sites
