[profiler] What to do with the information?

[Jack_Wellignton]

Hello guy I just dl your program and was mainly interrested about the profiler. Recently, I became technician (mostly mapping for me) on a french module called ''Royaumes Insulaires'' (two module). Our module is well know around french community and somewhat respected. However, because of frequent change in staff and passing of module between many hand (some not so experimented), I find it has accumulated lot of problem over time. I thought your program was a nice way for me to try and maybe catch one or two big old crappy script. After installation, I ran it first time and got some interresting data... but... what do I do now!? For starter like me how can we know a script is heavy? With my data could you give some hint as to how I should then use it to kill some lag? I know that some script are naturally more important and heavy then other but was is acceptable? When does supposed ''light''(not important) script become heavy? Finally how many msec are there in 1 hour 35 min (joking)?

[Papillon]

It's all relative. There is no way to tell if a script eats up too much CPU time in a absolute way.

I would start with those scripts that have the highest msecs (e.g. spawndaemon) or the highest total calls (e.g. mod_item_acq) and try to make them more efficient or call them less often.

Btw, a runtime delta of 1456 msec is pretty high. Depending on player load, Avlis rarely gets over 600 msecs.
_________________
Papillon

[Jack_Wellignton]

Very old script... the first one I checked actually after looking at data. It actually used to spawn pnj at difinite time and run on a on_hearthbeat. It is an important script in some way and used a lot. I will try and convince my team to convert spawn from this system to encounter. Thank for the hint..

[Jurivancer]

After the 1.66 update, we have been experiencing severe lag problems in our mod.

We have been trying to clean up stuff and remove any old, now extraneous scripts, etc.

We came upon your profiler and decided to go over the log files and see if we can find some useful info from it.

I am currently going over a log file, and one of our sections has what I assume to be a very high runtime delta:

Current statistics
-----------------------------------------------------------------------------------------------
onmoduleload 0 msec 1 calls *| no_scr_logspnloc 0 msec 1 calls *|
exposemap 1 msec 210 calls *| frc_rulebook 0 msec 1 calls *|
no_spn_melcast3 14 msec 1 calls *| x2_def_spawn 1030 msec 168 calls *|
nw_c2_dropin9 35 msec 2 calls *| frc_remove_temp 72 msec 2342 calls *|
sitonspawn 0 msec 1 calls *| no_scr_logeq 0 msec 1 calls *|
_mod_onenter 7 msec 1 calls *| acquireditem_tag 2751 msec 2342 calls *|
>no_spn_melcast3 0 msec 1 calls *| x0_ch_hen_spawn 4 msec 8 calls *|
torch_onequip 0 msec 5 calls *| nw_c2_omnivore 23 msec 7 calls *|
nw_c2_herbivore 168 msec 64 calls *| nw_c2_default9 1737 msec 263 calls *|
-----------------------------------------------------------------------------------------------
Elapsed time : 10005 msec
Runtime delta : 5842 msec
Total cumulative runtime : 5842 msec
Total number of scriptcalls : 5420

Now, I can look at this and see which scripts are called the most and which have the highest runtime, but what does the "Runtime Delta" actually mean?

(most other log blocks are in the 3-400 range with a couple being around 1000-1500, this being the most extreme example of a high runtime delta I thought I would post it).

Any info would be appreciated.
_________________
DM Jurivancer
Forgotten Realms Cormyr

[Acrodania]

Ouch. I can see where the lag would show up.

I can't pretend to understand what the "Delta" is but we normally run at around 800. Previous experience shows that when we go over 2,000 we start to have lag.

Look for scripts that have a hight MSec time compared to # of calls.

Example:
exposemap has 210 calls but only uses 1 msec
x2_def_spawn has 168 calls but takes 1030 msec to run them

Look over the rest of the scripts in the module and see if you can find other high msec to # run ratios. Remember that the script engine is single-threaded, if it takes one second to run a script the whole module stops while that script runs.....

[Papillon]

Runtime delta is the amount of time the profiler has recorded between two statistics update. In other words, the difference between the current "Total cumulative runtime" and the last "Total cumulative runtime". It's the total amount of time your scripts used up in the last ~10 seconds.

The example you posted seems to be the very first iteration (i.e. module load), which is not representative.
_________________
Papillon

[Jurivancer]

Thanks for the info.

Yeah, I'm guessing you are right about the log I posted being the startup.

Here is a followup to the Runtime Delta question.

I picked a log entry from the middle of the accumlated log, look at at all the scripts and such, then I go to the summary:

[Papillon]

You could do some obvious math with the "total" values, but the really interesting values are the delta (to quickly find a section where a script ran wild) and then of course the number of calls per script and how long it took to run.

There is no absolute good or bad with scripts and runtime, some scripts are just heavy and cannot be optimized further. The Profiler is an invaluable tool for finding those 4-5 script that should not eat up CPU time at all, or for finding NPCs pathfinding in vain.

A delta value below 1 second per 10 seconds is what I'd consider normal and good, below 600msec is even better. The less time your scripts eat, the more time the server has for other things.
_________________
Papillon