Profiler Module Documentation
From Nwnx
Documentation and program are © by Ingmar Stieger (Papillon). Version 1.6 of 13.01.2005.
|
|
What does this module do?
General introduction
The "Profiler" is a NWNX module that spits out statistics about running scripts. It shows how often a script has been called, how much time it took to complete, and gives some overall statistics. This is especially useful if you want to identify scripts with performance problems, or want to determine which scripts should be put in the script cache.
You do not need to put any special code in your scripts.... just copy the profile.dll in your NWN directory, load up a module, and check the logs.0 directory for profile.txt. Every 10 seconds, this module will append the current statistics into this file, so remember to re-open it once in a while to get updated statistics.
Licence This module is distributed unter the terms of the GNU GENERAL PUBLIC LICENSE included in licence.txt.
Changelog v1.1
The original version 1.0 overlooked some scripts. First of all, nested scripts weren't correctly logged. A script which called another script with ExecuteScript() wasn't accounted at all. Props go out to FastFrench for pointing this out.
Also, there was another script constellation that also went wrong in the previous version. When you call a function directly with ExecuteScript(1.0f, MyFunction()), not the whole script, but only a "part" of the script is executed, namely just that function. Version 1.1 takes this special case into consideration, too. "Partly" executed scripts are denoted with a '>' sign before the script name.
Changelog v1.2
The timeing measurement should be more accurate now. Previous versions took the time it took for a script to be loaded by the server into memory into account (either from disk or from the disk cache), but since NWN can cache scripts now, the profiler only measures the real execution time. This means you will get somewhat lower accumulative times compared to previous versions.
Note that scripts called via DelayCommand (e.g. DelayCommand(1.0f, ExecuteScript("myscript", OBJECT_SELF))) are counted twice, one time as a normal script call, and a second time as a "partly" called script. Thus when the line above is executed ten times, you will get two entries for this script: 10 times "myscript" and 10 times ">myscript". This is due to the way the NWN engine works and I currently do not know of a way to code around it.
Changelog v1.5
Logfiles have a fixed size limit now, which can be set at compile time. In the binary distribution, a hard limit of 512 KByte has been chosen. If the log file exceeds this limit, it will be emptied and the profiler starts again with a clean file.
During my tests, I found that pathfinding can be a big performance hog in NWN, especially under circumstances where creatures are blocked in a somewhat narrow space or where they are repeatedly trying to pathfind across several areas. Therefore, this updated version supports profiling the two pathfinding routines in NWN (that's a bit of a oversimplification, but that's how you can think of it).
There are two types of NPC pathfinding in NWN:
- finding a path within an area (called Tile pathfinding)
- finding a path to another area (called Cross area pathfinding)
Pathfinding can't be totally avoided of course, but you should be able to considerably reduce CPU cycles wasted by useless pathfinding in your module. Useless pathfinding can happen for example, when you place a NPC inside a small confined space, e.g. four fence placeables laid out as a square. It can also happen if a NPC does waypoint walking and tries to reach a waypoint that exists in the module, but is not reachable on foot. You will see excessive pathfinding events in the log file in these cases.
For tile pathfinding events, the name of the area where the pathfinding is happening is written to the log file and marked with a dollar ($) symbol. For cross area pathfinding, it's the tag of the creature marked with an at (@) symbol.
Another new feature: Updated entries are marked with a star (*) symbol. Previously, it was very hard to find out what scripts caused the delta in runtime between two logging events. Now it's easy to see which scripts eat up your valuable CPU cycles.
Changelog v1.6
Support for NWNX.INI file has been added. There are two options that can be configured:
[PROFILER] MaxLogSize = 512 ; in KByte LogLevel = 1 ; 1=overall statistics, 2=full script callstack
LogLevel 2 produces LOTS of output, be careful. Its main purpose is to help with identifying possible causes for server crashes.
Using the module
Running the NWNX Profiler on your module
The nice thing about this NWNX module is that you don't need to modify anything. Just drop the .dll in the NWN directory.
The statistics
The Profiler generates statistics that look like this:
Current statistics ----------------------------------------------------------------------------------------------- NW_G0_Conversat 0 msec 1 calls | m1q0bstud_2 0 msec 36 calls | nw_all_feedback7 0 msec 1 calls | m1q0caribeth_1 0 msec 7 calls *| nw_ch_ac1 0 msec 7 calls *| area_m1q0e_1 0 msec 5 calls | >m1q0bmagic_d 0 msec 5 calls | >m1q0bmagicb_2 0 msec 1 calls | m1q0bmagic_2 0 msec 1 calls | m1_initdlg_9 0 msec 2 calls | >m1q0atrig_2 0 msec 4 calls | m1q0bdendy_4 0 msec 7 calls *| m1q0bpatient_9 0 msec 1 calls | >nw_od_feedback8 0 msec 1 calls | m1q0brogue_d 1 msec 14 calls *| m1q0bclericb_2 0 msec 8 calls | m1q0cstud_9 1 msec 7 calls | nw_ch_ac2 0 msec 4 calls | m1q0apaveend 0 msec 1 calls | m1q0dpavel_9 0 msec 1 calls | nw_all_feedback8 0 msec 1 calls | nw_c2_default1 0 msec 77 calls *| >m1q0ddeadgob_9 0 msec 18 calls | m0q01a01pavesck1 0 msec 1 calls | m0q00plot 0 msec 1 calls | m1q0bmagicb_2 0 msec 1 calls | nw_c2_j_assvict1 0 msec 1 calls | m1q0dgeld_1 0 msec 7 calls *| m1q0d_area_1 0 msec 13 calls | m1q0bmagic_d 0 msec 7 calls | nw_od_feedback8 64 msec 1 calls | area_m1q0_1 0 msec 3 calls | m1q0apavel_1 1 msec 36 calls *| >nw_c2_default9 8 msec 116 calls *| area_m1q0b_1 0 msec 33 calls | m1q0bcleric_2 0 msec 8 calls | m1q0atrig_3 0 msec 1 calls | m1q0apavel_2 0 msec 20 calls | nw_c2_default2 0 msec 128 calls | nw_all_feedback1 0 msec 1 calls | nw_c2_default9 1 msec 3 calls | m1q0atrig_2 0 msec 2 calls | m1q0ddeadgob_9 0 msec 9 calls | ----------------------------------------------------------------------------------------------- Elapsed time : 3175 msec Runtime delta : 0 msec Total cumulative runtime : 76 msec Total number of scriptcalls : 602
(This is from the official "Prelude" module, running one minute).
- The first column is the scriptname, e.g. "m1q0bstud_2". If the first character is a '>' sign, a function within the script was called with an ExecuteScript call (e.g. ExecuteScript(1.0f, MyFunction()))
- The second column contains the amount of time this script has used up (accumulated).
- The third column contains the number of times this script has been called.
- The footer contains some overall information about the scripts.
