erik/acdream
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions 2

perf(diag): per-frame history export + checkpoint LOH/cache counters + soak capped mode (2026-07-24 audit review)

Browse source 
An adversarial performance review found our own instruments cannot
measure the project's own performance gates:

- FrameProfiler aggregated CPU/GPU/alloc/stage samples into ~5-second
  windows and reset the ring buffers after each report, so route-wide
  p50/p95/p99 distributions across a whole soak could not be
  reconstructed after the fact. ACDREAM_FRAME_HISTORY=<path> now opts
  into a separate per-frame history (one record per frame, ~72
  bytes/record, accumulated in memory with zero frame-thread I/O) that
  a shutdown-only Dispose() writes as CSV. The aggregated [frame-prof]
  report format and its existing metrics are unchanged.

- The canonical checkpoint JSON tracked cache residency (entry/byte
  counts) but never LOH size/fragmentation, process-wide allocated
  bytes, or cache hit/miss/eviction traffic — a committed audit JSON
  showed 65% LOH fragmentation that no tracked instrument recorded,
  and "does a revisit portal hit or miss the caches" was unanswerable
  from an artifact alone. WorldLifecycleResourceSnapshot now carries
  loh_size_bytes/loh_fragmentation_bytes (GCMemoryInfo.GenerationInfo
  index 3), process_total_allocated_bytes (GC.GetTotalAllocatedBytes),
  and Interlocked hit/miss/eviction counters for the CPU mesh cache,
  decoded-texture cache, and the four bounded DAT-object caches
  (portal/cell/highRes/language, aggregated).

- run-connected-r6-soak.ps1 unconditionally forced
  ACDREAM_UNCAPPED_RENDER=1 with no capped mode, while its sibling
  lifecycle-gate script correctly gated it behind a switch. Added
  -Uncapped (default capped, matching the sibling script's pattern),
  fixed the stationary dwell (12s -> 26s, past the 25s
  LiveEntityLivenessController deadline the adjacent comment already
  cited), and now write an env-disclosure.json into the automation
  artifact directory before every launch listing every ACDREAM_* var
  the script sets plus -Uncapped, since the prior audit could only see
  ACDREAM_DUMP_MOVE_TRUTH and nothing else was ever recorded anywhere.

Cache counters are wired via the existing composition path
(ObjectMeshManager already owns the CPU mesh cache and the mesh
extractor directly; content.Dats is threaded into
WorldLifecycleResourceSnapshotSource the same way every other
composition consumer receives it). The DAT-object cache lives behind
IDatReaderWriter, a third-party interface from the DatReaderWriter
package that cannot be extended; RuntimeDatCollection (the one
production implementation) exposes the aggregate stats directly and a
pattern match reads them, degrading to zero for any test double —
no new static registry was introduced (GpuMemoryTracker remains the
one precedented process-wide static).

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
(cherry picked from commit 1da2c33c875b41fa383dd79694ee2765f0e21896)
This commit is contained in:
Erik 2026-07-24 11:58:47 +02:00
parent bfc5e47365
commit 7b456b49d6
20 changed files with 477 additions and 9 deletions
Download patch file Download diff file Expand all files Collapse all files

132
src/AcDream.App/Diagnostics/FrameProfiler.cs
View file

@ -1,6 +1,8 @@
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;
@ -20,6 +22,38 @@ public enum FrameStage
Pacing = 3,
}
/// <summary>
/// One <c>ACDREAM_FRAME_HISTORY</c> CSV row — every field the aggregated
/// <c>[frame-prof]</c> report discards when its 5-second window resets.
/// Stage fields mirror <see cref="FrameStage"/> positionally (Update /
/// Upload / ImGui / Pacing, matching <see cref="FrameProfiler.FormatReport"/>'s
/// <c>names</c> array) — if <see cref="FrameStage"/> grows, extend this
/// record, <see cref="FrameProfiler.WriteHistoryCsv"/>, and the CSV header
/// together. <c>GpuUs</c> is <c>-1</c> for a frame with no available GPU
/// sample (warm-up, or <c>ACDREAM_WB_DIAG=1</c> self-disable).
/// </summary>
internal readonly struct FrameHistoryRecord(
int frameIndex,
double timestampMs,
long cpuUs,
long gpuUs,
long allocBytes,
long updateUs,
long uploadUs,
long imGuiUs,
long pacingUs)
{
public readonly int FrameIndex = frameIndex;
public readonly double TimestampMs = timestampMs;
public readonly long CpuUs = cpuUs;
public readonly long GpuUs = gpuUs;
public readonly long AllocBytes = allocBytes;
public readonly long UpdateUs = updateUs;
public readonly long UploadUs = uploadUs;
public readonly long ImGuiUs = imGuiUs;
public readonly long PacingUs = pacingUs;
}
/// <summary>
/// MP0 (2026-07-05) — the permanent honest frame profiler. One
/// <c>FrameBoundary</c> call at the top of <c>GameWindow.OnRender</c>
@ -35,11 +69,28 @@ public enum FrameStage
/// <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>
///
/// <para>2026-07-24 measurement-tooling review — the aggregated report
/// resets its ring buffers every ~5 s (<see cref="FrameStatsBuffer.Reset"/>),
/// so route-wide p50/p95/p99 distributions across a whole soak cannot be
/// reconstructed after the fact. <see cref="RenderingDiagnostics.FrameHistoryPath"/>
/// (<c>ACDREAM_FRAME_HISTORY=&lt;path&gt;</c>) opts into a SEPARATE
/// per-frame history: one <see cref="FrameHistoryRecord"/> per frame in a
/// preallocated, grow-as-needed <see cref="List{T}"/> (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). ZERO frame-thread I/O: the list only grows during
/// <see cref="FrameBoundary"/>; the CSV is written once, from
/// <see cref="Dispose"/>, at shutdown. Recording only takes effect while
/// <see cref="RenderingDiagnostics.FrameProfEnabled"/> is ALSO true — it
/// reuses that instrumentation rather than duplicating it. Does not
/// change the <c>[frame-prof]</c> report format or any existing metric.</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 int HistoryInitialCapacity = 4096;
private const long ReportIntervalTicks = 5 * TimeSpan.TicksPerSecond;
private static readonly int StageCount = Enum.GetValues<FrameStage>().Length;
@ -48,8 +99,12 @@ public sealed class FrameProfiler : IDisposable
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<FrameHistoryRecord>? _history;
private readonly long _profilerStartTimestamp;
private int _historyFrameIndex;
private GpuFrameTimer? _gpuTimer;
private long _lastBoundaryTimestamp;
@ -70,6 +125,10 @@ public sealed class FrameProfiler : IDisposable
_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();
if (RenderingDiagnostics.FrameHistoryPath is not null)
_history = new List<FrameHistoryRecord>(HistoryInitialCapacity);
}
/// <summary>
@ -105,6 +164,8 @@ public sealed class FrameProfiler : IDisposable
long now = Stopwatch.GetTimestamp();
long allocNow = GC.GetAllocatedBytesForCurrentThread();
bool historyFrame = false;
long historyCpuUs = 0, historyAllocBytes = 0;
if (!_wasEnabled)
{
// First enabled frame (startup or runtime toggle-on): establish
@ -128,21 +189,42 @@ public sealed class FrameProfiler : IDisposable
{
long cpuUs = (now - _lastBoundaryTimestamp) * 1_000_000L / Stopwatch.Frequency;
_cpuUs.Push(cpuUs);
_allocBytes.Push(allocNow - _lastAllocBytes);
long allocDelta = allocNow - _lastAllocBytes;
_allocBytes.Push(allocDelta);
for (int i = 0; i < StageCount; i++)
{
_stageUs[i].Push(_stageAccumTicks[i] * 1_000_000L / Stopwatch.Frequency);
long stageUs = _stageAccumTicks[i] * 1_000_000L / Stopwatch.Frequency;
_stageUs[i].Push(stageUs);
_lastStageUs[i] = stageUs;
_stageAccumTicks[i] = 0;
}
_framesInWindow++;
historyFrame = _history is not null;
historyCpuUs = cpuUs;
historyAllocBytes = allocDelta;
}
_lastBoundaryTimestamp = now;
_lastAllocBytes = allocNow;
if (_gpuTimer?.FrameBoundary() is long gpuUs)
long? gpuUsSample = _gpuTimer?.FrameBoundary();
if (gpuUsSample is long gpuUs)
_gpuUs.Push(gpuUs);
if (historyFrame)
{
_history!.Add(new FrameHistoryRecord(
_historyFrameIndex++,
(now - _profilerStartTimestamp) * 1000.0 / Stopwatch.Frequency,
historyCpuUs,
gpuUsSample ?? -1L,
historyAllocBytes,
_lastStageUs[(int)FrameStage.Update],
_lastStageUs[(int)FrameStage.Upload],
_lastStageUs[(int)FrameStage.ImGui],
_lastStageUs[(int)FrameStage.Pacing]));
}
long nowTicks = DateTime.UtcNow.Ticks;
if (nowTicks - _lastReportTicks >= ReportIntervalTicks && _framesInWindow > 0)
{
@ -200,7 +282,49 @@ public sealed class FrameProfiler : IDisposable
return sb.ToString();
}
public void Dispose() => _gpuTimer?.Dispose();
/// <summary>Pure CSV formatter — unit-tested; invariant culture. One header row plus one row per record.</summary>
internal static void WriteHistoryCsv(IEnumerable<FrameHistoryRecord> records, TextWriter writer)
{
var ci = CultureInfo.InvariantCulture;
writer.WriteLine("frame,timestamp_ms,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(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));
}
}
/// <summary>
/// Shutdown-only write of the accumulated <see cref="_history"/> as CSV
/// (the ONLY I/O this feature performs — never from <see cref="FrameBoundary"/>).
/// Failures are logged, not thrown: a history-export problem must never
/// block the rest of the render-owner shutdown chain
/// (<c>GameWindowLifetime</c>'s <c>Hard("frame profiler", ...)</c> stage).
/// </summary>
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);
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}");
}
}
}
}
/// <summary>Disposable stage scope; default instance is a no-op.</summary>

12
src/AcDream.App/Diagnostics/WorldLifecycleAutomationController.cs
View file

@ -62,6 +62,18 @@ internal sealed record WorldLifecycleResourceSnapshot(
int CompositeWarmupPending,
long ManagedBytes,
long ManagedCommittedBytes,
long LohSizeBytes,
long LohFragmentationBytes,
long ProcessTotalAllocatedBytes,
long CpuMeshCacheHits,
long CpuMeshCacheMisses,
long CpuMeshCacheEvictions,
long DecodedTextureCacheHits,
long DecodedTextureCacheMisses,
long DecodedTextureCacheEvictions,
long DatObjectCacheHits,
long DatObjectCacheMisses,
long DatObjectCacheEvictions,
double Fps,
double FrameMilliseconds,
string? LastFrameProfile);

42
src/AcDream.App/Diagnostics/WorldLifecycleResourceSnapshotSource.cs
View file

@ -3,7 +3,9 @@ using AcDream.App.Rendering.Vfx;
using AcDream.App.Rendering.Wb;
using AcDream.App.Streaming;
using AcDream.App.World;
using AcDream.Content;
using AcDream.Core.Vfx;
using DatReaderWriter.Lib.IO;
namespace AcDream.App.Diagnostics;
@ -14,6 +16,10 @@ namespace AcDream.App.Diagnostics;
/// </summary>
internal sealed class WorldLifecycleResourceSnapshotSource
{
// Generation index 3 is the large object heap; see GCMemoryInfo.GenerationInfo
// (verified against the installed net10.0 runtime — Gen0/1/2, LOH, POH).
private const int LohGenerationIndex = 3;
private readonly GpuWorldState _world;
private readonly LiveEntityAnimationRuntimeView<LiveEntityAnimationState>
_animations;
@ -29,6 +35,7 @@ internal sealed class WorldLifecycleResourceSnapshotSource
private readonly TextureCache _textures;
private readonly WbDrawDispatcher _dispatcher;
private readonly FrameProfiler _frameProfiler;
private readonly IDatReaderWriter _dats;
public WorldLifecycleResourceSnapshotSource(
GpuWorldState world,
@ -44,7 +51,8 @@ internal sealed class WorldLifecycleResourceSnapshotSource
WbMeshAdapter meshes,
TextureCache textures,
WbDrawDispatcher dispatcher,
FrameProfiler frameProfiler)
FrameProfiler frameProfiler,
IDatReaderWriter dats)
{
_world = world ?? throw new ArgumentNullException(nameof(world));
_animations = animations
@ -68,6 +76,7 @@ internal sealed class WorldLifecycleResourceSnapshotSource
?? throw new ArgumentNullException(nameof(dispatcher));
_frameProfiler = frameProfiler
?? throw new ArgumentNullException(nameof(frameProfiler));
_dats = dats ?? throw new ArgumentNullException(nameof(dats));
}
public WorldLifecycleResourceSnapshot Capture(RenderFrameOutcome outcome)
@ -78,6 +87,25 @@ internal sealed class WorldLifecycleResourceSnapshotSource
var mesh = meshManager.Diagnostics;
RenderFrameDiagnosticsSnapshot render = _renderDiagnostics.Snapshot;
GCMemoryInfo memory = GC.GetGCMemoryInfo();
ReadOnlySpan<GCGenerationInfo> generations = memory.GenerationInfo;
long lohSizeBytes = generations.Length > LohGenerationIndex
? generations[LohGenerationIndex].SizeAfterBytes
: 0L;
long lohFragmentationBytes = generations.Length > LohGenerationIndex
? generations[LohGenerationIndex].FragmentationAfterBytes
: 0L;
// The DAT-object cache lives behind IDatReaderWriter (a third-party
// interface from the DatReaderWriter package — we cannot extend it).
// RuntimeDatCollection is the one production implementation that
// owns the bounded per-database caches; a caller supplying a test
// double simply reports zero counters here.
CacheStats datObjectCacheStats = _dats is RuntimeDatCollection runtimeDats
? runtimeDats.ObjectCacheStats
: default;
CacheStats cpuMeshCacheStats = meshManager.CpuMeshCacheStats;
CacheStats decodedTextureCacheStats = meshManager.DecodedTextureCacheStats;
return new WorldLifecycleResourceSnapshot(
LoadedLandblocks: _world.LoadedLandblockIds.Count,
WorldEntities: _world.Entities.Count,
@ -112,6 +140,18 @@ internal sealed class WorldLifecycleResourceSnapshotSource
_dispatcher.LastCompositeWarmupPendingCount,
ManagedBytes: GC.GetTotalMemory(forceFullCollection: false),
ManagedCommittedBytes: memory.TotalCommittedBytes,
LohSizeBytes: lohSizeBytes,
LohFragmentationBytes: lohFragmentationBytes,
ProcessTotalAllocatedBytes: GC.GetTotalAllocatedBytes(precise: false),
CpuMeshCacheHits: cpuMeshCacheStats.Hits,
CpuMeshCacheMisses: cpuMeshCacheStats.Misses,
CpuMeshCacheEvictions: cpuMeshCacheStats.Evictions,
DecodedTextureCacheHits: decodedTextureCacheStats.Hits,
DecodedTextureCacheMisses: decodedTextureCacheStats.Misses,
DecodedTextureCacheEvictions: decodedTextureCacheStats.Evictions,
DatObjectCacheHits: datObjectCacheStats.Hits,
DatObjectCacheMisses: datObjectCacheStats.Misses,
DatObjectCacheEvictions: datObjectCacheStats.Evictions,
Fps: render.Fps,
FrameMilliseconds: render.FrameMilliseconds,
LastFrameProfile: _frameProfiler.LastReport);