Performance monitoring

[Per]

I've added some code to dump performance data to the script-specific dump log now. It measures all calls to events and timers, and finds the worst single call (with the game time it occurred at), average call time, and how many calls fall into two bins (higher than 25ms and higher than 50ms).

Here is an example from measuring nullbot on a very big high-oil map (using nullbot since it has many more timers to measure than semperfi-js):

Code: Select all

=== PERFORMANCE DATA ===
eventChat : 6 calls; 0ms average; 0ms worst (at 0); 0 calls over limit; 0 calls over half limit.
keepBuildingThings : 359 calls; 1ms average; 5ms worst (at 1616802); 0 calls over limit; 0 calls over half limit.
balanceGroups : 180 calls; 0ms average; 1ms worst (at 171702); 0 calls over limit; 0 calls over half limit.
produceDroids : 941 calls; 0ms average; 3ms worst (at 1792402); 0 calls over limit; 0 calls over half limit.
cheat : 60 calls; 0ms average; 0ms worst (at 0); 0 calls over limit; 0 calls over half limit.
returnDefendersToBase : 91 calls; 0ms average; 1ms worst (at 20002); 0 calls over limit; 0 calls over half limit.
eventDroidBuilt : 141 calls; 1ms average; 3ms worst (at 1560902); 0 calls over limit; 0 calls over half limit.
vtolAttack : 358 calls; 0ms average; 1ms worst (at 418202); 0 calls over limit; 0 calls over half limit.
eventDroidIdle : 214 calls; 0ms average; 0ms worst (at 0); 0 calls over limit; 0 calls over half limit.
regroupRegularly : 1217 calls; 0ms average; 5ms worst (at 1396502); 0 calls over limit; 0 calls over half limit.
attackStuff : 589 calls; 0ms average; 13ms worst (at 1770102); 0 calls over limit; 0 calls over half limit.
relaxStats : 180 calls; 0ms average; 1ms worst (at 10102); 0 calls over limit; 0 calls over half limit.
callUpdateEnemyInfo : 913 calls; 0ms average; 1ms worst (at 12002); 0 calls over limit; 0 calls over half limit.
harassStuff : 608 calls; 0ms average; 11ms worst (at 1695002); 0 calls over limit; 0 calls over half limit.
becomeHarder : 3 calls; 0ms average; 1ms worst (at 480002); 0 calls over limit; 0 calls over half limit.
huntForOil : 452 calls; 4ms average; 22ms worst (at 1702); 0 calls over limit; 0 calls over half limit.
sendAllForRepair : 1660 calls; 0ms average; 3ms worst (at 1651102); 0 calls over limit; 0 calls over half limit.
executeBuildOrder : 561 calls; 3ms average; 11ms worst (at 1596302); 0 calls over limit; 0 calls over half limit.
eventStructureBuilt : 155 calls; 0ms average; 1ms worst (at 832302); 0 calls over limit; 0 calls over half limit.
adapt : 60 calls; 0ms average; 1ms worst (at 30002); 0 calls over limit; 0 calls over half limit.
eventResearched : 37 calls; 0ms average; 1ms worst (at 357202); 0 calls over limit; 0 calls over half limit.
doResearch : 344 calls; 0ms average; 4ms worst (at 1526402); 0 calls over limit; 0 calls over half limit.
eventPickup : 2 calls; 0ms average; 0ms worst (at 0); 0 calls over limit; 0 calls over half limit.
eventDestroyed : 345 calls; 0ms average; 1ms worst (at 1042702); 0 calls over limit; 0 calls over half limit.
updateStatus : 913 calls; 0ms average; 3ms worst (at 1620002); 0 calls over limit; 0 calls over half limit.
updateGroupTargets : 900 calls; 0ms average; 1ms worst (at 10302); 0 calls over limit; 0 calls over half limit.
eventAttacked : 4905 calls; 0ms average; 8ms worst (at 1702202); 0 calls over limit; 0 calls over half limit.
buildDefenses : 72 calls; 4ms average; 8ms worst (at 1708702); 0 calls over limit; 0 calls over half limit.
eventStartLevel : 1 calls; 5ms average; 5ms worst (at 2); 0 calls over limit; 0 calls over half limit.
eventGameInit : 1 calls; 0ms average; 0ms worst (at 0); 0 calls over limit; 0 calls over half limit.
eventObjectSeen : 38 calls; 0ms average; 0ms worst (at 0); 0 calls over limit; 0 calls over half limit.

I hope this is useful to get some idea of where scripts can be improved.

[aubergine]

regroupRegularly() is a well named function! And, wow, huntForOil() needs some investigation.

Anyway, this is extremely useful stuff - much easier to find bottlenecks now. I like the fact it's tracking #calls as well.

[Originway]

thanks!

[Duha]

I've added some code to dump performance data to the script-specific dump log now. It measures all calls to events and timers, and finds the worst single call (with the game time it occurred at), average call time, and how many calls fall into two bins (higher than 25ms and higher than 50ms).

Thanks, good thing.

You can improve log readability with leftJustified()
something like that:
https://gist.github.com/4577319

[vexed]

Anything above 5ms is way too much. (heck, I would think anything above 3ms, but I am not sure what kind of overhead we have with the script stuff right now.)

While it may not seem like much, once you start adding in more AIs, then that 5ms can quickly climb to 45ms for 9 AI players.

I also think that if a function really is that slow, it would be much better to have support on the C++ side, but it should be a widely used function, and not something specific to the AI in question.

[aubergine]

Well, with this new feature at least now we can see which functions need attention. There are plenty of ways to speed things up, we just needed this log to let us know where to focus efforts.

[Goth Zagog-Thou]

Good stuff, Per.

[NoQ]

Just started using it. It's very helpful, much better than it used to be.

I just take a saved game, repeatedly reload it, run for ~30 seconds and observe the result, change the script, reload the same game again, ... until i get 0ms everywhere (:

[Duha]

Can any one attach some examples of performance log?