Permanent frame profiler: FrameBoundary() at the top of OnRender measures CPU frame time (swap-to-swap delta), brackets the frame in a GpuFrameTimer TimeElapsed query (self-disabled under ACDREAM_WB_DIAG=1), and samples per-frame allocated bytes + GC collection deltas. BeginStage(FrameStage) scopes attribute CPU time to Update/Upload/ImGui. Emits one [frame-prof] report line every ~5s while RenderingDiagnostics.FrameProfEnabled is on; zero-cost stage scopes when off. Report formatting is a pure static method, unit-tested for invariant-culture formatting and the gpu=off fallback text. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
197 lines
8.1 KiB
C#
197 lines
8.1 KiB
C#
using System;
|
|
using System.Diagnostics;
|
|
using System.Globalization;
|
|
using System.Text;
|
|
using AcDream.Core.Rendering;
|
|
using Silk.NET.OpenGL;
|
|
|
|
namespace AcDream.App.Diagnostics;
|
|
|
|
/// <summary>Stage indices for per-frame CPU attribution.</summary>
|
|
public enum FrameStage
|
|
{
|
|
/// <summary>Whole OnUpdate body (simulation + streaming apply).</summary>
|
|
Update = 0,
|
|
/// <summary>WbMeshAdapter.Tick — staged mesh/texture GPU upload drain.</summary>
|
|
Upload = 1,
|
|
/// <summary>ImGui Render (dev overlay).</summary>
|
|
ImGui = 2,
|
|
}
|
|
|
|
/// <summary>
|
|
/// MP0 (2026-07-05) — the permanent honest frame profiler. One
|
|
/// <c>FrameBoundary</c> call at the top of <c>GameWindow.OnRender</c>
|
|
/// measures CPU frame time as the delta between consecutive boundaries
|
|
/// (captures the FULL frame including present), brackets the frame in a
|
|
/// GPU <c>TimeElapsed</c> query (via <see cref="GpuFrameTimer"/>), and
|
|
/// samples per-frame allocated bytes + GC collection counts. Stage scopes
|
|
/// (<see cref="BeginStage"/>) attribute CPU time to Update / Upload /
|
|
/// ImGui. Emits one <c>[frame-prof]</c> line every ~5 s while
|
|
/// <see cref="RenderingDiagnostics.FrameProfEnabled"/> is true; costs one
|
|
/// bool check per frame when off.
|
|
///
|
|
/// <para>Permanent apparatus — every MP-track gate reads it; do not strip.
|
|
/// Whole-frame GPU timing self-disables under <c>ACDREAM_WB_DIAG=1</c>
|
|
/// (nested TimeElapsed is illegal GL; see GpuFrameTimer).</para>
|
|
/// Spec: docs/superpowers/specs/2026-07-05-modern-pipeline-design.md §5.
|
|
/// </summary>
|
|
public sealed class FrameProfiler : IDisposable
|
|
{
|
|
private const int WindowCapacity = 2048; // ~12 s at 165 fps
|
|
private const long ReportIntervalTicks = 5 * TimeSpan.TicksPerSecond;
|
|
private static readonly int StageCount = Enum.GetValues<FrameStage>().Length;
|
|
|
|
private readonly FrameStatsBuffer _cpuUs = new(WindowCapacity);
|
|
private readonly FrameStatsBuffer _gpuUs = new(WindowCapacity);
|
|
private readonly FrameStatsBuffer _allocBytes = new(WindowCapacity);
|
|
private readonly FrameStatsBuffer[] _stageUs;
|
|
private readonly long[] _stageAccumTicks;
|
|
private readonly bool _wbDiagActive =
|
|
Environment.GetEnvironmentVariable("ACDREAM_WB_DIAG") == "1";
|
|
|
|
private GpuFrameTimer? _gpuTimer;
|
|
private long _lastBoundaryTimestamp;
|
|
private long _lastAllocBytes;
|
|
private long _lastReportTicks;
|
|
private int _gc0Base, _gc1Base, _gc2Base;
|
|
private int _framesInWindow;
|
|
private int _ownerThreadId;
|
|
private bool _threadWarned;
|
|
private bool _wbDiagNoticePrinted;
|
|
private bool _wasEnabled;
|
|
|
|
public FrameProfiler()
|
|
{
|
|
_stageUs = new FrameStatsBuffer[StageCount];
|
|
for (int i = 0; i < StageCount; i++) _stageUs[i] = new FrameStatsBuffer(WindowCapacity);
|
|
_stageAccumTicks = new long[StageCount];
|
|
}
|
|
|
|
/// <summary>
|
|
/// Call as the FIRST statement of <c>GameWindow.OnRender</c>.
|
|
/// </summary>
|
|
public void FrameBoundary(GL gl)
|
|
{
|
|
bool enabled = RenderingDiagnostics.FrameProfEnabled;
|
|
if (!enabled)
|
|
{
|
|
if (_wasEnabled) { _gpuTimer?.Stop(); _wasEnabled = false; _lastBoundaryTimestamp = 0; }
|
|
return;
|
|
}
|
|
|
|
if (_ownerThreadId == 0) _ownerThreadId = Environment.CurrentManagedThreadId;
|
|
else if (!_threadWarned && _ownerThreadId != Environment.CurrentManagedThreadId)
|
|
{
|
|
_threadWarned = true;
|
|
Console.WriteLine("[frame-prof] WARNING: frame boundary crossed threads; alloc counter is per-thread and now unreliable");
|
|
}
|
|
|
|
long now = Stopwatch.GetTimestamp();
|
|
long allocNow = GC.GetAllocatedBytesForCurrentThread();
|
|
|
|
if (!_wasEnabled)
|
|
{
|
|
// First enabled frame (startup or runtime toggle-on): establish
|
|
// baselines, emit nothing.
|
|
_wasEnabled = true;
|
|
_lastReportTicks = DateTime.UtcNow.Ticks;
|
|
_gc0Base = GC.CollectionCount(0); _gc1Base = GC.CollectionCount(1); _gc2Base = GC.CollectionCount(2);
|
|
if (_gpuTimer is null && !_wbDiagActive) _gpuTimer = new GpuFrameTimer(gl);
|
|
if (_wbDiagActive && !_wbDiagNoticePrinted)
|
|
{
|
|
_wbDiagNoticePrinted = true;
|
|
Console.WriteLine("[frame-prof] GPU frame timing OFF: ACDREAM_WB_DIAG=1 owns TimeElapsed queries (nested queries are illegal GL)");
|
|
}
|
|
}
|
|
else
|
|
{
|
|
long cpuUs = (now - _lastBoundaryTimestamp) * 1_000_000L / Stopwatch.Frequency;
|
|
_cpuUs.Push(cpuUs);
|
|
_allocBytes.Push(allocNow - _lastAllocBytes);
|
|
for (int i = 0; i < StageCount; i++)
|
|
{
|
|
_stageUs[i].Push(_stageAccumTicks[i] * 1_000_000L / Stopwatch.Frequency);
|
|
_stageAccumTicks[i] = 0;
|
|
}
|
|
_framesInWindow++;
|
|
}
|
|
|
|
_lastBoundaryTimestamp = now;
|
|
_lastAllocBytes = allocNow;
|
|
|
|
if (_gpuTimer?.FrameBoundary() is long gpuUs)
|
|
_gpuUs.Push(gpuUs);
|
|
|
|
long nowTicks = DateTime.UtcNow.Ticks;
|
|
if (nowTicks - _lastReportTicks >= ReportIntervalTicks && _framesInWindow > 0)
|
|
{
|
|
int gc0 = GC.CollectionCount(0) - _gc0Base;
|
|
int gc1 = GC.CollectionCount(1) - _gc1Base;
|
|
int gc2 = GC.CollectionCount(2) - _gc2Base;
|
|
Console.WriteLine(FormatReport(_framesInWindow, _cpuUs, _gpuUs,
|
|
gpuActive: _gpuTimer is not null, _allocBytes, gc0, gc1, gc2, _stageUs));
|
|
_lastReportTicks = nowTicks;
|
|
_gc0Base += gc0; _gc1Base += gc1; _gc2Base += gc2;
|
|
_framesInWindow = 0;
|
|
_cpuUs.Reset(); _gpuUs.Reset(); _allocBytes.Reset();
|
|
for (int i = 0; i < StageCount; i++) _stageUs[i].Reset();
|
|
}
|
|
}
|
|
|
|
/// <summary>
|
|
/// Attribute the enclosed CPU time to <paramref name="stage"/>.
|
|
/// Usage: <c>using var _ = profiler.BeginStage(FrameStage.Update);</c>.
|
|
/// Zero-cost (default scope) when the profiler is off.
|
|
/// </summary>
|
|
public StageScope BeginStage(FrameStage stage)
|
|
=> RenderingDiagnostics.FrameProfEnabled
|
|
? new StageScope(this, stage, Stopwatch.GetTimestamp())
|
|
: default;
|
|
|
|
internal void EndStage(FrameStage stage, long startTimestamp)
|
|
=> _stageAccumTicks[(int)stage] += Stopwatch.GetTimestamp() - startTimestamp;
|
|
|
|
/// <summary>Pure report formatter — unit-tested; invariant culture.</summary>
|
|
public static string FormatReport(
|
|
int frameCount,
|
|
FrameStatsBuffer cpu, FrameStatsBuffer gpu, bool gpuActive,
|
|
FrameStatsBuffer alloc, int gc0, int gc1, int gc2,
|
|
FrameStatsBuffer[] stages)
|
|
{
|
|
var ci = CultureInfo.InvariantCulture;
|
|
var sb = new StringBuilder(256);
|
|
sb.Append("[frame-prof] n=").Append(frameCount);
|
|
sb.AppendFormat(ci, " | cpu_ms p50={0:0.0} p95={1:0.0} p99={2:0.0} max={3:0.0}",
|
|
cpu.Percentile(0.50) / 1000.0, cpu.Percentile(0.95) / 1000.0,
|
|
cpu.Percentile(0.99) / 1000.0, cpu.Max() / 1000.0);
|
|
if (gpuActive)
|
|
sb.AppendFormat(ci, " | gpu_ms p50={0:0.0} p95={1:0.0}",
|
|
gpu.Percentile(0.50) / 1000.0, gpu.Percentile(0.95) / 1000.0);
|
|
else
|
|
sb.Append(" | gpu=off(wbdiag)");
|
|
sb.AppendFormat(ci, " | alloc_kb p50={0:0.0} max={1:0.0} gc={2}/{3}/{4}",
|
|
alloc.Percentile(0.50) / 1024.0, alloc.Max() / 1024.0, gc0, gc1, gc2);
|
|
string[] names = { "upd", "upl", "imgui" };
|
|
for (int i = 0; i < stages.Length && i < names.Length; i++)
|
|
sb.AppendFormat(ci, " | {0} p50={1:0.0} p95={2:0.0}",
|
|
names[i], stages[i].Percentile(0.50) / 1000.0, stages[i].Percentile(0.95) / 1000.0);
|
|
return sb.ToString();
|
|
}
|
|
|
|
public void Dispose() => _gpuTimer?.Dispose();
|
|
}
|
|
|
|
/// <summary>Disposable stage scope; default instance is a no-op.</summary>
|
|
public readonly struct StageScope : IDisposable
|
|
{
|
|
private readonly FrameProfiler? _owner;
|
|
private readonly FrameStage _stage;
|
|
private readonly long _start;
|
|
|
|
internal StageScope(FrameProfiler owner, FrameStage stage, long start)
|
|
{
|
|
_owner = owner; _stage = stage; _start = start;
|
|
}
|
|
|
|
public void Dispose() => _owner?.EndStage(_stage, _start);
|
|
}
|