Profiler Module Documentation

Documentation and program are © by Ingmar Stieger (Papillon). Version 1.6 of 13.01.2005.

Table of Contents:

I. What does this module do?
II. Using the module

I. What does this module do?

A. 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 nwnx_profile.dll in your NWN directory, load up a module, and check the logs.0 directory for nwnx_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.

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

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

D. 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:

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.

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

II. Using the module

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

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