chore(diag): dense-town FPS profiling apparatus (ACDREAM_FPS_PROF) [throwaway]

FrameProfiler (frame/update/render/present/gpu split + per-renderer glFinish
attribution) + OnRender/OnUpdate hooks + terrain & EnvCell glFinish timers +
the degrade-coverage probe test. Used to root-cause the dense-town FPS; STRIP
when the fix lands (mirrors 92e95be).

Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>

src/AcDream.App/Rendering/FrameProfiler.cs

@@ -0,0 +1,191 @@
+using System;
+using System.Collections.Generic;
+using System.Diagnostics;
+using System.Linq;
+using Silk.NET.OpenGL;
+
+namespace AcDream.App.Rendering;
+
+/// <summary>
+/// THROWAWAY perf apparatus (2026-06-23) for the dense-town FPS investigation.
+/// Gated on <c>ACDREAM_FPS_PROF=1</c>. Answers the first fork — is the frame
+/// CPU-render-bound, GPU-bound, or wait/vsync-bound — by measuring three numbers
+/// per frame and printing their distribution every ~1 s:
+///
+/// <list type="bullet">
+///   <item><b>wall</b>: the real frame period the user sees (Silk's inter-frame
+///   delta). 1000/wall = the title-bar FPS.</item>
+///   <item><b>cpuRender</b>: wall-clock CPU time spent inside <c>OnRender</c>
+///   (the render-thread submission cost — walk, group-build, draw issue).</item>
+///   <item><b>gpu</b>: GPU time for the whole frame's GL work, via a
+///   <c>TimeElapsed</c> query bracketing the frame (ring of 3 for async readback,
+///   mirroring WbDrawDispatcher's #125-safe pattern).</item>
+/// </list>
+///
+/// Interpretation: gpu≈wall ⇒ GPU-bound (then break down by pass); cpuRender≈wall
+/// &amp; gpu≪ ⇒ CPU-render-bound (draw-call submission / batching / the walk);
+/// wall≫both ⇒ wait/vsync-bound (the 60→30 quantization cliff — confirm via the
+/// printed vsync state). Also prints live vsync + MSAA sample count.
+///
+/// Do NOT run alongside <c>ACDREAM_WB_DIAG=1</c>: WB-DIAG opens its own per-pass
+/// <c>TimeElapsed</c> queries and GL forbids nesting them inside this frame query.
+/// </summary>
+internal sealed class FrameProfiler
+{
+    private const int RingDepth = 3;
+    private const int SampleCap = 512;
+
+    private readonly GL _gl;
+    private readonly uint[] _gpuQuery = new uint[RingDepth];
+    private readonly bool[] _begun = new bool[RingDepth];
+    private bool _queriesInit;
+    private int _frame;
+
+    private readonly Stopwatch _cpuSw = new();
+    // Free-running clock to measure the OnUpdate→OnRender gap robustly (no
+    // EndUpdate hook needed → survives any early-return in OnUpdate).
+    private readonly Stopwatch _clock = Stopwatch.StartNew();
+    private double _updateStartMs;
+    private double _lastUpdateMs;
+
+    private readonly double[] _wallMs = new double[SampleCap];
+    private readonly double[] _cpuMs  = new double[SampleCap];
+    private readonly double[] _gpuMs  = new double[SampleCap];
+    private readonly double[] _updMs  = new double[SampleCap];
+    private readonly double[] _presMs = new double[SampleCap];
+    private int _count;
+    private double _lastGpuMs;          // carried forward when a slot isn't ready yet
+
+    private double _accumSeconds;
+    private int _flushFrames = 1;
+    private const double FlushSeconds = 1.0;
+
+    private bool _vsync;
+    private int _msaa;
+
+    public FrameProfiler(GL gl) => _gl = gl ?? throw new ArgumentNullException(nameof(gl));
+
+    // THROWAWAY per-renderer GPU attribution (glFinish-bracketed, set true by
+    // ACDREAM_FPS_PROF=1). Renderers drain+time their own draw and report here;
+    // glFinish serializes CPU/GPU so the FRAME time inflates, but each renderer's
+    // GPU cost is exact while the view is held still. Read+cleared each Flush.
+    internal static readonly bool PassGpuEnabled =
+        string.Equals(Environment.GetEnvironmentVariable("ACDREAM_FPS_PROF"), "1", StringComparison.Ordinal);
+    private static readonly Dictionary<string, (double sum, int n)> _rendererGpu = new();
+    private static readonly object _rgLock = new();
+    internal static void AddRendererGpu(string name, double ms)
+    {
+        lock (_rgLock)
+        {
+            var cur = _rendererGpu.TryGetValue(name, out var v) ? v : (sum: 0.0, n: 0);
+            _rendererGpu[name] = (cur.sum + ms, cur.n + 1);
+        }
+    }
+
+    /// <summary>Call at the very top of OnUpdate. Stamps the start of the update phase.</summary>
+    public void MarkUpdateStart() => _updateStartMs = _clock.Elapsed.TotalMilliseconds;
+
+    /// <summary>Call at the very top of OnRender, before any GL work.</summary>
+    public void BeginFrame()
+    {
+        if (!_queriesInit)
+        {
+            for (int i = 0; i < RingDepth; i++) _gpuQuery[i] = _gl.GenQuery();
+            _queriesInit = true;
+        }
+        // OnUpdate ran immediately before this; its duration ≈ render-start − update-start.
+        double nowMs = _clock.Elapsed.TotalMilliseconds;
+        _lastUpdateMs = _updateStartMs > 0 ? nowMs - _updateStartMs : 0;
+        _cpuSw.Restart();
+        int slot = _frame % RingDepth;
+        _gl.BeginQuery(QueryTarget.TimeElapsed, _gpuQuery[slot]);
+        _begun[slot] = true;
+    }
+
+    /// <summary>Call at the very end of OnRender, after all GL work (incl. ImGui).</summary>
+    public void EndFrame(double wallMs, bool vsync, int msaa, double deltaSeconds)
+    {
+        _gl.EndQuery(QueryTarget.TimeElapsed);
+        _cpuSw.Stop();
+        double cpuMs = _cpuSw.Elapsed.TotalMilliseconds;
+        _vsync = vsync;
+        _msaa = msaa;
+
+        // Read the oldest ring slot (written RingDepth-1 frames ago, now ready).
+        int readSlot = (_frame + 1) % RingDepth;
+        if (_begun[readSlot])
+        {
+            _gl.GetQueryObject(_gpuQuery[readSlot], QueryObjectParameterName.ResultAvailable, out int avail);
+            if (avail != 0)
+            {
+                _gl.GetQueryObject(_gpuQuery[readSlot], QueryObjectParameterName.Result, out ulong ns);
+                _lastGpuMs = ns / 1_000_000.0;
+            }
+        }
+
+        // Present/swap/GPU-tail wait = whatever the frame period isn't update or render CPU.
+        double presentMs = Math.Max(0.0, wallMs - _lastUpdateMs - cpuMs);
+
+        if (_count < SampleCap)
+        {
+            _wallMs[_count] = wallMs;
+            _cpuMs[_count]  = cpuMs;
+            _gpuMs[_count]  = _lastGpuMs;
+            _updMs[_count]  = _lastUpdateMs;
+            _presMs[_count] = presentMs;
+            _count++;
+        }
+
+        _frame++;
+        _accumSeconds += deltaSeconds;
+        if (_accumSeconds >= FlushSeconds)
+        {
+            Flush();
+            _accumSeconds = 0;
+            _count = 0;
+        }
+    }
+
+    private void Flush()
+    {
+        if (_count == 0) return;
+        _flushFrames = _count;
+        var (wP50, wP95, wMin, wMax) = Stats(_wallMs, _count);
+        var (cP50, cP95, _, cMax)    = Stats(_cpuMs, _count);
+        var (gP50, gP95, _, gMax)    = Stats(_gpuMs, _count);
+        var (uP50, uP95, _, uMax)    = Stats(_updMs, _count);
+        var (pP50, pP95, _, pMax)    = Stats(_presMs, _count);
+        double fpsP50 = wP50 > 0 ? 1000.0 / wP50 : 0;
+        double fpsLow = wMax > 0 ? 1000.0 / wMax : 0;   // worst frame → lowest fps
+
+        Console.WriteLine(
+            $"[FPS-PROF] n={_count} vsync={(_vsync ? "ON" : "off")} msaa={_msaa}x | "
+          + $"wall={wP50:F1}/{wP95:F1}/{wMin:F1}/{wMax:F1} ms (fps {fpsP50:F0} p50, {fpsLow:F0} low)\n"
+          + $"           update={uP50:F1}/{uP95:F1} ms (max {uMax:F1}) | "
+          + $"cpuRender={cP50:F1}/{cP95:F1} ms (max {cMax:F1}) | "
+          + $"present(wait)={pP50:F1}/{pP95:F1} ms (max {pMax:F1}) | "
+          + $"gpu={gP50:F1}/{gP95:F1} ms (max {gMax:F1})");
+
+        lock (_rgLock)
+        {
+            if (_rendererGpu.Count > 0)
+            {
+                var parts = _rendererGpu
+                    .OrderByDescending(kv => kv.Value.sum)
+                    .Select(kv => $"{kv.Key}={kv.Value.sum / Math.Max(1, _flushFrames):F2}ms/frame (calls/frame={kv.Value.n / (double)Math.Max(1, _flushFrames):F1})");
+                Console.WriteLine("[PASS-GPU] (glFinish, frame time inflated) " + string.Join("  ", parts));
+                _rendererGpu.Clear();
+            }
+        }
+    }
+
+    private static (double p50, double p95, double min, double max) Stats(double[] src, int n)
+    {
+        var buf = new double[n];
+        Array.Copy(src, buf, n);
+        Array.Sort(buf);
+        double p50 = buf[(int)(n * 0.50)];
+        double p95 = buf[Math.Min(n - 1, (int)(n * 0.95))];
+        return (p50, p95, buf[0], buf[n - 1]);
+    }
+}

src/AcDream.App/Rendering/GameWindow.cs

@@ -62,6 +62,14 @@ public sealed class GameWindow : IDisposable
     private double _lastFps = 60.0;
     private double _lastFrameMs = 16.7;
 
+    // THROWAWAY FPS-investigation apparatus (2026-06-23, ACDREAM_FPS_PROF=1):
+    // frame-level CPU/GPU/wall profiler to find the dense-town bottleneck. See
+    // FrameProfiler. Lazy-constructed on first OnRender once _gl is live.
+    private readonly bool _fpsProf =
+        string.Equals(Environment.GetEnvironmentVariable("ACDREAM_FPS_PROF"), "1", StringComparison.Ordinal);
+    private FrameProfiler? _frameProfiler;
+    private int _msaaSamples;
+
     // Phase I.2: per-frame counters surfaced through the ImGui DebugPanel
     // VM closures. Computed once per render pass alongside the frustum
     // walk + nearest-object scan; the VM closures just read the cached
@@ -976,6 +984,7 @@ public sealed class GameWindow : IDisposable
         var startupDisplay = startupStore.LoadDisplay();
         var startupBase    = AcDream.UI.Abstractions.Settings.QualitySettings.From(startupDisplay.Quality);
         var startupQuality = AcDream.UI.Abstractions.Settings.QualitySettings.WithEnvOverrides(startupBase);
+        _msaaSamples = startupQuality.MsaaSamples;   // ACDREAM_FPS_PROF apparatus
 
         var options = WindowOptions.Default with
         {
@@ -7613,6 +7622,11 @@ public sealed class GameWindow : IDisposable
 
     private void OnUpdate(double dt)
     {
+        // THROWAWAY FPS apparatus (ACDREAM_FPS_PROF=1): stamp the start of the
+        // update phase so the profiler can split frame time into update vs render
+        // vs present. Robust to early-returns below (no matching EndUpdate needed).
+        if (_fpsProf) _frameProfiler?.MarkUpdateStart();
+
         // [FRAME-DIAG]: applies run later this frame inside _streamingController.Tick;
         // flush the PREVIOUS OnUpdate's accumulated apply cost here (a clean per-frame
         // boundary, independent of where in OnUpdate the applies landed) and reset.
@@ -8347,6 +8361,14 @@ public sealed class GameWindow : IDisposable
 
     private void OnRender(double deltaSeconds)
     {
+        // THROWAWAY FPS apparatus (ACDREAM_FPS_PROF=1): bracket the whole frame's
+        // CPU (this method) + GPU (TimeElapsed query) work. Begin before any GL.
+        if (_fpsProf && _gl is not null)
+        {
+            _frameProfiler ??= new FrameProfiler(_gl);
+            _frameProfiler.BeginFrame();
+        }
+
         // Phase G.1: set the clear color from the current sky's fog
         // tint so the horizon band continues naturally past the
         // rendered geometry. Fog blends to this color at max distance
@@ -9399,6 +9421,11 @@ public sealed class GameWindow : IDisposable
             _imguiBootstrap.Render();
         }
 
+        // THROWAWAY FPS apparatus (ACDREAM_FPS_PROF=1): close the frame's CPU+GPU
+        // brackets after ALL GL work (incl. ImGui). wall = the real frame period.
+        if (_fpsProf && _frameProfiler is not null)
+            _frameProfiler.EndFrame(deltaSeconds * 1000.0, _window!.VSync, _msaaSamples, deltaSeconds);
+
         // Update the window title with performance stats every ~0.5s.
         _perfAccum += deltaSeconds;
         _perfFrameCount++;
@@ -10765,9 +10792,15 @@ public sealed class GameWindow : IDisposable
                 AcDream.Core.Vfx.ParticleRenderPass.SkyPreScene);
 
         EnableClipDistances();
+        // THROWAWAY FPS apparatus: glFinish-bracket the PER-SLICE terrain draw so
+        // [PASS-GPU] reports terrain ms/frame + calls/frame (= slice count). This
+        // is the suspected multiplier: terrain is redrawn fully once per slice.
+        System.Diagnostics.Stopwatch? _terrGpuSw = null;
+        if (FrameProfiler.PassGpuEnabled) { _gl!.Finish(); _terrGpuSw = System.Diagnostics.Stopwatch.StartNew(); }
         _terrainCpuStopwatch.Restart();
         _terrain?.Draw(camera, frustum, neverCullLandblockId: playerLb);
         _terrainCpuStopwatch.Stop();
+        if (_terrGpuSw is not null) { _gl!.Finish(); FrameProfiler.AddRendererGpu("terrain", _terrGpuSw.Elapsed.TotalMilliseconds); }
         _terrainCpuSamples[_terrainCpuSampleCursor] =
             (long)(_terrainCpuStopwatch.Elapsed.TotalMicroseconds * 100.0);
         _terrainCpuSampleCursor = (_terrainCpuSampleCursor + 1) % _terrainCpuSamples.Length;

src/AcDream.App/Rendering/Wb/EnvCellRenderer.cs

@@ -836,6 +836,18 @@ public sealed unsafe class EnvCellRenderer : IDisposable
     /// </summary>
     public void Render(WbRenderPass renderPass, HashSet<uint>? filter)
     {
+        // THROWAWAY FPS apparatus (ACDREAM_FPS_PROF=1): glFinish-bracket this cell
+        // draw so the profiler can attribute its exact GPU cost. Serializes the
+        // pipeline (inflates frame time) but isolates cell-draw GPU at a held view.
+        System.Diagnostics.Stopwatch? _passSw = null;
+        if (AcDream.App.Rendering.FrameProfiler.PassGpuEnabled)
+        {
+            _gl.Finish();
+            _passSw = System.Diagnostics.Stopwatch.StartNew();
+        }
+        try
+        {
+
         // WB EnvCellRenderManager.cs:400:
         if (!_initialized || _shader is null || _shader.Program == 0) return;
 
@@ -1030,6 +1042,15 @@ public sealed unsafe class EnvCellRenderer : IDisposable
                 System.Console.WriteLine(sb.ToString());
             }
         }
+        }
+        finally
+        {
+            if (_passSw is not null)
+            {
+                _gl.Finish();
+                AcDream.App.Rendering.FrameProfiler.AddRendererGpu("cells", _passSw.Elapsed.TotalMilliseconds);
+            }
+        }
     }
 
     // ---------------------------------------------------------------------------