Changes between Version 1 and Version 2 of EngineProfiling

Timestamp:

Jul 31, 2011, 11:16:18 PM (13 years ago)

Author:

Philip Taylor

Comment:

more profiling

EngineProfiling

@@ -28 +28 @@
 and it will measure all code from the `PROFILE` until the end of the current scope. (You can also use `PROFILE_START("foo"); ... PROFILE_END("foo");` which automatically add scoping braces.)
 
+The profiler is relatively expensive; you usually shouldn't put `PROFILE` in code that will be called thousands of times per frame, since the profiling overhead will dominate the code you're trying to measure.
+
 Pressing F11 multiple times will toggle through different profiler modes (script data, network data, renderer data).
 
 Pressing Shift+F11 will save `profile.txt` somewhere (usually the `binaries/system/` directory, assuming you're running code from SVN). Pressing it multiple times (without restarting the game) will append new measurements to that file.
+
+== Low-overhead timer ==
+
+A less fancy way to measure sections of code is:
+{{{
+#include "lib/timer.h"
+...
+{
+  TIMER(L"description");
+  ... code to measure ...
+}
+}}}
+which will record the time from `TIMER` until the end of the current scope, then immediately print it via `debug_printf` (which goes to `stdout` on Unix, and the debugger Output window on Windows).
+
+To measure cumulative time spent in a section of code:
+{{{
+#include "lib/timer.h"
+TIMER_ADD_CLIENT(tc_SomeDescription);
+...
+{
+  TIMER_ACCRUE(tc_SomeDescription);
+  ... code to measure ...
+}
+}}}
+which will sum the time spent, then print it via `debug_printf` once when the game is shutting down. The output will be like
+{{{
+TIMER TOTALS (9 clients)
+-----------------------------------------------------
+  tc_SomeDescription: 10.265 Mc (12x)
+  ...
+}}}
+saying the cumulative time, measured in CPU cycles (kc = kilocycles (10^3^), Mc = megacycles (10^6^), etc). (It measures cycles since that's cheaper and more reliable than converting to seconds, given that clock frequency can change while the game is running. Divide by your CPU frequency manually to get real time). This should have significantly lower overhead than `PROFILE`, so you can use it in functions that get called more often.
+
+== Simulation replay mode ==
+
+If you're not measuring graphics or GUI code, replay mode lets you run the simulation (the gameplay code and scripts and the AI etc) at maximum speed with all graphics disabled. This should be fully deterministic (i.e. you'll get the same results on each run) and doesn't need user interaction (so you can easily run in Valgrind).
+
+First, play the game normally, in either single-player or multiplayer. It will generate a file `~/.config/0ad/logs/sim_log/${PID}/commands.txt` (or somewhere in `%APPDATA%\logs\` on Windows) based on the process ID; looking for the newest directory should find it. This contains the map setup data and a list of all players' inputs, so the game can be replayed. You might want to copy the `commands.txt` to somewhere memorable.
+
+Run the game like
+{{{
+./pyrogenesis -replay=path/to/commands.txt
+}}}
+(or something equivalent on Windows). It will print its status to `stdout` (or the Output window on Windows). It gives the MD5 checksum of the complete simulation state once it's finished, which is handy if you're changing the code and want to make sure you're not affecting the simulation behaviour. Run in a profiler to measure whatever you want to measure.
+
+It also stores the in-game profiler state in `profile.txt` every 20 turns. There's a script in `source/tools/replayprofile/` which can plot a graph from that file.
+
+== Valgrind ==
+
+Callgrind with KCacheGrind is quite nice for detailed (though not hugely accurate) profiling. Valgrind often doesn't like !SpiderMonkey's JITs so you may have to use `valgrind --smc-check=all ...` if it otherwise crashes.