VM Profiler

VM Profiler allows JK2 modders to find hot spots and issues in their code. Below is an example output of inclusive instruction counts:

Incl Instructions     Calls Function Name
(...)
  4%    116735852   1182024 VectorNormalize
  5%    154956908    177075 PM_Weapon
  6%    192032836    206288 BG_PlayerStateToEntityStateExtraPolate
 10%    295559587     92531 SpectatorThink
 10%    298631589     30012 WP_SaberPositionUpdate
 11%    339072748    124152 PM_WalkMove
 22%    623918436     15006 G_RunFrame
 48%   1375863441    269490 PmoveSingle
 49%   1407920249    268647 Pmove
 75%   2136007703    268795 ClientThink_real
 76%   2151066861    268795 ClientThink
100%   2830033625    298858 vmMain
       2830033625  21564102 total

• Instructions is a raw instruction count executed by the corresponding function and its children.
• Incl column contains percentage of total instructions.
• Calls is how many times the function was called

Instructions

Compiling JK2MV

VM profiler is not included in JK2MV official releases due to slight performance degradation it causes. JK2MV needs to be compiled with DEBUG_VM preprocessor macro defined. You can add it to GlobalDefines CMake variable, or to CMAKE_CXX_FLAGS.

Compiling QVM Mod

Along with a QVM module, its symbol table (.map file) is required. You can produce it by passing -m option to q3asm assembler when compiling your mod.

Profiling

Only interpreted QVM can be profiled. Let's assume you want to profile game module. Run JK2MV with +set vm_game 1 +set vm_cgame 2 +set vm_ui 2 options. The only command is vmprofile:

Usage: vmprofile exclusive        start collecting exclusive counts
       vmprofile inclusive        start collecting inclusive counts
       vmprofile print [vm]       print collected data

• In exclusive mode only instructions executed inside the function body are being counted and whole Excl column sums up to 100%.
• In inclusive mode also instructions executed in function's children are added to its counter.
• print shows counters collected so far and doesn't reset them. Functions that weren't called are not printed at all.

Example

I launched the game with +set vm_game 1 parameter and typed vmprofile exclusive in the console. After two map restarts and few minutes of duelling, I checked collected counts by typing vmprofile print jk2mpgame:

Excl Instructions     Calls Function Name
(...)
  5%    105989014    113867 BG_PlayerStateToEntityStateExtraPolate
 11%    227961261    120895 ClientThink_real
 19%    375704242   1126194 Q_stricmpn
       1916298093  12820373 total

Why would Q_stricmpn be so high on the list? I suspected map restarts in the begining, so this time I ran the profiler in inclusive mode:

]vmprofile inclusive
]map_restart
==== ShutdownGame ====

(...)

]vmprofile print jk2mpgame
Incl Instructions     Calls Function Name

(...)

  1%      4144512       468 G_RunFrame
 76%    186392851    552564 Q_stricmpn
 84%    205732591    552564 Q_stricmp
 94%    231491186       993 GetIDForString
 96%    234236571         1 BG_ParseAnimationFile
 96%    234396181         1 SP_worldspawn
 96%    234781480         1 G_SpawnEntitiesFromString
 97%    238472667         1 G_InitGame
 97%    238472706         1 MVAPI_AfterInit
100%    243726221       836 vmMain
        243726221   1160581 total

That was it. You can see BG_ParseAnimationFile using a large chunk of CPU time on each restart and slowing it down. Reading the code I noticed it was due to linear search in animations dictionary and improved it by implementing a hash table. Patch can be seen here: aufau/SaberMod@100e9a9 Resulting profile of map restart:

 17%      2183968       230 Info_SetValueForKey
 18%      2389949         3 G_ParseInfos
 27%      3513933         1 G_InitBots
 48%      6083726         1 BG_ParseAnimationFile
 49%      6248520         1 SP_worldspawn
 52%      6627679         1 G_SpawnEntitiesFromString
 81%     10283284         1 G_InitGame
 81%     10283323         1 MVAPI_AfterInit
100%     12608807       421 vmMain
         12608807     76818 total

Q_stricmpn is not even in the first ten anymore, but most important are absolute numbers. Original game module used 243726221 instructions for a map restart, patched version only 12608807. 2000% improvement!

Caveats

No symbols

Make sure that:

• fs_game is set correctly and it's indeed running your mod.
• .qvm and .map files are in the mod/vm/ directory.
• QVM you're trying to profile is being interpreted, that is you added vm_* 1 option when starting JK2MV.

Printed table is empty

This probably means you are not using JK2MV compiled with DEBUG_VM definition. See Compiling JK2MV section.