nwnx profiler results

[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

[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 ?

[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.

[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.

[Galadorn]

omg what a bunch'o'geeks.

[Hialmar]

*to Zicada, ignoring Galadorn* Sounds good.

[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

[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.

[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.

[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).

[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)

[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.

[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.

[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 ?

[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.