Diagnostics/CpuScope.cs

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.

File Access
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)" );
	}
}