Page 1 of 3
nwnx profiler results
Posted: Thu May 05, 2011 12:24 pm
by zicada
Hey guys,
Here are the highest rated scripts from the nwnx profiler,- possible culprits for the jump in cpu usage after people have logged out of the server.
Could we look through these scripts and try to fix whatever bugs are causing them to act like this ?
Current statistics
---------------------------------------------------------------------------
acf_cre_onperception_morale 640234 msec 61184 calls *|
nw_c2_defaulte 201146 msec 238107 calls |
>acf_cre_onspawnin 6268 msec 9582 calls |
acf_cre_onperception 22562 msec 24941 calls |
gp_secretobject_hb 68810 msec 27843 calls *|
acf_mod_onheartbeat 759 msec 21128 calls *|
nw_c2_default1 332436 msec 257132 calls *|
>nw_c2_default1 829565 msec 1415336 calls |
>acf_cre_flocking 229659 msec 12317 calls |
acf_cre_onheartbeat 1550314 msec 236827 calls *|
acf_cre_flocking 4013 msec 12382 calls |
acf_trg_onheartbeat 3450 msec 125457 calls |
acf_cre_onblocked 221716 msec 238107 calls |
acf_area_onhbeat 162461 msec 4563505 calls *|
nw_c2_default2 71325 msec 86837 calls *|
---------------------------------------------------------------------------
Elapsed time : 10028 msec
Runtime delta : 439 msec
Total cumulative runtime : 4513163 msec
Total number of scriptcalls : 7375840
Re: nwnx profiler results
Posted: Thu May 05, 2011 12:45 pm
by Hialmar
Could you post the two or three previous reports so that we can see if some of these scripts where running a lot in the last reporting interval ?
Re: nwnx profiler results
Posted: Thu May 05, 2011 12:55 pm
by Zelknolf
These scripts are mostly AI, aside from the ones that you'd expect to be called a billion times (trigger, area, module heartbeats) -- if these are responsible for performance spikes when no one is on, I'd think we have a build problem.
Re: nwnx profiler results
Posted: Thu May 05, 2011 12:57 pm
by zicada
the current testfile is over 200mb. I'll remove it and have it start a new one, then i can put a url to it here.
Re: nwnx profiler results
Posted: Thu May 05, 2011 6:24 pm
by Galadorn
omg what a bunch'o'geeks.
Re: nwnx profiler results
Posted: Fri May 06, 2011 12:01 pm
by Hialmar
*to Zicada, ignoring Galadorn* Sounds good.
Re: nwnx profiler results
Posted: Fri May 06, 2011 12:07 pm
by zicada
Here it is, already grown to almost 90mb heh.
The process is currently around 60-65% cpu usage, after 23 hours of uptime. Had a bunch of players on last night.
http://zicada.no/temp/xp_profiler.txt
Re: nwnx profiler results
Posted: Fri May 06, 2011 11:03 pm
by Zelknolf
... is the module set to reload when empty? Or to run through some of its module load events? Or is something
calling those events repeatedly? Or are the event scripts set correctly?
Because uh,
>acf_mod_onmoduleload 346 msec 2029 calls *|
Compared to:
acf_mod_onheartbeat 0 msec 1 calls *|
That strikes me as fishy. And that pattern repeats through the log, with thousands of onmoduleloads called per few heartbeats. We're not in much trouble if it's just the script running, aside from, y'know, that it seems a bit silly to be running and we should probably get to tidying that up at some point. But if that's the module actually trying to reload itself, or part of itself, that frequently, it may well be the problem.
Re: nwnx profiler results
Posted: Sat May 07, 2011 9:19 am
by Hialmar
The > before the name of scripts means that this script has called other scripts and the count you see is, if I understand correctly, the number of calls done in the original script.
So basically this means that the module spent 346 ms in 2029 calls to other scripts.
This sounds normal.
Anyway the interesting part is towards the end of the file and there I read:
Code: Select all
>acf_mod_onmoduleload 15291 msec 2226 calls |
and farther
acf_mod_onmoduleload 5614 msec 1 calls
So the acf_mod_onmoduleload script was called only once and we spent 20 sec in the whole run so quite normal.
Now I'll fire up Excel and see if I can find something interesting at the end of the file.
Re: nwnx profiler results
Posted: Sat May 07, 2011 9:57 am
by Hialmar
Here are some interesting data (I've kept only the scripts that are called for more than 10 secs):
After 3 675 secs:
Code: Select all
Total cumulative runtime : 3675518 msec
acf_cre_onheartbeat 1384033 msec 202000 calls *|
>nw_c2_default1 575150 msec 957200 calls |
acf_cre_onblocked 573584 msec 272916 calls *|
nw_c2_default1 301667 msec 211022 calls *|
nw_c2_defaulte 284397 msec 347698 calls *|
>acf_cre_flocking 137915 msec 6045 calls *|
acf_cre_onperception_morale 101348 msec 25948 calls *|
slv_uni_blocked 64918 msec 74782 calls |
acf_area_onhbeat 61935 msec 1783176 calls *|
nw_c2_default2 33751 msec 41822 calls *|
gp_secretobject_hb 30454 msec 12491 calls *|
>acf_mod_onmoduleload 14986 msec 2222 calls |
acf_cre_onperception 13844 msec 15663 calls |
acf_cre_ondeath 13075 msec 32 calls |
>003_mod_onpcloaded 12280 msec 1631 calls |
At the end of run (3 783 secs):
Code: Select all
Total cumulative runtime : 3783629 msec
acf_cre_onheartbeat 1443139 msec 203098 calls *|
acf_cre_onblocked 596561 msec 273335 calls *|
>nw_c2_default1 575150 msec 957200 calls |
nw_c2_default1 302564 msec 212201 calls *|
nw_c2_defaulte 284707 msec 348117 calls *|
>acf_cre_flocking 151132 msec 6276 calls *|
acf_cre_onperception_morale 111007 msec 26130 calls *|
slv_uni_blocked 64918 msec 74782 calls |
acf_area_onhbeat 62662 msec 1803924 calls *|
nw_c2_default2 33878 msec 42004 calls *|
gp_secretobject_hb 31088 msec 12740 calls *|
>acf_mod_onmoduleload 15291 msec 2226 calls |
acf_cre_onperception 13844 msec 15663 calls |
acf_cre_ondeath 13075 msec 32 calls |
>003_mod_onpcloaded 12280 msec 1631 calls |
As could be expected the module spends most of its time in the acf_cre_onheartbeat (which means creature AI IIRC).
Re: nwnx profiler results
Posted: Sat May 07, 2011 10:07 am
by Hialmar
Here are some more precise figures:
During 108 secs (so about 2 minutes), we spent:
- 59 secs in the acf_cre_onheartbeat ;
- 23 secs in the acf_cre_onblocked ;
- 9 secs in the acf_cre_onperception_morale ;
The others deal mainly with standard NW scripts (nw_c2_default*).
If "c" means creatures as well, then as I understand it we have an AI problem with creatures blocked trying to unblock themselves.
Maybe we could check if people are logged in and if noone is around despawn everything blocked or leave them blocked.
If someone else want to consult the spreadsheet files here they are:
http://www.alandfaraway.org/TSMProblem.xls (Excel format)
http://www.alandfaraway.org/TSMProblem.ods (OpenOffice format)
Re: nwnx profiler results
Posted: Sat May 07, 2011 10:44 am
by Hialmar
Just checked the code:
- acf_cre_onblocked calls nw_c2_defaulte (and I suppose slv_uni_blocked
does the same) ;
- acf_cre_onheartbeat calls nw_c2_default1 ;
- acf_cre_onperception_morale calls nw_c2_default2 ;
On perception does other things but the problem are mainly in NWN default scripts so I think we should put the tests to see if people are online before calling them.
Re: nwnx profiler results
Posted: Sat May 07, 2011 12:43 pm
by Zelknolf
Yes, the nw_c2_default* scripts are AI. In fact, the fact that some instances of the scripts are not showing as hooked verifies that TSM is not ACR compliant. The thought I'm having re: AI is that Zicada is reporting that the module is eating up more processor time when all of the players log off-- and while it's certainly a bad thing if we're not despawning things when players leave, it would typically mean that the module would be as bad (or seem to be as bad) when players are on compared to when they're not if spawns were our only issue.
At least, this is why I would investigate the whole pile of module load events, even though the script itself isn't particularly intensive, the act of loading a module certainly is.
Re: nwnx profiler results
Posted: Sat May 07, 2011 12:48 pm
by zicada
After the players have logged off for the first time and the nwserver process is using alot of cpu,- once somebody logs back in, it tends to jump back down to where it was again.
One way we could test wether the issue is custom alfa content or default nwn-stuff could be to load up one of the default nwn-modules and have some people log in and out of that to see if we can reproduce the issue there.
Thoughts ?
Re: nwnx profiler results
Posted: Sat May 07, 2011 8:33 pm
by Hialmar
It's worth a try.
Although I'm afraid you won't have this kind of problem with a mod that's not a monster as TSM.
*nods to Zelk about the not hooked calls* I suppose someone dropped a few NWN standard monsters in one area.