From 73bb8777a911fa0b79ab4378430382713f8457d6 Mon Sep 17 00:00:00 2001 From: Erik Date: Sun, 5 Jul 2026 19:11:25 +0200 Subject: [PATCH] feat(pipeline): MP0 - FrameProfiler facade (CPU/GPU/alloc/stages, 5s report) 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 --- src/AcDream.App/Diagnostics/FrameProfiler.cs | 197 ++++++++++++++++++ .../FrameProfilerReportTests.cs | 48 +++++ 2 files changed, 245 insertions(+) create mode 100644 src/AcDream.App/Diagnostics/FrameProfiler.cs create mode 100644 tests/AcDream.App.Tests/FrameProfilerReportTests.cs diff --git a/src/AcDream.App/Diagnostics/FrameProfiler.cs b/src/AcDream.App/Diagnostics/FrameProfiler.cs new file mode 100644 index 00000000..dd01f9a1 --- /dev/null +++ b/src/AcDream.App/Diagnostics/FrameProfiler.cs @@ -0,0 +1,197 @@ +using System; +using System.Diagnostics; +using System.Globalization; +using System.Text; +using AcDream.Core.Rendering; +using Silk.NET.OpenGL; + +namespace AcDream.App.Diagnostics; + +/// Stage indices for per-frame CPU attribution. +public enum FrameStage +{ + /// Whole OnUpdate body (simulation + streaming apply). + Update = 0, + /// WbMeshAdapter.Tick — staged mesh/texture GPU upload drain. + Upload = 1, + /// ImGui Render (dev overlay). + ImGui = 2, +} + +/// +/// MP0 (2026-07-05) — the permanent honest frame profiler. One +/// FrameBoundary call at the top of GameWindow.OnRender +/// measures CPU frame time as the delta between consecutive boundaries +/// (captures the FULL frame including present), brackets the frame in a +/// GPU TimeElapsed query (via ), and +/// samples per-frame allocated bytes + GC collection counts. Stage scopes +/// () attribute CPU time to Update / Upload / +/// ImGui. Emits one [frame-prof] line every ~5 s while +/// is true; costs one +/// bool check per frame when off. +/// +/// Permanent apparatus — every MP-track gate reads it; do not strip. +/// Whole-frame GPU timing self-disables under ACDREAM_WB_DIAG=1 +/// (nested TimeElapsed is illegal GL; see GpuFrameTimer). +/// Spec: docs/superpowers/specs/2026-07-05-modern-pipeline-design.md §5. +/// +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().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]; + } + + /// + /// Call as the FIRST statement of GameWindow.OnRender. + /// + 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(); + } + } + + /// + /// Attribute the enclosed CPU time to . + /// Usage: using var _ = profiler.BeginStage(FrameStage.Update);. + /// Zero-cost (default scope) when the profiler is off. + /// + 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; + + /// Pure report formatter — unit-tested; invariant culture. + 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(); +} + +/// Disposable stage scope; default instance is a no-op. +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); +} diff --git a/tests/AcDream.App.Tests/FrameProfilerReportTests.cs b/tests/AcDream.App.Tests/FrameProfilerReportTests.cs new file mode 100644 index 00000000..e451f576 --- /dev/null +++ b/tests/AcDream.App.Tests/FrameProfilerReportTests.cs @@ -0,0 +1,48 @@ +using AcDream.App.Diagnostics; +using Xunit; + +namespace AcDream.App.Tests; + +public class FrameProfilerReportTests +{ + [Fact] + public void FormatReport_IsInvariantAndComplete() + { + var cpu = new FrameStatsBuffer(16); + var gpu = new FrameStatsBuffer(16); + var alloc = new FrameStatsBuffer(16); + var stages = new[] { new FrameStatsBuffer(16), new FrameStatsBuffer(16), new FrameStatsBuffer(16) }; + for (long i = 1; i <= 10; i++) + { + cpu.Push(i * 1000); // 1..10 ms in µs + gpu.Push(i * 100); + alloc.Push(i * 1024); // bytes + stages[0].Push(i * 200); + stages[1].Push(i * 50); + stages[2].Push(i * 10); + } + + string line = FrameProfiler.FormatReport( + frameCount: 10, cpu: cpu, gpu: gpu, gpuActive: true, + alloc: alloc, gc0: 3, gc1: 1, gc2: 0, stages: stages); + + Assert.StartsWith("[frame-prof]", line); + Assert.Contains("n=10", line); + Assert.Contains("cpu_ms p50=5.0 p95=10.0 p99=10.0 max=10.0", line); + Assert.Contains("gpu_ms p50=0.5", line); + Assert.Contains("alloc_kb p50=5.0 max=10.0", line); + Assert.Contains("gc=3/1/0", line); + Assert.Contains("upd p50=1.0", line); // stage 0: 200µs·5 = 1.0 ms + } + + [Fact] + public void FormatReport_GpuInactive_SaysWhy() + { + var empty = new FrameStatsBuffer(4); + string line = FrameProfiler.FormatReport( + frameCount: 0, cpu: empty, gpu: empty, gpuActive: false, + alloc: empty, gc0: 0, gc1: 0, gc2: 0, + stages: new[] { empty, empty, empty }); + Assert.Contains("gpu=off(wbdiag)", line); + } +}