Diagnostics/LobbyProbe.cs

A static diagnostics helper that samples per-frame performance while the lobby UI is open or the game is running, aggregates metrics over a configurable interval, and writes human-readable reports to the log. It tracks frame times, GPU time, GC Gen0 counts, UI timing splits, rendered panels and scene object counts, and exposes a console command to toggle/report interval.

NetworkingFile Access
using Sandbox;
using System.Linq;

namespace NZombies;

/// <summary>
/// THE LOBBY REPORTS ON ITSELF, INTO THE LOG, BECAUSE THE PUBLISHED CLIENT IS THE ONLY PLACE IT LAGS.
/// </summary>
///
/// ⛔ IT EXISTS BECAUSE THE EDITOR CANNOT REPRODUCE THE COMPLAINT, AND THAT WAS MEASURED. Reported as
/// *"the lobby is only laggy on the published versions, the editor does not suffer from it"*. The
/// obvious difference is networking — a published build auto-hosts (`NZStartup.ShouldAutoHost`) and
/// the editor does not — so it was tested head to head in the editor on Basalt, same session, same
/// focus: solo 5.51 ms median, hosting 5.51 ms median, both 180 fps. Networking is not it, the map is
/// not it (countdown 5.52), and what is left is something only the packaged client has: its
/// resolution, its settings, its mounted assets. None of that is visible from here.
///
/// ⚠️ SO THE CLIENT WRITES IT DOWN. Every `Interval` seconds while the lobby is open, one line goes
/// to the log — and a published client's log is `sbox/logs/sbox.log`, which is readable from this
/// machine with no copy-paste at all. Open the lobby for thirty seconds and the answer is on disk.
///
/// ⚠️ EACH FIELD IS A SUSPECT, NOT DECORATION:
///   fps / frame / gpu    whether it is lag at all, and CPU or GPU
///   over33               stutter, which an average hides
///   renders/s            the lobby panel re-rendering every frame (its BuildHash changing)
///   stage                the character stage being rebuilt — dress, lights, models — over and over
///   res                  the published client runs fullscreen at native size; the editor's view is small
///   objects / lights     what the world behind the menu is still holding
///   gc                   allocation pressure turning into collection pauses
///
/// ⛔ THE FIRST PUBLISHED READING SPLIT THE CASE IN TWO, AND ONLY A BREAKDOWN CAN FINISH IT. It
/// said 15.0 ms a frame with the GPU busy for 2.5 of them, no redraws, no stage rebuilds, and
/// eleven gen-0 collections a second — and a line that flat is either real CPU work or a sleeping
/// frame limiter. The engine has one that would fit: `fps_max_menu` (120 on this machine, beside
/// `fps_max` 1000 and `fps_max_inactive` 90), applied while the engine believes a menu is up. So the
/// report now carries the engine's own per-system timings — if they sum to far less than the
/// frame, the rest is the limiter asleep — plus `Game.IsMainMenuVisible` and the exception count.
///
/// ⚠️ AND IT REPORTS IN GAME TOO, AS `[nz-game-perf]`, every `GameInterval` seconds. "The lobby is
/// slow but the game is not" is a comparison, and until now only one side of it was ever written
/// down. Both sides from the same session rule out the machine, the settings and the build.
///
/// ⛔ `ui` IS SPLIT TOO, AS `[nz-lobby-ui]` (2026-10-05), because that is where the published lobby's
/// time goes: ~15 ms a frame against the editor's ~1.7, at any window size, with the lobby not
/// redrawing at all. `UISystem.Simulate` wraps each of its steps in a named `Performance.Scope`, and
/// the engine keeps those by name (`PerformanceStats.Timings.Get`): tick (every panel's tick, its
/// BuildHash and bindings, a `ScenePanel`'s own scene), input, layout, and building the draw lists.
/// Beside them, how many panels the game's UI holds and how many are shown, so a tree that grows
/// between reports is a leak. `nz_lobby_ab` (`LobbyAb`) then finds which panel it is.
public static class LobbyProbe
{
	/// <summary>Report at all. `nz_lobby_probe 0` to silence it.</summary>
	public static bool Enabled { get; set; } = true;

	/// <summary>Seconds between reports while the lobby is open.</summary>
	public static float Interval { get; set; } = 10f;

	/// <summary>Seconds between reports while playing — slower, the game is the comparison, not the suspect.</summary>
	public static float GameInterval { get; set; } = 30f;

	static bool _inLobby;
	static int _exceptions;

	/// <summary>Times the lobby panel's markup ran — counted by the razor itself.</summary>
	public static int Renders;

	/// <summary>Times the character stage was torn down and built again.</summary>
	public static int StageBuilds;

	static double _sumMs, _worstMs, _sumGpu;
	static int _frames, _slow, _gen0;
	static float _next;
	static int _rendersAt, _stagesAt;

	/// <summary>
	/// One lobby frame. Called by the panel's `OnUpdate` while it is open.
	/// </summary>
	///
	/// ⚠️ CHEAP ON EVERY FRAME AND DEAR ONLY ONCE PER REPORT. The per-frame half is four adds and a
	/// compare; the census walk happens at report time alone, so the probe cannot become the cost
	/// it is looking for.
	public static void Frame( bool inLobby = true )
	{
		// ⚠️ THE A/B (`nz_lobby_ab`) RIDES ON THIS FRAME TOO, whether or not the probe itself reports
		LobbyAb.Frame( inLobby );

		if ( !Enabled ) return;

		// ⚠️ A CHANGE OF SIDE STARTS A FRESH WINDOW, so no report ever averages lobby frames with
		// game frames — which would make both numbers wrong in the one direction that matters.
		if ( inLobby != _inLobby )
		{
			_inLobby = inLobby;
			Reset();
			return;
		}

		var s = PerfProbe.Read();
		_exceptions += Sandbox.Diagnostics.PerformanceStats.Exceptions;
		_frames++;
		_sumMs += s.FrameMs;
		_sumGpu += s.GpuMs;
		if ( s.FrameMs > _worstMs ) _worstMs = s.FrameMs;
		if ( s.FrameMs > 33.3 ) _slow++;

		// ⚠️ SUMMED, NOT DIFFED. `PerformanceStats.Gen0Collections` is a PER-FRAME count — the perf
		// log's own gen0 column averages 0.02 a row — so subtracting two samples of it printed
		// `gc0 +-1` on the first test run, which is a number that cannot mean anything.
		_gen0 += s.Gen0;

		if ( _next <= 0f ) { Reset(); return; }
		if ( Time.Now < _next ) return;

		Report( s );
		Reset();
	}

	static void Reset()
	{
		_sumMs = _worstMs = _sumGpu = 0;
		_frames = _slow = _gen0 = _exceptions = 0;
		_rendersAt = Renders;
		_stagesAt = StageBuilds;
		_next = Time.Now + System.MathF.Max( 1f, _inLobby ? Interval : GameInterval );
	}

	static void Report( PerfProbe.Sample s )
	{
		if ( _frames == 0 ) return;

		var secs = System.MathF.Max( 0.01f, _inLobby ? Interval : GameInterval );
		var avg = _sumMs / _frames;
		var fps = avg > 0.0001 ? 1000.0 / avg : 0.0;

		var scene = Game.ActiveScene;
		var objects = scene.IsValid() ? scene.GetAllObjects( false ).Count() : 0;
		var rows = PerfCensus.Take();

		// ⚠️ THE ENGINE'S OWN SPLIT, averaged over this window's frames (capped at 600, which is what
		// the engine keeps). If these sum to far less than the frame, the remainder is the limiter.
		var n = System.Math.Clamp( _frames, 1, 600 );
		var split = string.Join( " ", Sandbox.Diagnostics.PerformanceStats.Timings.GetMain()
			.Select( t => $"{t.Name.ToLowerInvariant()} {t.AverageMs( n ):0.0}" ) );

		Log.Info( $"[nz-{(_inLobby ? "lobby" : "game")}-split] {split}"
			+ $" · menu {(Game.IsMainMenuVisible ? "VISIBLE" : "hidden")}"
			+ $" · {_exceptions} exception(s)" );

		Log.Info( $"[nz-{(_inLobby ? "lobby" : "game")}-ui] {UiSteps( n )} · {Panels( scene )}" );

		Log.Info( $"[nz-{(_inLobby ? "lobby" : "game")}-perf] {fps:0} fps · frame {avg:0.0} ms avg, {_worstMs:0.0} worst,"
			+ $" {_slow} over 33 ms · gpu {_sumGpu / _frames:0.0} ms"
			+ $" · renders {(Renders - _rendersAt) / secs:0.0}/s · stage built {StageBuilds - _stagesAt}x"
			+ $" · preview {(LobbyState.PreviewStage ? "on" : "off")}"
			+ $" · res {Screen.Width:0}x{Screen.Height:0}"
			+ $" · {(Networking.IsActive ? (Networking.IsHost ? "hosting" : "client") : "solo")}"
			+ $" · {NZMap.Current} · {objects} objects, {rows.Sum( r => r.DrawCalls )} draws,"
			+ $" {rows.Sum( r => r.Lights )} lights ({rows.Sum( r => r.Shadowing )} shadowed)"
			+ $" · {_gen0} gen0 collection(s)" );
	}

	/// <summary>The engine's own steps inside `ui`, as `UISystem.Simulate` names them, and what the report calls each.</summary>
	///
	/// ⚠️ SUMMED OVER EVERY UI SYSTEM THAT RUNS THEM, the game's and the s&box menu's, since they share the names. The menu's
	/// panels sit in a suspended scene while a game runs, and a suspended root is skipped, so in practice these are the game's.
	static readonly (string Scope, string Short)[] UiScopes =
	{
		("Tick Panels", "tick"), ("Tick Input", "input"), ("Pre Layout", "prelayout"), ("Layout", "layout"),
		("Post Layout", "postlayout"), ("Build Command Lists", "build"), ("Combine Command Lists", "combine"),
	};

	static string UiSteps( int n ) => string.Join( " ", UiScopes.Select( s =>
		$"{s.Short} {Sandbox.Diagnostics.PerformanceStats.Timings.Get( s.Scope ).AverageMs( n ):0.0}" ) );

	/// <summary>
	/// How many UI components the scene has, how many panels they hold and how many of those are shown, the three biggest
	/// components, and how many objects each `ScenePanel`'s own scene holds.
	/// </summary>
	///
	/// ⛔ THE LAST TWO ARE FOR A LOBBY THAT SLOWS DOWN THE LONGER IT IS OPEN (2026-10-05 21:05-21:28, the published game after a
	/// round on Overtime): `ui` 18 → 62 ms and `update` 1 → 6 ms in twenty minutes, the main scene flat at 485 objects and the
	/// lobby not redrawing. Something grows, and these two say where: a component whose panels keep multiplying, or the
	/// character preview's private scene, which a `ScenePanel` ticks INSIDE the UI step (and whose updates count as `update`
	/// too) and which the object count above never sees.
	static string Panels( Scene scene )
	{
		if ( !scene.IsValid() ) return "no scene";

		int roots = 0, all = 0, shown = 0;
		var sizes = new System.Collections.Generic.List<(string Name, int Count)>();
		var stages = new System.Collections.Generic.List<int>();

		foreach ( var pc in scene.GetAllComponents<PanelComponent>() )
		{
			if ( pc.Panel is not { } root ) continue;
			roots++;
			int mine = 0;

			foreach ( var p in root.Descendants.Prepend( root ) )
			{
				all++;
				mine++;
				if ( p.IsVisible ) shown++;
				if ( p is Sandbox.UI.ScenePanel sp && sp.RenderScene.IsValid() )
					stages.Add( sp.RenderScene.GetAllObjects( false ).Count() );
			}

			sizes.Add( (pc.GetType().Name, mine) );
		}

		var biggest = string.Join( ", ", sizes.OrderByDescending( z => z.Count ).Take( 3 ).Select( z => $"{z.Name} {z.Count}" ) );
		return $"{roots} UI components, {all} panels ({shown} shown) · biggest: {biggest}"
			+ (stages.Count > 0 ? $" · preview scene {string.Join( "/", stages )} object(s)" : "");
	}

	/// <summary>
	/// `nz_lobby_probe [0|1] [seconds]` — the lobby's self-report: switch, and how often.
	/// </summary>
	[ConCmd( "nz_lobby_probe" )]
	public static void Cmd( int on = -1, float seconds = 0f )
	{
		if ( on >= 0 ) Enabled = on != 0;
		if ( seconds > 0f ) Interval = seconds;

		Log.Info( $"[nz-lobby-perf] probe {(Enabled ? "on" : "OFF")} · every {Interval:0}s while the"
			+ " lobby is open · a published client writes it to sbox/logs/sbox.log" );
	}
}