From 2757dda63a24ee1b8213f5619b29b4e840fd253e Mon Sep 17 00:00:00 2001 From: Erik Date: Sun, 5 Jul 2026 19:03:59 +0200 Subject: [PATCH] docs(pipeline): MP0 implementation plan - frame profiler + baseline capture Five bite-sized tasks: FrameStatsBuffer (TDD), FrameProfEnabled flag + GpuFrameTimer TimeElapsed ring, FrameProfiler facade (TDD on the report formatter), GameWindow wiring (one boundary call + three stage scopes) with DebugPanel mirror, and the user-driven baseline capture that gates MP1. Records two spec deviations: GPU per-stage timestamps deferred (frame is CPU-bound at ~0.5ms GPU), and the toggle lives in RenderingDiagnostics per the diagnostic-owner rule, not RuntimeOptions. Encodes the discovered GL constraint: whole-frame TimeElapsed is mutually exclusive with ACDREAM_WB_DIAG per-pass queries. Co-Authored-By: Claude Fable 5 --- .../plans/2026-07-05-mp0-frame-profiler.md | 754 ++++++++++++++++++ 1 file changed, 754 insertions(+) create mode 100644 docs/superpowers/plans/2026-07-05-mp0-frame-profiler.md diff --git a/docs/superpowers/plans/2026-07-05-mp0-frame-profiler.md b/docs/superpowers/plans/2026-07-05-mp0-frame-profiler.md new file mode 100644 index 00000000..12f4dea3 --- /dev/null +++ b/docs/superpowers/plans/2026-07-05-mp0-frame-profiler.md @@ -0,0 +1,754 @@ +# MP0 — Honest Frame Profiler + Baseline Capture Implementation Plan + +> **For agentic workers:** REQUIRED SUB-SKILL: Use superpowers:subagent-driven-development (recommended) or superpowers:executing-plans to implement this plan task-by-task. Steps use checkbox (`- [ ]`) syntax for tracking. + +**Goal:** Build the permanent frame profiler (CPU frame time, GPU frame time, per-stage CPU attribution, per-frame allocation) and capture the MP baseline report that gates the rest of the Modern Pipeline track. + +**Architecture:** A pure, unit-testable stats core (`FrameStatsBuffer`) + a GL query wrapper (`GpuFrameTimer`) + a facade (`FrameProfiler`) wired into `GameWindow` at exactly one frame-boundary call plus three stage scopes. Toggle lives in `RenderingDiagnostics` (the established diagnostic-owner pattern), mirrored in the DebugPanel. Spec: `docs/superpowers/specs/2026-07-05-modern-pipeline-design.md` §5. + +**Tech Stack:** .NET 10, Silk.NET OpenGL (`QueryTarget.TimeElapsed` ring, mirroring `WbDrawDispatcher`'s existing idiom), xunit in `tests/AcDream.App.Tests`. + +**Spec deviations (recorded):** +1. Spec §5 lists per-stage GPU attribution via `glQueryCounter` (GL_TIMESTAMP) markers. Deferred: the measured GPU total is ~0.5 ms (the frame is CPU-bound), so MP0 ships per-stage **CPU** attribution + whole-frame GPU only. GPU timestamps get added in the MP phase whose gate first needs GPU-side attribution (likely MP3). +2. The spec says "Toggles via `RuntimeOptions` + DebugPanel". `RuntimeOptions`' own doc comment says runtime diagnostic toggles belong in diagnostic owner classes, NOT RuntimeOptions ([RuntimeOptions.cs:13-19](../../src/AcDream.App/RuntimeOptions.cs)). We follow the codebase rule: the flag goes in `RenderingDiagnostics` (env-seeded, runtime-toggleable). No RuntimeOptions change. + +**Hard GL constraint (discovered during planning):** GL forbids two simultaneously active `TimeElapsed` queries. `WbDrawDispatcher` already brackets its opaque/transparent passes with `TimeElapsed` queries when `ACDREAM_WB_DIAG=1` ([WbDrawDispatcher.cs:1642](../../src/AcDream.App/Rendering/Wb/WbDrawDispatcher.cs)). Therefore the profiler's whole-frame GPU query is **disabled (with a one-time console notice) when `ACDREAM_WB_DIAG=1`**. This is also the 2026-06-23 measurement lesson (separate flags for whole-frame vs per-pass) enforced in code. + +**Threading assumption:** Silk.NET drives `OnUpdate` and `OnRender` on the same loop thread in this app. `FrameProfiler` captures the first caller's managed thread id and emits a one-time warning if any later call arrives on a different thread (guards the `GC.GetAllocatedBytesForCurrentThread` validity). + +--- + +## File map + +| File | Action | Responsibility | +|---|---|---| +| `src/AcDream.App/Diagnostics/FrameStatsBuffer.cs` | Create | Pure ring-buffer stats: samples, percentiles, stage accumulators, report line. Zero GL, zero statics. | +| `src/AcDream.App/Diagnostics/GpuFrameTimer.cs` | Create | GL `TimeElapsed` query ring (depth 4, `Begun` flags per the #125 lesson). | +| `src/AcDream.App/Diagnostics/FrameProfiler.cs` | Create | Facade: frame boundary, stage scopes, GC counters, 5-second `[frame-prof]` report. | +| `src/AcDream.Core/Rendering/RenderingDiagnostics.cs` | Modify | Add `FrameProfEnabled` flag (env `ACDREAM_FRAME_PROF`). | +| `src/AcDream.App/Rendering/GameWindow.cs` | Modify | One field + one call at `OnRender` top (~:8757), stage scope around `_wbMeshAdapter?.Tick()` (~:8813), around `_imguiBootstrap.Render()` (~:9821), and at `OnUpdate` top (~:7952). Wiring only — no logic in GameWindow. | +| `src/AcDream.UI.Abstractions/Panels/Debug/DebugVM.cs` | Modify | `FrameProf` mirror property (copy the `ProbeResolve` pattern at :248). | +| `src/AcDream.UI.ImGui/` (renderer for DebugPanel) | Modify | Checkbox for the mirror (locate via `grep -rn "ProbeResolve" src/AcDream.UI.ImGui/`). | +| `tests/AcDream.App.Tests/FrameStatsBufferTests.cs` | Create | Percentiles, ring wrap, stage reset, report format. | +| `docs/research/2026-07-XX-mp0-baseline.md` | Create (Task 5) | The baseline report — MP0's deliverable. | + +Line numbers drift; match by the quoted anchor code, not the number. + +--- + +### Task 1: FrameStatsBuffer (pure stats core, TDD) + +**Files:** +- Create: `src/AcDream.App/Diagnostics/FrameStatsBuffer.cs` +- Test: `tests/AcDream.App.Tests/FrameStatsBufferTests.cs` + +- [ ] **Step 1: Write the failing tests** + +```csharp +using AcDream.App.Diagnostics; +using Xunit; + +namespace AcDream.App.Tests; + +public class FrameStatsBufferTests +{ + [Fact] + public void Percentiles_OnKnownDistribution_AreExact() + { + var buf = new FrameStatsBuffer(capacity: 100); + // 1..100 µs — p50 = 50, p95 = 95, p99 = 99, max = 100. + for (long i = 1; i <= 100; i++) buf.Push(i); + + Assert.Equal(50, buf.Percentile(0.50)); + Assert.Equal(95, buf.Percentile(0.95)); + Assert.Equal(99, buf.Percentile(0.99)); + Assert.Equal(100, buf.Max()); + } + + [Fact] + public void Push_PastCapacity_KeepsOnlyNewestWindow() + { + var buf = new FrameStatsBuffer(capacity: 4); + foreach (long v in new long[] { 1000, 1000, 1000, 1000, 1, 2, 3, 4 }) + buf.Push(v); + // The four 1000s were overwritten; window is {1,2,3,4}. + Assert.Equal(4, buf.Count); + Assert.Equal(4, buf.Max()); + Assert.Equal(2, buf.Percentile(0.50)); + } + + [Fact] + public void Percentile_Empty_ReturnsZero() + { + var buf = new FrameStatsBuffer(capacity: 8); + Assert.Equal(0, buf.Percentile(0.95)); + Assert.Equal(0, buf.Max()); + Assert.Equal(0, buf.Count); + } + + [Fact] + public void Reset_ClearsWindow() + { + var buf = new FrameStatsBuffer(capacity: 8); + buf.Push(5); buf.Push(7); + buf.Reset(); + Assert.Equal(0, buf.Count); + Assert.Equal(0, buf.Percentile(0.5)); + } +} +``` + +- [ ] **Step 2: Run tests to verify they fail** + +Run: `dotnet test tests/AcDream.App.Tests --filter FrameStatsBufferTests -v minimal` +Expected: FAIL — `FrameStatsBuffer` does not exist (compile error). + +- [ ] **Step 3: Implement FrameStatsBuffer** + +```csharp +using System; + +namespace AcDream.App.Diagnostics; + +/// +/// MP0 (2026-07-05) — fixed-capacity ring buffer of long samples +/// (microseconds or bytes) with percentile/max over the current window. +/// Pure and allocation-free after construction: +/// sorts into a preallocated scratch array, so the 5-second report path +/// allocates nothing. Not thread-safe — owned by the window loop thread. +/// Spec: docs/superpowers/specs/2026-07-05-modern-pipeline-design.md §5. +/// +public sealed class FrameStatsBuffer +{ + private readonly long[] _samples; + private readonly long[] _scratch; + private int _cursor; + private int _count; + + public FrameStatsBuffer(int capacity) + { + if (capacity <= 0) throw new ArgumentOutOfRangeException(nameof(capacity)); + _samples = new long[capacity]; + _scratch = new long[capacity]; + } + + public int Count => _count; + + public void Push(long value) + { + _samples[_cursor] = value; + _cursor = (_cursor + 1) % _samples.Length; + if (_count < _samples.Length) _count++; + } + + public void Reset() + { + _cursor = 0; + _count = 0; + } + + /// + /// Nearest-rank percentile over the current window: element at + /// ceil(q·n) in the ascending sort (1-based), 0 when empty. + /// + public long Percentile(double q) + { + if (_count == 0) return 0; + Array.Copy(_samples, _scratch, _count); + Array.Sort(_scratch, 0, _count); + int rank = (int)Math.Ceiling(q * _count); // 1-based nearest rank + if (rank < 1) rank = 1; + if (rank > _count) rank = _count; + return _scratch[rank - 1]; + } + + public long Max() + { + long max = 0; + for (int i = 0; i < _count; i++) + if (_samples[i] > max) max = _samples[i]; + return max; + } +} +``` + +- [ ] **Step 4: Run tests to verify they pass** + +Run: `dotnet test tests/AcDream.App.Tests --filter FrameStatsBufferTests -v minimal` +Expected: 4 passed. + +- [ ] **Step 5: Commit** + +```bash +git add src/AcDream.App/Diagnostics/FrameStatsBuffer.cs tests/AcDream.App.Tests/FrameStatsBufferTests.cs +git commit -m "feat(pipeline): MP0 - FrameStatsBuffer ring/percentile core" +``` + +--- + +### Task 2: RenderingDiagnostics flag + GpuFrameTimer + +**Files:** +- Modify: `src/AcDream.Core/Rendering/RenderingDiagnostics.cs` (append inside the class, before the closing brace) +- Create: `src/AcDream.App/Diagnostics/GpuFrameTimer.cs` + +- [ ] **Step 1: Add the flag to RenderingDiagnostics** + +Append inside `public static class RenderingDiagnostics` (after `ShouldRenderIndoor`, before the final `}`): + +```csharp + /// + /// MP0 (2026-07-05) — master toggle for the permanent frame profiler + /// (AcDream.App.Diagnostics.FrameProfiler): CPU frame time + /// (swap-to-swap), whole-frame GPU time, per-stage CPU attribution, + /// per-frame allocation counters, reported as one [frame-prof] + /// line every ~5 s. Permanent apparatus (every MP-track gate reads it) — + /// do NOT strip with session probes. The whole-frame GPU query is + /// self-disabled while ACDREAM_WB_DIAG=1 (GL forbids nested + /// TimeElapsed queries; WbDrawDispatcher owns per-pass queries under + /// that flag — the 2026-06-23 "separate flags" measurement lesson). + /// Initial state from ACDREAM_FRAME_PROF=1; runtime-toggleable + /// via the DebugPanel mirror (DebugVM.FrameProf). + /// Spec: docs/superpowers/specs/2026-07-05-modern-pipeline-design.md §5. + /// + public static bool FrameProfEnabled { get; set; } = + Environment.GetEnvironmentVariable("ACDREAM_FRAME_PROF") == "1"; +``` + +- [ ] **Step 2: Create GpuFrameTimer** + +```csharp +using System; +using Silk.NET.OpenGL; + +namespace AcDream.App.Diagnostics; + +/// +/// MP0 (2026-07-05) — whole-frame GPU time via a ring of +/// queries (depth 4, so results are +/// read ~3 frames late and never stall). Mirrors WbDrawDispatcher's query +/// idiom including the #125 lesson: a glGenQueries name is not a query +/// OBJECT until first glBeginQuery, so never-begun slots are skipped via +/// the Begun flags. +/// +/// MUST NOT be active while ACDREAM_WB_DIAG=1: GL forbids two +/// simultaneously active TimeElapsed queries and WbDrawDispatcher brackets +/// its passes with them under that flag. The caller (FrameProfiler) +/// enforces the exclusion; this class just does the ring. +/// +internal sealed class GpuFrameTimer : IDisposable +{ + private const int RingDepth = 4; + + private readonly GL _gl; + private readonly uint[] _queries = new uint[RingDepth]; + private readonly bool[] _begun = new bool[RingDepth]; + private int _frameIndex; + private bool _queryActive; + + public GpuFrameTimer(GL gl) + { + _gl = gl ?? throw new ArgumentNullException(nameof(gl)); + for (int i = 0; i < RingDepth; i++) + _queries[i] = _gl.GenQuery(); + } + + /// + /// Call once per frame at the frame boundary. Ends the previous + /// frame's query, polls the oldest slot non-blocking, begins this + /// frame's query. Returns the completed GPU time in microseconds for + /// a ~RingDepth-frames-old frame, or null when no result is ready. + /// + public long? FrameBoundary() + { + if (_queryActive) + { + _gl.EndQuery(QueryTarget.TimeElapsed); + _queryActive = false; + } + + long? completedUs = null; + int readSlot = _frameIndex % RingDepth; // about to be reused — oldest + if (_begun[readSlot]) + { + _gl.GetQueryObject(_queries[readSlot], QueryObjectParameterName.ResultAvailable, out int avail); + if (avail != 0) + { + _gl.GetQueryObject(_queries[readSlot], QueryObjectParameterName.Result, out ulong ns); + completedUs = (long)(ns / 1000UL); + } + // Not available ⇒ sample silently dropped (same policy as + // WbDrawDispatcher) — percentiles tolerate missing samples. + } + + _gl.BeginQuery(QueryTarget.TimeElapsed, _queries[readSlot]); + _begun[readSlot] = true; + _queryActive = true; + _frameIndex++; + return completedUs; + } + + /// End any active query without beginning a new one (used when the profiler is toggled off mid-session). + public void Stop() + { + if (_queryActive) + { + _gl.EndQuery(QueryTarget.TimeElapsed); + _queryActive = false; + } + } + + public void Dispose() + { + Stop(); + for (int i = 0; i < RingDepth; i++) + _gl.DeleteQuery(_queries[i]); + } +} +``` + +Note: `_gl.GenQuery()` / `_gl.DeleteQuery(uint)` are the Silk.NET single-name helpers; if this overload doesn't resolve on the project's Silk.NET version, use the array forms exactly as `WbDrawDispatcher` does (`grep -n "GenQueries" src/AcDream.App/Rendering/Wb/WbDrawDispatcher.cs`) and copy that call shape. + +- [ ] **Step 3: Build** + +Run: `dotnet build` +Expected: green (no tests possible for the GL class headless; correctness rides on the copied WbDrawDispatcher idiom + Task 5's live run). + +- [ ] **Step 4: Commit** + +```bash +git add src/AcDream.Core/Rendering/RenderingDiagnostics.cs src/AcDream.App/Diagnostics/GpuFrameTimer.cs +git commit -m "feat(pipeline): MP0 - FrameProfEnabled flag + GPU TimeElapsed ring" +``` + +--- + +### Task 3: FrameProfiler facade + +**Files:** +- Create: `src/AcDream.App/Diagnostics/FrameProfiler.cs` +- Test: `tests/AcDream.App.Tests/FrameProfilerReportTests.cs` + +- [ ] **Step 1: Write the failing test (report formatting is the testable part)** + +```csharp +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 + Assert.DoesNotContain(",0", line.Replace("gc=3/1/0", "")); // no comma decimals (invariant culture) + } + + [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); + } +} +``` + +- [ ] **Step 2: Run tests to verify they fail** + +Run: `dotnet test tests/AcDream.App.Tests --filter FrameProfilerReportTests -v minimal` +Expected: FAIL — `FrameProfiler` does not exist. + +- [ ] **Step 3: Implement FrameProfiler** + +```csharp +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); +} +``` + +- [ ] **Step 4: Run tests to verify they pass** + +Run: `dotnet test tests/AcDream.App.Tests --filter FrameProfilerReportTests -v minimal` +Expected: 2 passed. (If the `,0` invariant assertion trips on stage names, adjust only the assertion's exclusion — the formatter must keep `CultureInfo.InvariantCulture` everywhere.) + +- [ ] **Step 5: Commit** + +```bash +git add src/AcDream.App/Diagnostics/FrameProfiler.cs tests/AcDream.App.Tests/FrameProfilerReportTests.cs +git commit -m "feat(pipeline): MP0 - FrameProfiler facade (CPU/GPU/alloc/stages, 5s report)" +``` + +--- + +### Task 4: GameWindow wiring + DebugPanel mirror + +**Files:** +- Modify: `src/AcDream.App/Rendering/GameWindow.cs` +- Modify: `src/AcDream.UI.Abstractions/Panels/Debug/DebugVM.cs` +- Modify: the DebugPanel ImGui renderer (locate in step 4) + +- [ ] **Step 1: Add the field and frame-boundary call** + +Near GameWindow's other diagnostic fields (search for `_frameDiag` field declaration to co-locate): + +```csharp + // MP0 (2026-07-05): permanent frame profiler — one FrameBoundary call + // per OnRender + three stage scopes. All logic lives in + // AcDream.App.Diagnostics.FrameProfiler (structure rule 1). + private readonly AcDream.App.Diagnostics.FrameProfiler _frameProfiler = new(); +``` + +At the very top of `OnRender` (anchor: `private void OnRender(double deltaSeconds)` ~line 8756 — the call goes BEFORE the `var kf = WorldTime.CurrentSky;` line): + +```csharp + _frameProfiler.FrameBoundary(_gl!); +``` + +In `Dispose`/`OnClosing` teardown (anchor: where `_wbMeshAdapter` is disposed — profiler goes before `_dats`): + +```csharp + _frameProfiler.Dispose(); +``` + +- [ ] **Step 2: Add the three stage scopes** + +`OnUpdate` (anchor: `private void OnUpdate(double dt)` ~line 7952) — first statement of the body: + +```csharp + using var _updStage = _frameProfiler.BeginStage(AcDream.App.Diagnostics.FrameStage.Update); +``` + +Upload drain (anchor: `_wbMeshAdapter?.Tick();` ~line 8813 — wrap it, keeping the existing `[FRAME-DIAG]` lines untouched): + +```csharp + using (var _uplStage = _frameProfiler.BeginStage(AcDream.App.Diagnostics.FrameStage.Upload)) + { + _wbMeshAdapter?.Tick(); + } +``` + +ImGui render (anchor: `_imguiBootstrap.Render();` ~line 9821): + +```csharp + using (var _imguiStage = _frameProfiler.BeginStage(AcDream.App.Diagnostics.FrameStage.ImGui)) + { + _imguiBootstrap.Render(); + } +``` + +- [ ] **Step 3: Add the DebugVM mirror** + +In `src/AcDream.UI.Abstractions/Panels/Debug/DebugVM.cs`, after the `ProbeResolve` property (~line 252), following the same pattern: + +```csharp + /// + /// Runtime mirror of RenderingDiagnostics.FrameProfEnabled + /// (env var ACDREAM_FRAME_PROF). Toggling here starts/stops the + /// [frame-prof] 5-second report live — no relaunch required. + /// + public bool FrameProf + { + get => AcDream.Core.Rendering.RenderingDiagnostics.FrameProfEnabled; + set => AcDream.Core.Rendering.RenderingDiagnostics.FrameProfEnabled = value; + } +``` + +- [ ] **Step 4: Add the DebugPanel checkbox** + +Locate the renderer: `grep -rn "ProbeResolve" src/AcDream.UI.ImGui/` — expected: one hit in the DebugPanel renderer drawing a checkbox bound to `vm.ProbeResolve`. Add an identical checkbox line for `vm.FrameProf` labeled `"Frame profiler ([frame-prof])"` adjacent to it, copying the exact checkbox idiom used there. + +- [ ] **Step 5: Build + full test suite** + +Run: `dotnet build` +Expected: green. +Run: `dotnet test` +Expected: all green (no existing test touches these paths). + +- [ ] **Step 6: Commit** + +```bash +git add src/AcDream.App/Rendering/GameWindow.cs src/AcDream.UI.Abstractions/Panels/Debug/DebugVM.cs src/AcDream.UI.ImGui/ +git commit -m "feat(pipeline): MP0 - wire FrameProfiler into GameWindow + DebugPanel toggle" +``` + +--- + +### Task 5: Baseline capture (user-driven; MP0's deliverable + gate) + +**Files:** +- Create: `docs/research/2026-07-XX-mp0-baseline.md` (use the actual capture date) + +- [ ] **Step 1: Confirm Release build is green** + +Run: `dotnet build -c Release` +Expected: green. Never launch on a red build. + +- [ ] **Step 2: Launch with the profiler on (user drives)** + +```powershell +$env:ACDREAM_DAT_DIR="$env:USERPROFILE\Documents\Asheron's Call"; $env:ACDREAM_LIVE="1" +$env:ACDREAM_TEST_HOST="127.0.0.1"; $env:ACDREAM_TEST_PORT="9000" +$env:ACDREAM_TEST_USER="testaccount"; $env:ACDREAM_TEST_PASS="testpassword" +$env:ACDREAM_FRAME_PROF="1" # NOT ACDREAM_WB_DIAG — mutually exclusive GPU timing +dotnet run --project src\AcDream.App\AcDream.App.csproj --no-build -c Release 2>&1 | Tee-Object -FilePath "mp0-baseline.log" +``` + +Launch in the background (`run_in_background: true`); the user manages the client lifecycle per CLAUDE.md. Ask the user to run this route, pausing ~30 s (≥5 report lines) in each state: +1. Dense town, standing still, facing the dense view (Holtburg center; Fort Tethana/Arwic if reachable). +2. Dense town, panning the camera continuously. +3. Walking a full town traversal (streaming active). +4. 2–3 portal hops (the hitch scenario). +5. A dungeon interior walk. + +- [ ] **Step 3: Extract the numbers** + +Run: `Select-String -Path mp0-baseline.log -Pattern "\[frame-prof\]"` +Expected: one line per 5 s. Map line timestamps/order to the route states (the user says when each state started; correlate by order). + +- [ ] **Step 4: Write the baseline report** + +Create `docs/research/2026-07-XX-mp0-baseline.md` containing, per route state: cpu_ms p50/p95/p99/max, gpu_ms p50/p95, alloc_kb p50/max, gc counts, stage split (upd/upl/imgui p50/p95) — plus: +- **The attribution verdict:** where do the ~6 dense-town CPU ms actually go (update vs upload vs imgui vs unattributed-render)? Does it confirm the spec §1 split (render-submission dominant)? +- **The gate decision (spec §5):** if attribution confirms the assumed split → proceed to MP1 planning unchanged. If it contradicts (e.g. Update dominates) → amend the spec's phase order BEFORE MP1, in the same session, and say so in this doc. +- The hitch profile: worst max/p99 during portal hops and traversal — this is MP1's "before" number. + +- [ ] **Step 5: Commit + update the spec status** + +Mark the spec's MP0 row as baseline-captured (one-line edit in `docs/superpowers/specs/2026-07-05-modern-pipeline-design.md` §5 gate line: append "— PASSED , see baseline doc"). + +```bash +git add docs/research/2026-07-XX-mp0-baseline.md docs/superpowers/specs/2026-07-05-modern-pipeline-design.md +git commit -m "docs(pipeline): MP0 baseline captured - attribution verdict + gate decision" +``` + +--- + +## Post-plan notes for the executor + +- **Do not strip `[frame-prof]`** in future probe-cleanup commits — it is permanent apparatus (the flag doc comment says so; so does spec §5). +- The existing `[FRAME-DIAG]` / `[WB-DIAG]` apparatus is untouched by this plan — the distance-degrade handoff still owns its strip decision. +- The roadmap "Modern Pipeline side track" section + milestones-doc freeze-exception paragraph (spec §12) should be added in the same commit as Task 5's baseline doc if not already present.