using System; using System.Collections.Generic; using System.Diagnostics; using System.Globalization; using System.IO; 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, /// Software presentation deadline wait (zero under VSync or uncapped mode). Pacing = 3, } /// /// One ACDREAM_FRAME_HISTORY CSV row — every field the aggregated /// [frame-prof] report discards when its 5-second window resets. /// Stage fields mirror positionally (Update / /// Upload / ImGui / Pacing, matching 's /// names array) — if grows, extend this /// record, , and the CSV header /// together. GpuUs is -1 for a frame with no available GPU /// sample (warm-up, or ACDREAM_WB_DIAG=1 self-disable). /// internal readonly record struct FrameHistoryRecord( int FrameIndex, double TimestampMs, long CpuUs, long GpuUs, long AllocBytes, long UpdateUs, long UploadUs, long ImGuiUs, long PacingUs); /// /// MP0 (2026-07-05) — the permanent honest frame profiler. One /// FrameBoundary call at the top of the accepted render transaction /// measures CPU frame time as the delta between consecutive boundaries /// (captures the FULL frame including present) and samples per-frame allocated /// bytes + GC collection counts. and /// separately bracket only submitted render work. /// 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). /// /// 2026-07-24 measurement-tooling review — the aggregated report /// resets its ring buffers every ~5 s (), /// so route-wide p50/p95/p99 distributions across a whole soak cannot be /// reconstructed after the fact. /// (ACDREAM_FRAME_HISTORY=<path>) opts into a SEPARATE /// per-frame history: one per frame in a /// preallocated, grow-as-needed (1 int + 1 double + /// 7 longs ≈ 72 bytes/record; a multi-hour capture at 165 fps is roughly /// 165 * 3600 * 72 bytes ≈ 43 MB/hour — fine for a bounded diagnostic run, /// not for unattended day-long capture). Its initial capacity is about 9 MiB /// and covers the canonical route above 300 FPS without a frame-thread resize. /// ZERO frame-thread I/O: the CSV is written once, from /// , at shutdown. Recording only takes effect while /// is ALSO true — it /// reuses that instrumentation rather than duplicating it. Does not /// change the [frame-prof] report format or any existing metric. /// 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 int HistoryInitialCapacity = 131072; 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 long[] _lastStageUs; private readonly bool _wbDiagActive = Environment.GetEnvironmentVariable("ACDREAM_WB_DIAG") == "1"; private readonly List? _history; private readonly long _profilerStartTimestamp; private readonly DateTime _profilerStartUtc; private int _currentFrameIndex = -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; /// Most recent immutable report line, for explicit automation checkpoints. public string? LastReport { get; private set; } public FrameProfiler() { _stageUs = new FrameStatsBuffer[StageCount]; for (int i = 0; i < StageCount; i++) _stageUs[i] = new FrameStatsBuffer(WindowCapacity); _stageAccumTicks = new long[StageCount]; _lastStageUs = new long[StageCount]; _profilerStartTimestamp = Stopwatch.GetTimestamp(); _profilerStartUtc = DateTime.UtcNow; if (RenderingDiagnostics.FrameHistoryPath is not null) _history = new List(HistoryInitialCapacity); } /// /// Call once at the accepted render-transaction boundary, before /// . /// public void FrameBoundary(GL gl) { bool enabled = RenderingDiagnostics.FrameProfEnabled; if (!enabled) { if (_wasEnabled) { // Dispose (not just Stop) so a later re-enable rebuilds the // query ring fresh — a kept instance would poll slots left // pending from BEFORE the pause and report temporally stale // GPU samples. Safe here: this runs at the top of OnRender // with the GL context current. _gpuTimer?.Dispose(); _gpuTimer = null; _wasEnabled = false; _lastBoundaryTimestamp = 0; _currentFrameIndex = -1; } 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. Clear any stage ticks a StageScope // disposed after toggle-off may have accumulated mid-pause — // EndStage still runs on scopes that were live when the flag // flipped, and that partial delta must not leak into the first // re-enabled frame. _wasEnabled = true; _lastReportTicks = DateTime.UtcNow.Ticks; Array.Clear(_stageAccumTicks); _gc0Base = GC.CollectionCount(0); _gc1Base = GC.CollectionCount(1); _gc2Base = GC.CollectionCount(2); if (_gpuTimer is null && !_wbDiagActive) _gpuTimer = new GpuFrameTimer(gl); _currentFrameIndex = 0; 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); long allocDelta = allocNow - _lastAllocBytes; _allocBytes.Push(allocDelta); for (int i = 0; i < StageCount; i++) { long stageUs = _stageAccumTicks[i] * 1_000_000L / Stopwatch.Frequency; _stageUs[i].Push(stageUs); _lastStageUs[i] = stageUs; _stageAccumTicks[i] = 0; } _framesInWindow++; if (_history is not null) { _history.Add(new FrameHistoryRecord( _currentFrameIndex, (now - _profilerStartTimestamp) * 1000.0 / Stopwatch.Frequency, cpuUs, -1L, allocDelta, _lastStageUs[(int)FrameStage.Update], _lastStageUs[(int)FrameStage.Upload], _lastStageUs[(int)FrameStage.ImGui], _lastStageUs[(int)FrameStage.Pacing])); } _currentFrameIndex++; } _lastBoundaryTimestamp = now; _lastAllocBytes = allocNow; 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; LastReport = FormatReport(_framesInWindow, _cpuUs, _gpuUs, gpuActive: _gpuTimer is not null, _allocBytes, gc0, gc1, gc2, _stageUs); Console.WriteLine(LastReport); _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(); } } /// /// Begin GPU timing immediately before render-resource, world, and private /// presentation submission. Completed delayed samples are associated with /// their owning history row rather than the frame that happened to poll /// them. /// public void BeginGpuFrame() { if (!_wasEnabled || _gpuTimer is null || _currentFrameIndex < 0) return; Span completed = stackalloc GpuFrameSample[4]; int completedCount = _gpuTimer.BeginFrame(_currentFrameIndex, completed); for (int index = 0; index < completedCount; index++) { GpuFrameSample sample = completed[index]; _gpuUs.Push(sample.ElapsedUs); if (_history is not null && (uint)sample.FrameIndex < (uint)_history.Count) { FrameHistoryRecord row = _history[sample.FrameIndex]; _history[sample.FrameIndex] = row with { GpuUs = sample.ElapsedUs }; } } } /// End GPU timing immediately after render submission. public void EndGpuFrame() { _gpuTimer?.EndFrame(); } /// /// 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", "pace" }; 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(); } /// Pure CSV formatter — unit-tested; invariant culture. One header row plus one row per record. internal static void WriteHistoryCsv( IEnumerable records, TextWriter writer, DateTime profilerStartUtc) { var ci = CultureInfo.InvariantCulture; DateTime startUtc = profilerStartUtc.ToUniversalTime(); writer.WriteLine( "frame,timestamp_ms,timestamp_utc,cpu_us,gpu_us,alloc_bytes," + "update_us,upload_us,imgui_us,pacing_us"); foreach (FrameHistoryRecord r in records) { writer.Write(r.FrameIndex.ToString(ci)); writer.Write(','); writer.Write(r.TimestampMs.ToString("0.000", ci)); writer.Write(','); writer.Write(startUtc.AddMilliseconds(r.TimestampMs).ToString("O", ci)); writer.Write(','); writer.Write(r.CpuUs.ToString(ci)); writer.Write(','); writer.Write(r.GpuUs.ToString(ci)); writer.Write(','); writer.Write(r.AllocBytes.ToString(ci)); writer.Write(','); writer.Write(r.UpdateUs.ToString(ci)); writer.Write(','); writer.Write(r.UploadUs.ToString(ci)); writer.Write(','); writer.Write(r.ImGuiUs.ToString(ci)); writer.Write(','); writer.WriteLine(r.PacingUs.ToString(ci)); } } /// /// Shutdown-only write of the accumulated as CSV /// (the ONLY I/O this feature performs — never from ). /// Failures are logged, not thrown: a history-export problem must never /// block the rest of the render-owner shutdown chain /// (GameWindowLifetime's Hard("frame profiler", ...) stage). /// public void Dispose() { _gpuTimer?.Dispose(); if (_history is { Count: > 0 } && RenderingDiagnostics.FrameHistoryPath is { } path) { try { using var writer = new StreamWriter(path, append: false); WriteHistoryCsv(_history, writer, _profilerStartUtc); Console.WriteLine($"[frame-prof] wrote {_history.Count} history record(s) to '{path}'"); } catch (Exception ex) { Console.WriteLine($"[frame-prof] WARNING: failed to write frame history to '{path}': {ex.Message}"); } } } } /// 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); }