A static diagnostic utility that measures CPU time spent in named code scopes per frame. It provides a struct-based Measure scope for using statements, accumulates per-frame totals and call counts, exposes queries and console commands to report and measure overhead.
using Sandbox;
using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Linq;
namespace NZombies;
/// <summary>
/// WHERE THE CPU MILLISECONDS GO, per named scope, per frame.
///
/// ⛔ THE GAP THE PERF LOG COULD NOT CLOSE. PerfLog measures frame_ms and gpu_ms, so it can prove a
/// frame was CPU-bound and it can prove the cost scales with zombie count — a survival log gave a
/// clean 0.25ms per zombie, linear, no O(N^2) term. What it cannot say is WHICH work that is. Every
/// candidate read plausibly: the 10Hz think, the animation update, the voice repositioning, the
/// engine's own agent steering and avoidance. Reading the code narrowed nothing, because the
/// expensive thing is not always the thing that looks expensive — this session has already spent a
/// round blaming a scene walk that the log then showed never ran.
///
/// ⚠️ GpuProfilerStats HAS NO CPU EQUIVALENT reachable from game code, which is why this exists at
/// all rather than reading the engine's own profiler.
///
/// ⚠️ NESTED SCOPES DOUBLE-COUNT, DELIBERATELY. An outer `zombie.update` that contains
/// `zombie.think` reports both in full, so the outer tells you the subsystem's total and the inner
/// tells you its share. Totals across scopes therefore exceed frame_ms and are not meant to sum —
/// `nz_cpu` marks which scopes are outers.
///
/// ⚠️ THE OVERHEAD IS MEASURED, AND IT IS 9x WHAT I FIRST WROTE HERE. This comment claimed ~20ns
/// per scope from the cost of Stopwatch.GetTimestamp alone; `nz_cpu_overhead` reported 179ns, because
/// the dictionary lookup and the frame-roll check dominate, not the timestamp. At 36 zombies x 8
/// scopes x 60fps that is 3.1ms per SECOND — 0.31% of a frame, still fine, but a third of a percent
/// rather than a tenth. The command exists precisely so this number is read rather than asserted:
/// three instruments this session reported confidently and wrongly, and this was very nearly a
/// fourth.
/// </summary>
public static class CpuScope
{
/// <summary>
/// Collect or not.
///
/// ⚠️ ON BY DEFAULT, WHICH IS A DELIBERATE CHOICE AND NOT AN OVERSIGHT. This exists to be read
/// from a log after a normal play session, and a diagnostic that must be switched on first is a
/// diagnostic that is off on the run you needed it for. The overhead is under 0.1% of a frame.
/// `nz_cpu 0` disables it, and then Measure() is a single bool test.
///
/// ⚠️ NULLABLE-BACKED. Hotload copies statics forward by name and skips initialisers, so a plain
/// `= true` here would come back as whatever a previous compile left behind. Same trap as
/// ZombieAI.VerticalGateEnabled, which reported ON for a whole session after being set to false.
/// </summary>
public static bool Enabled
{
get => _enabled ??= true;
set => _enabled = value;
}
static bool? _enabled;
/// <summary>
/// Scopes that wrap other scopes, so a report can say totals will not sum.
///
/// ⛔ RENAMED FROM `_outers` DELIBERATELY. This static's default value changed, and s&box
/// hotload copies statics forward BY NAME and skips the initialiser -- so editing the list
/// under the old name would appear to do nothing until a full editor restart. Renaming forces
/// the new default to be constructed. Rename it again the next time this set changes.
/// </summary>
static HashSet<string> _outerScopes;
public static HashSet<string> Outers => _outerScopes ??= new()
{
"zombie.update", "frame.other",
// ⚠️ THE THREE DAMAGE-PATH OUTERS. dmg.hit is one body the bullet passed through and
// contains everything below it; dmg.ondamage is Health.OnDamage; dmg.apply is Health.Apply.
// dmg.headscale also contains dmg.part in its else branch, but it is NOT listed here -- it
// is a leaf everywhere else, and marking it outer would hide that.
"dmg.hit", "dmg.ondamage", "dmg.apply",
// ⚠️ THE FIRING OUTERS, AND THEY NEST THREE DEEP: shot.total contains shot.bullet,
// which contains dmg.hit, which contains the rest. shot.total minus shot.bullet is the
// cost of firing that is not the bullet at all -- sound, muzzle flash, recoil, UI.
"shot.total", "shot.bullet",
// ⚠️ THE FIRE-RATE CHAIN, WHICH NESTS FOUR DEEP: dtap.charge contains wep.isshooting,
// which contains wep.rpm, which contains dtap.rate. Only the three that wrap others
// are listed; dtap.rate is a leaf.
"dtap.charge", "wep.isshooting", "wep.rpm",
// ⚠️ ui.dmgnum wraps its own sync and place.
"ui.dmgnum",
};
static Dictionary<string, double> _current;
static Dictionary<string, double> _previous;
static Dictionary<string, int> _currentCalls;
static Dictionary<string, int> _previousCalls;
static Dictionary<string, double> Current => _current ??= new();
static Dictionary<string, double> Previous => _previous ??= new();
static Dictionary<string, int> CurrentCalls => _currentCalls ??= new();
static Dictionary<string, int> PreviousCalls => _previousCalls ??= new();
// ⚠️ Time.Now, not a tick counter — there is no Time.Tick in this engine. Time.Now is constant
// for the whole of a frame, so a change in it IS the frame boundary. Same approach as SoundGate.
static float _frameAt = -1f;
/// <summary>
/// Roll the accumulators if this is a new frame.
///
/// ⚠️ LAZY, from inside Measure(), rather than driven by a component's update. A collector that only
/// worked while some other object happened to exist is the PerfLog driver problem — and the
/// ordering would decide whether a scope landed in this frame or the last one.
/// </summary>
static void RollIfNewFrame()
{
if ( _frameAt == Time.Now ) return;
_frameAt = Time.Now;
// Swap rather than copy — the reader wants a stable snapshot and this avoids allocating one.
(_previous, _current) = (Current, Previous);
(_previousCalls, _currentCalls) = (CurrentCalls, PreviousCalls);
_current.Clear();
_currentCalls.Clear();
}
/// <summary>
/// Time a block: `using ( CpuScope.Measure( "zombie.think" ) ) { ... }`.
///
/// ⚠️ A STRUCT, so an enabled scope allocates nothing. A class here would put one object per
/// scope per zombie per frame on the heap, which would make the profiler the thing worth
/// profiling.
/// </summary>
// ⛔ NOT NAMED `Time`, WHICH IS WHAT IT WAS AND WOULD NOT COMPILE. `using Sandbox` brings the
// engine's `Time` class into scope, so a bare `Time( "x" )` inside this class resolved to the
// TYPE and produced "is a method, which is not valid in the given context" — a confusing error
// for a name collision. Qualifying every call site would have hidden the trap for the next one.
public static Scope Measure( string name ) => new Scope( name );
public readonly struct Scope : IDisposable
{
readonly string _name;
readonly long _start;
public Scope( string name )
{
if ( !Enabled ) { _name = null; _start = 0; return; }
RollIfNewFrame();
_name = name;
_start = Stopwatch.GetTimestamp();
}
public void Dispose()
{
if ( _name is null ) return;
var ms = (Stopwatch.GetTimestamp() - _start) * 1000.0 / Stopwatch.Frequency;
Current.TryGetValue( _name, out var had );
Current[_name] = had + ms;
CurrentCalls.TryGetValue( _name, out var n );
CurrentCalls[_name] = n + 1;
}
}
/// <summary>Milliseconds spent in a scope during the last complete frame.</summary>
public static double Get( string name )
{
Previous.TryGetValue( name, out var ms );
return ms;
}
/// <summary>Times this scope was entered during the last complete frame.</summary>
public static int Calls( string name )
{
PreviousCalls.TryGetValue( name, out var n );
return n;
}
/// <summary>Every scope seen in the last complete frame, dearest first.</summary>
public static List<(string Name, double Ms, int Calls)> Ranked()
=> Previous
.Select( kv => (kv.Key, kv.Value, Calls( kv.Key )) )
.OrderByDescending( x => x.Value )
.ToList();
// ── commands ─────────────────────────────────────────────────────────────
/// <summary>
/// `nz_cpu [0|1]` — the last frame's CPU breakdown by scope.
///
/// ⚠️ ONE FRAME, NOT AN AVERAGE. A single frame from a paused editor is not representative of
/// anything; the value of this command is checking the scopes are wired and reporting sane
/// numbers. The averages come from the perf log, which carries these columns every frame.
/// </summary>
[ConCmd( "nz_cpu" )]
public static void Report( int on = -1 )
{
if ( on >= 0 )
{
Enabled = on != 0;
Log.Info( $"[nz-cpu] collection {(Enabled ? "ON" : "off")}" );
if ( !Enabled ) return;
}
var rows = Ranked();
if ( rows.Count == 0 )
{
Log.Warning( "[nz-cpu] nothing recorded — no frame has run since collection was enabled,"
+ " or the game is not playing" );
return;
}
Log.Info( $"[nz-cpu] last frame, dearest first (collection {(Enabled ? "ON" : "off")})" );
Log.Info( $"[nz-cpu] {"scope",-24} {"ms",8} {"calls",7} {"us/call",9}" );
foreach ( var (name, ms, calls) in rows )
{
var per = calls > 0 ? ms * 1000.0 / calls : 0.0;
Log.Info( $"[nz-cpu] {name,-24} {ms,8:0.000} {calls,7} {per,9:0.0}"
+ (Outers.Contains( name ) ? " (outer)" : "") );
}
Log.Info( "[nz-cpu] outers CONTAIN the scopes below them — these do not sum to frame time" );
}
/// <summary>
/// `nz_cpu_overhead` — what the timer itself costs, measured rather than claimed.
///
/// ⛔ BECAUSE A PROFILER THAT DISTORTS WHAT IT MEASURES IS WORSE THAN NONE. Three separate
/// instruments this session reported confidently and wrongly, so this one states its own error
/// bar instead of asserting it is negligible.
/// </summary>
[ConCmd( "nz_cpu_overhead" )]
public static void Overhead( int samples = 20000 )
{
var was = Enabled;
Enabled = true;
// Warm up, so JIT is not counted as overhead.
for ( int i = 0; i < 1000; i++ ) using ( Measure( "overhead.warm" ) ) { }
var t0 = Stopwatch.GetTimestamp();
for ( int i = 0; i < samples; i++ ) using ( Measure( "overhead.probe" ) ) { }
var ms = (Stopwatch.GetTimestamp() - t0) * 1000.0 / Stopwatch.Frequency;
Enabled = was;
var ns = ms * 1e6 / samples;
Log.Info( $"[nz-cpu] {samples} scopes in {ms:0.00} ms = {ns:0} ns per scope" );
Log.Info( $"[nz-cpu] at 36 zombies x 8 scopes x 60fps that is"
+ $" {36 * 8 * 60 * ns / 1e6:0.00} ms per second"
+ $" ({36 * 8 * ns / 1e6 / 16.7 * 100:0.00}% of a 60fps frame)" );
}
}