Audio/EditorAudioDiagnostics.cs

Editor-only diagnostics component that watches audio playback and engine timing during editor play sessions. It samples engine performance counters, music and tone playback cursors, tracks UI activity, logs warnings for frame gaps or stalled audio cursors, can emit a continuous PCM tone, and provides console commands to mark history, enable profiling windows, and toggle the reference tone.

File AccessNative Interop
using System.Diagnostics;
using Sandbox.Diagnostics;

namespace BlockParty;

/// <summary>
/// Editor-only, passive watchdog. No tasks, forced GC, file writes, or per-frame log strings.
/// Time is the mix thread's published sample cursor, not proof that the output device was audible.
/// A driver dropout (or decoded silence with an advancing cursor) needs a manual marker/tone test.
/// </summary>
internal sealed class EditorAudioDiagnostics : IDisposable
{
	private const double FrameWarningSeconds = 0.25;
	private readonly Snapshot[] _history = new Snapshot[32]; // ~16 seconds at two samples/sec
	private int _next, _count;
	private readonly double _startedAt = Now;
	private double _previousStart, _previousWork, _nextSample, _nextFrameWarning;
	private double _maxGap, _maxWork;
	private double _windowSeconds, _profileUntil;
	private int _frames, _focusedFrames;
	private PhaseSnapshot _phasePeaks;
	private int _phaseFollowupFrames;
	private long _bytes, _gcTicks;
	private int _gen0, _gen1, _gen2, _exceptions;
	private SoundHandle _previousMusic, _tone;
	private SoundFile _toneFile;
	private AudioCursorWatch _musicWatch, _toneWatch;
	private bool _previousPaused, _previousValid;
	private bool _disabled;
	private Snapshot _latest;
	private readonly EditorUiActivity _uiActivity = new();
	private double _nextUiDump;
	private static double Now => Stopwatch.GetTimestamp() / (double)Stopwatch.Frequency;

	public EditorAudioDiagnostics()
	{
		Log.Info( "[audio-diag] Editor watchdog enabled: frame gaps >=250ms, stationary audio cursors >=500ms. " +
			"audio_diag_mark dumps recent history including leaderboard/picker activity; audio_diag_tone true/false enables/disables a quiet PCM reference tone. " +
			"audio_diag_profile true logs allocation/frame windows for two minutes (false stops early). " +
			"GC/phase fields are engine completed-frame observations, not proof of cause; phase peaks are per sample window " +
			"and may overlap. Device silence may require a manual marker." );
	}

	public FrameScope BeginFrame( string stage )
	{
		if ( !Game.IsEditor || _disabled ) return default;
		try
		{
			return SampleFrame( stage );
		}
		catch ( Exception exception )
		{
			DisableAfterFailure( exception );
			return default;
		}
	}

	private void DisableAfterFailure( Exception exception )
	{
		// A broken diagnostic must not abort GameManager.OnUpdate or retry/throw every frame.
		_disabled = true;
		Dispose();
		Log.Warning( $"[audio-diag] Watchdog disabled for this play session after a diagnostic error; " +
			$"game updates will continue. Restart the play session after fixing the diagnostic. {exception}" );
	}

	private FrameScope SampleFrame( string stage )
	{
		double now = Now;
		double gap = _previousStart == 0 ? 0 : now - _previousStart;
		_previousStart = now;
		_windowSeconds += gap;
		_frames++;
		if ( Application.IsFocused ) _focusedFrames++;
		_maxGap = Math.Max( _maxGap, gap );
		_maxWork = Math.Max( _maxWork, _previousWork );
		_bytes += PerformanceStats.BytesAllocated;
		_gcTicks += PerformanceStats.GcPause;
		_gen0 += PerformanceStats.Gen0Collections;
		_gen1 += PerformanceStats.Gen1Collections;
		_gen2 += PerformanceStats.Gen2Collections;
		_exceptions += PerformanceStats.Exceptions;
		var phases = PhaseSnapshot.Read();
		_phasePeaks.Include( phases );

		var music = Audio.DiagnosticMusicHandle;
		bool changed = !ReferenceEquals( music, _previousMusic );
		var sound = SoundSnapshot.Read( music );
		var tone = SoundSnapshot.Read( _tone );
		float previousCursor = _latest.Music.Cursor;
		bool frameGap = gap >= FrameWarningSeconds;
		var musicChange = _musicWatch.Update( now, sound.Cursor, sound.AudibleCandidate,
			changed || frameGap || sound.Paused != _previousPaused );
		var toneChange = _toneWatch.Update( now, tone.Cursor, tone.AudibleCandidate, frameGap );
		if ( stage != _uiActivity.Current.Stage ) _uiActivity.ClearState();
		_latest = new Snapshot
		{
			Seconds = now - _startedAt, Stage = stage, Focused = Application.IsFocused,
			Path = Audio.DiagnosticMusicPath, Music = sound, Tone = tone,
			Gap = gap, Work = _previousWork, EngineFrame = PerformanceStats.FrameTime,
			MaxGap = _maxGap, MaxWork = _maxWork, Bytes = _bytes, GcTicks = _gcTicks,
			Gen0 = _gen0, Gen1 = _gen1, Gen2 = _gen2, Exceptions = _exceptions,
			WindowSeconds = _windowSeconds, Frames = _frames, FocusedFrames = _focusedFrames,
			Phases = phases, PhasePeaks = _phasePeaks, Ui = _uiActivity.Current,
			MusicStill = _musicWatch.StillSeconds, ToneStill = _toneWatch.StillSeconds
		};

		if ( frameGap && now >= _nextFrameWarning )
		{
			_nextFrameWarning = now + 5; // no log flood when background throttled or debugging
			_phaseFollowupFrames = 3; // the engine may publish the hitch's phase timings on the NEXT frame
			Log.Warning( $"[audio-diag] FRAME GAP: {gap * 1000:0}ms between updates; previous GameManager update " +
				$"{_previousWork * 1000:0}ms, outside that update {Math.Max( 0, gap - _previousWork ) * 1000:0}ms; " +
				$"music cursor {previousCursor:0.000}->{sound.Cursor:0.000}. " +
				"Background throttling, editor pause/debugger and hotload can also cause gaps. " + _latest.Describe() );
			DumpUiActivity( now );
		}
		else if ( _phaseFollowupFrames > 0 )
		{
			_phaseFollowupFrames--;
			Log.Info( $"[audio-diag] FRAME GAP FOLLOW-UP +{_latest.Seconds:0.000}s " +
				$"stage={stage} engineFrame={_latest.EngineFrame * 1000:0}ms " +
				$"engineLastMs=[{phases}] gcPause={PerformanceStats.GcPause / 10000.0:0.00}ms" );
		}
		if ( !changed && _previousValid && !sound.Valid )
		{
			Log.Warning( "[audio-diag] MUSIC HANDLE ENDED without a track switch/StopMusic: " + _latest.Describe() );
		}
		else if ( changed || sound.Paused != _previousPaused || sound.Valid != _previousValid )
		{
			Log.Info( "[audio-diag] MUSIC STATE changed: " + _latest.Describe() );
		}
		ReportCursor( "MUSIC", musicChange, _latest );
		ReportCursor( "PCM", toneChange, _latest );
		_previousMusic = music;
		_previousPaused = sound.Paused;
		_previousValid = sound.Valid;

		if ( now >= _nextSample )
		{
			if ( now < _profileUntil ) Log.Info( "[audio-diag] PROFILE " + _latest.Describe() );
			_history[_next] = _latest;
			_next = (_next + 1) % _history.Length;
			_count = Math.Min( _count + 1, _history.Length );
			_nextSample = now + 0.5;
			_maxGap = _maxWork = 0;
			_phasePeaks = default;
			_bytes = _gcTicks = 0;
			_gen0 = _gen1 = _gen2 = _exceptions = 0;
			_windowSeconds = 0;
			_frames = _focusedFrames = 0;
		}
		// Exclude diagnostic sampling/logging from game-work time, but include it in the next gap.
		return new FrameScope( this, Now );
	}

	private void ReportCursor( string source, AudioCursorWatch.Change change, Snapshot sample )
	{
		if ( change == AudioCursorWatch.Change.Stalled )
		{
			Log.Warning( $"[audio-diag] {source} CURSOR STALLED across running game updates (>=500ms). " + sample.Describe() );
			DumpUiActivity( Now );
		}
		else if ( change == AudioCursorWatch.Change.Recovered )
			Log.Info( $"[audio-diag] {source} cursor resumed. " + sample.Describe() );
	}

	[ConCmd( "audio_diag_mark" )]
	public static void Mark()
	{
		if ( !Game.IsEditor ) return;
		var diagnostics = GameManager.Instance?.AudioDiagnostics;
		if ( diagnostics is null ) { Log.Info( "[audio-diag] Start the game first." ); return; }
		if ( diagnostics._disabled ) Log.Warning( "[audio-diag] Watchdog is disabled; the following history is stale." );
		Log.Info( "[audio-diag] MANUAL DROPOUT MARKER: recent samples oldest first. " +
			"Window totals: frames/alloc/GC/exceptions; frames counts GameManager updates, not GPU presents. " +
			"fps uses wall time; allocBPerFrame is engine-wide allocated bytes per observed update, not retained memory. " +
			"focusedFrames counts updates observed with focus; maxGap/maxWork cover every update in that sample window. " +
			"enginePeakMs retains each category's largest completed-frame timing in the window; categories can overlap " +
			"and GPU timings may arrive later. These are engine-wide, not just this game's work. " +
			"A moving cursor does not rule out silent decoding, mixer or output-device trouble." );
		for ( int i = 0; i < diagnostics._count; i++ )
		{
			int index = (diagnostics._next - diagnostics._count + i + diagnostics._history.Length) % diagnostics._history.Length;
			Log.Info( "[audio-diag] HISTORY " + diagnostics._history[index].Describe() );
		}
		Log.Info( "[audio-diag] LATEST " + diagnostics._latest.Describe() );
		diagnostics.DumpUiActivity( Now, force: true );
	}

	public void ObserveLeaderboard( object owner, string level, bool loading, bool pickerOpen,
		int rows, int first, int last, float scroll, string action = null, float input = 0 )
	{
		if ( !Game.IsEditor || _disabled ) return;
		_uiActivity.Board( owner, Now - _startedAt, level, loading, pickerOpen, rows, first, last, scroll, action, input );
	}

	public void ObserveLevelSelect( object owner, string level, bool loading, int rows, int first, int last,
		float scroll, float mapX, float mapY, string action = null, float input = 0 )
	{
		if ( !Game.IsEditor || _disabled ) return;
		_uiActivity.Board( owner, Now - _startedAt, level, loading, false, rows, first, last, scroll,
			action, input, "LevelSelectStage", mapX, mapY );
	}

	public void ObservePicker( bool grid, float x, float y, int previews, int searchLength, string action = null )
	{
		if ( !Game.IsEditor || _disabled ) return;
		_uiActivity.Picker( Now - _startedAt, grid, x, y, previews, searchLength, action );
	}

	private void DumpUiActivity( double now, bool force = false )
	{
		if ( !force && now < _nextUiDump ) return;
		_nextUiDump = now + 5;
		double seconds = now - _startedAt;
		var message = new System.Text.StringBuilder();
		message.Append( "[audio-diag] UI ACTIVITY: last 20s, up to 64 entries; movement is coalesced. " +
			"Visible row ranges are zero-based, end-exclusive; context is the last UI observation, not a sampled call stack. " +
			_uiActivity.Current.Describe( seconds ) );
		for ( int i = 0; i < _uiActivity.Count; i++ )
		{
			var entry = _uiActivity.Oldest( i );
			if ( seconds - entry.LastAt <= 20 ) message.Append( "\n[audio-diag] UI EVENT " ).Append( entry.Describe() );
		}
		// One log event avoids repeated editor-console text updates for every buffered action.
		Log.Info( message.ToString() );
	}

	[ConCmd( "audio_diag_profile" )]
	public static void Profile( bool enabled = true )
	{
		if ( !Game.IsEditor ) return;
		var diagnostics = GameManager.Instance?.AudioDiagnostics;
		if ( diagnostics is null ) { Log.Info( "[audio-diag] Start the game first." ); return; }
		if ( diagnostics._disabled ) { Log.Warning( "[audio-diag] Watchdog is disabled; restart the play session." ); return; }
		diagnostics._profileUntil = enabled ? Now + 120 : 0;
		Log.Info( $"[audio-diag] Allocation window logging {(enabled ? "ON for 120 seconds" : "OFF")}. " +
			"Keep the game focused and use the same fps_max for comparisons. " +
			"frames counts GameManager updates, not GPU presents; allocation counters cover the engine process. " +
			"Logging adds a small amount of allocation at two samples per second; the first window may include pre-command updates." );
	}

	[ConCmd( "audio_diag_tone" )]
	public static void Tone( bool enabled = true )
	{
		if ( !Game.IsEditor ) return;
		var diagnostics = GameManager.Instance?.AudioDiagnostics;
		if ( diagnostics is null ) { Log.Info( "[audio-diag] Start the game first." ); return; }
		if ( diagnostics._disabled ) { Log.Warning( "[audio-diag] Watchdog is disabled; restart the play session." ); return; }
		try { diagnostics.SetTone( enabled ); }
		catch ( Exception exception ) { diagnostics.DisableAfterFailure( exception ); }
	}

	private void SetTone( bool enabled )
	{
		_tone?.Stop();
		_tone = null;
		_toneWatch = default;
		if ( enabled )
		{
			// Uncompressed 220Hz sine, one second / integer cycles. Opt-in and audible so a silent
			// voice optimization cannot invalidate the reference. Bypasses Music mixer/our sliders.
			if ( _toneFile is null )
			{
				const int rate = 48000;
				var pcm = new byte[rate * 2];
				for ( int i = 0; i < rate; i++ )
				{
					short value = (short)(MathF.Sin( MathF.Tau * 220 * i / rate ) * short.MaxValue);
					pcm[i * 2] = (byte)value;
					pcm[i * 2 + 1] = (byte)(value >> 8);
				}
				_toneFile = SoundFile.FromPcm( "blockparty_audio_diag_pcm", pcm,
					new SoundFile.PcmOptions { Channels = 1, Rate = rate, Bits = 16, Loop = true } );
			}
			_tone = Sound.PlayFile( _toneFile, 0.015f, 1f );
			if ( _tone is not null )
			{
				_tone.TargetMixer = Sandbox.Audio.Mixer.FindMixerByName( "Master" );
				_tone.ListenLocal = true;
				_tone.SpacialBlend = 0;
				_tone.DistanceAttenuation = false;
			}
		}
		Log.Info( $"[audio-diag] PCM reference tone {(enabled ? "requested ON" : "OFF")}. " +
			"Music-only dropout with continuous tone points toward the music path; both dropping points toward shared audio/output. " +
			"The tone still follows engine master volume." );
	}

	public void Dispose()
	{
		// Disposal is terminal even if a stopped scene still has a reachable manager.
		_disabled = true;
		var tone = _tone;
		_tone = null;
		try { tone?.Stop(); }
		catch ( Exception exception )
		{
			Log.Warning( $"[audio-diag] Could not stop the diagnostic tone: {exception.Message}" );
		}
	}

	internal readonly struct FrameScope : IDisposable
	{
		private readonly EditorAudioDiagnostics _owner;
		private readonly double _start;
		public FrameScope( EditorAudioDiagnostics owner, double start ) { _owner = owner; _start = start; }
		public void Dispose() { if ( _owner is not null ) _owner._previousWork = Now - _start; }
	}

	private struct SoundSnapshot
	{
		public bool Valid, Paused, Playing;
		public float Cursor, Volume, Pitch, Amplitude, MixerVolume, MasterVolume;
		public bool AudibleCandidate => Valid && Playing && !Paused && Volume > 0 && MixerVolume > 0 && MasterVolume > 0;
		// Do not dereference SoundFile.Duration here: the managed SoundFile can survive without
		// a native VSound resource, even when this playback handle is valid (runtime-decoded music).
		public static SoundSnapshot Read( SoundHandle handle ) => handle is null || !handle.IsValid ? default : new()
		{
			Valid = handle.IsValid, Paused = handle.Paused, Playing = handle.IsPlaying,
			Cursor = handle.Time, Volume = handle.Volume, Pitch = handle.Pitch, Amplitude = handle.Amplitude,
			MixerVolume = handle.TargetMixer?.Volume ?? 1, MasterVolume = Sound.MasterVolume
		};
		public override string ToString() => $"valid={Valid} playing={Playing} paused={Paused} t={Cursor:0.000}s " +
			$"pitch={Pitch:0.00} vol={Volume:0.000} mixer={MixerVolume:0.00} master={MasterVolume:0.00} amp={Amplitude:0.00000}";
	}

	/// <summary>Read existing engine counters; do not install scopes, enumerate histories or allocate
	/// in the healthy-frame path. Peaks preserve a short spike between the half-second samples.</summary>
	private struct PhaseSnapshot
	{
		public float Async, Ui, Audio, Editor, Render, Update, Idle, Network, Gpu;
		public static PhaseSnapshot Read() => new()
		{
			Async = PerformanceStats.Timings.Async.GetMetric( 1 ).Max,
			Ui = PerformanceStats.Timings.Ui.GetMetric( 1 ).Max,
			Audio = PerformanceStats.Timings.Audio.GetMetric( 1 ).Max,
			Editor = PerformanceStats.Timings.Editor.GetMetric( 1 ).Max,
			Render = PerformanceStats.Timings.Render.GetMetric( 1 ).Max,
			Update = PerformanceStats.Timings.Update.GetMetric( 1 ).Max,
			Idle = PerformanceStats.Timings.Idle.GetMetric( 1 ).Max,
			Network = PerformanceStats.Timings.Network.GetMetric( 1 ).Max,
			Gpu = PerformanceStats.GpuFrametime
		};
		public void Include( PhaseSnapshot other )
		{
			Async = Math.Max( Async, other.Async );
			Ui = Math.Max( Ui, other.Ui );
			Audio = Math.Max( Audio, other.Audio );
			Editor = Math.Max( Editor, other.Editor );
			Render = Math.Max( Render, other.Render );
			Update = Math.Max( Update, other.Update );
			Idle = Math.Max( Idle, other.Idle );
			Network = Math.Max( Network, other.Network );
			Gpu = Math.Max( Gpu, other.Gpu );
		}
		public override string ToString() => $"async={Async:0.0} ui={Ui:0.0} audio={Audio:0.0} editor={Editor:0.0} " +
			$"render={Render:0.0} update={Update:0.0} idle={Idle:0.0} network={Network:0.0} gpu={Gpu:0.0}";
	}

	private struct Snapshot
	{
		public double Seconds, Gap, Work, EngineFrame, MaxGap, MaxWork, MusicStill, ToneStill;
		public string Stage, Path;
		public bool Focused;
		public SoundSnapshot Music, Tone;
		public PhaseSnapshot Phases, PhasePeaks;
		public EditorUiActivity.State Ui;
		public long Bytes, GcTicks;
		public int Gen0, Gen1, Gen2, Exceptions;
		public double WindowSeconds;
		public int Frames, FocusedFrames;
		public string Describe() => $"+{Seconds:0.000}s stage={Stage} focused={Focused} " +
			$"window={WindowSeconds:0.000}s frames={Frames} focusedFrames={FocusedFrames} " +
			$"fps={(WindowSeconds > 0 ? Frames / WindowSeconds : 0):0.0} allocBPerFrame={(Frames > 0 ? Bytes / (double)Frames : 0):0.0} " +
			$"gap={Gap * 1000:0}ms work={Work * 1000:0}ms engineFrame={EngineFrame * 1000:0}ms " +
			$"maxGap={MaxGap * 1000:0}ms maxWork={MaxWork * 1000:0}ms " +
			$"alloc={Bytes / 1024.0:0}KiB gc={Gen0}/{Gen1}/{Gen2} gcPause={GcTicks / 10000.0:0.00}ms exceptions={Exceptions} " +
			$"engineLastMs=[{Phases}] enginePeakMs=[{PhasePeaks}] " +
			$"music='{Path ?? "none"}' [{Music}] still={MusicStill:0.00}s PCM=[{Tone}] still={ToneStill:0.00}s " + Ui.Describe( Seconds );
	}
}