Performance monitoring

For AI and campaign script related discussions and questions

Performance monitoring

Postby Per » 19 Jan 2013, 18:20

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.
Per
Warzone 2100 Team Member
Warzone 2100 Team Member
 
Posts: 3605
Joined: 03 Aug 2006, 19:39

Re: Performance monitoring

Postby aubergine » 19 Jan 2013, 20:41

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.
"Dedicated to discovering Warzone artefacts, and sharing them freely for the benefit of the community."
-- https://warzone.atlassian.net/wiki/display/GO
User avatar
aubergine
Professional
Professional
 
Posts: 3459
Joined: 10 Oct 2010, 00:58

Re: Performance monitoring

Postby Originway » 20 Jan 2013, 08:21

thanks!
Originway
Trained
Trained
 
Posts: 412
Joined: 08 Aug 2012, 06:22

Re: Performance monitoring

Postby Duha » 20 Jan 2013, 10:43

Per wrote: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
http://addons.wz2100.net/ developer
User avatar
Duha
Trained
Trained
 
Posts: 287
Joined: 25 Mar 2012, 20:05
Location: SPb, Russia

Re: Performance monitoring

Postby vexed » 25 Jan 2013, 05:44

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.
/facepalm ...Grinch stole Warzone🙈🙉🙊 contra principia negantem non est disputandum
Super busy, don't expect a timely reply back.
User avatar
vexed
Inactive
Inactive
 
Posts: 2407
Joined: 27 Jul 2010, 02:07

Re: Performance monitoring

Postby aubergine » 25 Jan 2013, 06:19

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.
"Dedicated to discovering Warzone artefacts, and sharing them freely for the benefit of the community."
-- https://warzone.atlassian.net/wiki/display/GO
User avatar
aubergine
Professional
Professional
 
Posts: 3459
Joined: 10 Oct 2010, 00:58

Re: Performance monitoring

Postby Goth Zagog-Thou » 25 Jan 2013, 09:13

Good stuff, Per. :)
User avatar
Goth Zagog-Thou
Regular
Regular
 
Posts: 1582
Joined: 06 Jan 2007, 08:08
Location: Delta Base

Re: Performance monitoring

Postby NoQ » 26 Jan 2013, 17:25

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 (:
User avatar
NoQ
Special
Special
 
Posts: 6068
Joined: 24 Dec 2009, 11:35
Location: /var/zone

Re: Performance monitoring

Postby Duha » 04 Feb 2013, 13:21

Can any one attach some examples of performance log?
http://addons.wz2100.net/ developer
User avatar
Duha
Trained
Trained
 
Posts: 287
Joined: 25 Mar 2012, 20:05
Location: SPb, Russia


Return to Scripting