178 lines
8.4 KiB
HTML
178 lines
8.4 KiB
HTML
<html>
|
|
<head>
|
|
<title> Profiler Module Documentation </title>
|
|
</head>
|
|
|
|
<body style="font-family:Arial,Verdana,sans-serif;">
|
|
<h2>Profiler Module Documentation</h2>
|
|
|
|
<h4>Documentation and program are © by Ingmar Stieger (Papillon). Version 1.6 of 13.01.2005.</h4>
|
|
|
|
<h3>Table of Contents:</h3>
|
|
<table>
|
|
<tr>
|
|
<td> <a href="#I">I.</a></td>
|
|
<td> <a href="#I">What does this module do?</a></td>
|
|
</tr>
|
|
<tr>
|
|
<td><a href="#II">II.</a></td>
|
|
<td><a href="#II">Using the module</a></td>
|
|
</tr>
|
|
</table>
|
|
|
|
<a name="I">
|
|
<h3>I. What does this module do?</h3>
|
|
|
|
<h4>A. General introduction</h4>
|
|
|
|
<p> 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.
|
|
|
|
<p>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
|
|
<b>logs.0</b> directory for <b>nwnx_profile.txt</b>. 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.
|
|
|
|
<p><b>Licence</b><br> This module is distributed unter the terms of the GNU
|
|
GENERAL PUBLIC LICENSE included in <a href="licence.txt">licence.txt</a>.
|
|
|
|
<h4>B. Changelog v1.1</h4>
|
|
|
|
<p>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.
|
|
|
|
<p>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.
|
|
|
|
<h4>C. Changelog v1.2</h4>
|
|
|
|
<p>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.
|
|
|
|
<p>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.
|
|
|
|
<h4>D. Changelog v1.5</h4>
|
|
|
|
<p>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.
|
|
|
|
<p>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).
|
|
|
|
<p>There are two types of NPC pathfinding in NWN:
|
|
<ul>
|
|
<li>finding a path within an area (called <i>Tile pathfinding</i>)
|
|
<li>finding a path to another area (called <i>Cross area pathfinding</i>)
|
|
</ul>
|
|
|
|
<p>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.
|
|
|
|
<p>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.
|
|
|
|
<p>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.
|
|
|
|
<h4>E. Changelog v1.6</h4>
|
|
|
|
<p>Support for NWNX.INI file has been added. There are two options that can be
|
|
configured:
|
|
|
|
<pre>
|
|
[PROFILER]
|
|
MaxLogSize = 512 ; in KByte
|
|
LogLevel = 1 ; 1=overall statistics, 2=full script callstack
|
|
</pre>
|
|
|
|
<p>LogLevel 2 produces LOTS of output, be careful. Its main purpose is to help with
|
|
identifying possible causes for server crashes.
|
|
|
|
<a name="II">
|
|
<h3>II. Using the module</h3>
|
|
|
|
<h4>A. Running the NWNX Profiler on your module</h4>
|
|
|
|
<p>The nice thing about this NWNX module is that you don't need to modify anything.
|
|
Just drop the .dll in the NWN directory.
|
|
|
|
<h4>B. The statistics</h4>
|
|
|
|
<p>The Profiler generates statistics that look like this:
|
|
|
|
<pre>
|
|
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
|
|
</pre>
|
|
|
|
(this is from the official "Prelude" module, running one minute).
|
|
|
|
<ul>
|
|
<li>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()))
|
|
<li>The second column contains the amount of time this script has used up (accumulated).
|
|
<li>The third column contains the number of times this script has been called.
|
|
<li>The footer contains some overall information about the scripts.
|
|
</ul>
|
|
</body>
|
|
</html>
|