From 00e1b32177ea2655cf871bbe5e7c57546cc38f25 Mon Sep 17 00:00:00 2001 From: Erik Date: Tue, 28 Jul 2026 20:35:59 +0200 Subject: [PATCH] perf(render): Campaign V slice V8 commit 1 - the Vulkan arm gets an instrument V8 is the performance gate, and it opened on a plain fact: the Vulkan arm emitted no [frame-prof] line at all. V6h wired it to NullRenderFrameGpuMeasurement, whose BeginFrame does nothing - and that method is the ONLY caller of FrameProfiler.FrameBoundary. So a Vulkan run produced no CPU frame distribution, no allocation-per-frame column, no frame-history CSV and no GPU sample. The campaign's own performance vehicle, tools/run-connected-r6-soak.ps1, waits on [frame-prof] boundaries to time its samples, so it could not be pointed at the backend V8 exists to judge. You cannot measure what you have not instrumented, so the instrument lands first. The bracket is deliberately identical on both arms. On GL, FrameProfilerGpuMeasurement begins a TimeElapsed query at BeginFrame and ends it at EndFrame, spanning resource preparation, the world scene and private presentation, and NOT the swapchain present. VulkanFrameGpuMeasurement opens and closes a Vulkan timestamp scope at exactly those two points. Two differently-bracketed numbers in one comparison table would have been worse than reporting none. Vulkan timestamps resolve two or three frames late, so the sample carries the profiler frame index that ISSUED it rather than being credited to the frame that happened to read it - the pairing GpuFrameTimer already performs internally on GL. VulkanGpuDevice opens the whole-frame scope tagged with that index, reads the previous use of the slot back in BeginFrameResources BEFORE the tag is overwritten, and hands completed (tag, microseconds) pairs to the adapter through a bounded queue that never blocks. VulkanGpuTimerPool gains TryTakeResolved, which consumes the value it reports. TryResolve deliberately reports the last known measurement forever, which is right for a diagnostic readout and wrong for a percentile: counting one measurement into the distribution twice is how an instrument flatters itself. FrameProfiler gains a GL-free FrameBoundary() overload and RecordGpuSample. Every other line of its bookkeeping - the CPU delta, the per-thread allocation delta, the stage buffers, the history row, the five-second report - is the same code the GL arm runs. The GL path is byte-for-byte unchanged in behaviour: FrameBoundary(GL) still owns and creates the query ring. Gates: Release build green. App tests 4,152 passed / 3 skipped, exactly the pre-slice baseline. Strict GL offline pixel gate against 13c8733d: 1.95e-05 (11 px of 563,200), inside the documented 9-31 px band, so GL did not move. An offline Vulkan run now reports gpu_ms in [frame-prof] and fills gpu_us in the frame-history CSV, where before this commit it reported neither. No divergence-register row is owed: this is diagnostic apparatus and no rendered pixel depends on it. Co-Authored-By: Claude Fable 5 --- .../Composition/FrameRootComposition.cs | 10 ++- src/AcDream.App/Diagnostics/FrameProfiler.cs | 52 ++++++++++- .../Gpu/Vk/VulkanFrameGpuMeasurement.cs | 56 ++++++++++++ .../Gpu/Vk/VulkanGpuDevice.Resources.cs | 86 ++++++++++++++++++- .../Rendering/Gpu/Vk/VulkanGpuTimerPool.cs | 14 +++ 5 files changed, 213 insertions(+), 5 deletions(-) create mode 100644 src/AcDream.App/Rendering/Gpu/Vk/VulkanFrameGpuMeasurement.cs diff --git a/src/AcDream.App/Composition/FrameRootComposition.cs b/src/AcDream.App/Composition/FrameRootComposition.cs index 95d5feb6..fd6cde4d 100644 --- a/src/AcDream.App/Composition/FrameRootComposition.cs +++ b/src/AcDream.App/Composition/FrameRootComposition.cs @@ -588,7 +588,15 @@ internal sealed class FrameRootCompositionPhase host.GpuFrameLifetime, gl is not null ? new FrameProfilerGpuMeasurement(d.FrameProfiler, gl) - : AcDream.App.Rendering.Gpu.Vk.NullRenderFrameGpuMeasurement.Instance, + // Campaign V slice V8: the Vulkan arm measures the same bracket + // through its own timestamp scope. It stayed on the null adapter + // from V6h until V8, which meant no [frame-prof] line existed on + // Vulkan at all — see VulkanFrameGpuMeasurement. + : d.Graphics.Vulkan is { } vulkanGraphics + ? new AcDream.App.Rendering.Gpu.Vk.VulkanFrameGpuMeasurement( + d.FrameProfiler, + vulkanGraphics.Device) + : AcDream.App.Rendering.Gpu.Vk.NullRenderFrameGpuMeasurement.Instance, framePreparation, worldSceneRenderer, privatePresentation, diff --git a/src/AcDream.App/Diagnostics/FrameProfiler.cs b/src/AcDream.App/Diagnostics/FrameProfiler.cs index 69d02add..ab083aff 100644 --- a/src/AcDream.App/Diagnostics/FrameProfiler.cs +++ b/src/AcDream.App/Diagnostics/FrameProfiler.cs @@ -99,6 +99,7 @@ public sealed class FrameProfiler : IDisposable private int _currentFrameIndex = -1; private GpuFrameTimer? _gpuTimer; + private bool _externalGpuActive; private long _lastBoundaryTimestamp; private long _lastAllocBytes; private long _lastReportTicks; @@ -112,6 +113,14 @@ public sealed class FrameProfiler : IDisposable /// Most recent immutable report line, for explicit automation checkpoints. public string? LastReport { get; private set; } + /// + /// Index of the frame currently being measured, or -1 before the first + /// enabled boundary. Campaign V slice V8: a backend whose GPU timer is not + /// GL's query ring pairs its delayed samples with this index, exactly as + /// does internally on the GL arm. + /// + public int CurrentFrameIndex => _currentFrameIndex; + public FrameProfiler() { _stageUs = new FrameStatsBuffer[StageCount]; @@ -128,7 +137,20 @@ public sealed class FrameProfiler : IDisposable /// Call once at the accepted render-transaction boundary, before /// . /// - public void FrameBoundary(GL gl) + public void FrameBoundary(GL gl) => FrameBoundary(gl, ownsGpuTimer: true); + + /// + /// Campaign V slice V8: the same CPU/allocation boundary with no GL context. + /// The Vulkan arm has no TimeElapsed query ring to own, so it drives + /// this overload and feeds GPU time in through + /// . Everything else — the CPU delta, the + /// per-thread allocation delta, the stage buffers, the history row and the + /// five-second report — is the identical code path GL uses, because a + /// perf gate that compared two different instruments would compare nothing. + /// + public void FrameBoundary() => FrameBoundary(null, ownsGpuTimer: false); + + private void FrameBoundary(GL? gl, bool ownsGpuTimer) { bool enabled = RenderingDiagnostics.FrameProfEnabled; if (!enabled) @@ -171,7 +193,8 @@ public sealed class FrameProfiler : IDisposable _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); + if (ownsGpuTimer && gl is not null && _gpuTimer is null && !_wbDiagActive) + _gpuTimer = new GpuFrameTimer(gl); _currentFrameIndex = 0; if (_wbDiagActive && !_wbDiagNoticePrinted) { @@ -219,7 +242,8 @@ public sealed class FrameProfiler : IDisposable 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); + gpuActive: _gpuTimer is not null || _externalGpuActive, + _allocBytes, gc0, gc1, gc2, _stageUs); Console.WriteLine(LastReport); _lastReportTicks = nowTicks; _gc0Base += gc0; _gc1Base += gc1; _gc2Base += gc2; @@ -261,6 +285,28 @@ public sealed class FrameProfiler : IDisposable _gpuTimer?.EndFrame(); } + /// + /// Campaign V slice V8: publish one delayed GPU sample measured by a backend + /// that owns its own timer (Vulkan timestamp queries). Identical bookkeeping + /// to 's promotion loop — the sample joins the + /// five-second window and back-fills the history row of the frame that + /// issued it, so gpu_us in the CSV is never attributed to a frame + /// that merely happened to poll it. + /// + public void RecordGpuSample(int frameIndex, long elapsedUs) + { + if (!_wasEnabled) + return; + + _externalGpuActive = true; + _gpuUs.Push(elapsedUs); + if (_history is not null && (uint)frameIndex < (uint)_history.Count) + { + FrameHistoryRecord row = _history[frameIndex]; + _history[frameIndex] = row with { GpuUs = elapsedUs }; + } + } + /// /// Attribute the enclosed CPU time to . /// Usage: using var _ = profiler.BeginStage(FrameStage.Update);. diff --git a/src/AcDream.App/Rendering/Gpu/Vk/VulkanFrameGpuMeasurement.cs b/src/AcDream.App/Rendering/Gpu/Vk/VulkanFrameGpuMeasurement.cs new file mode 100644 index 00000000..634f797f --- /dev/null +++ b/src/AcDream.App/Rendering/Gpu/Vk/VulkanFrameGpuMeasurement.cs @@ -0,0 +1,56 @@ +using AcDream.App.Diagnostics; + +namespace AcDream.App.Rendering.Gpu.Vk; + +/// +/// Campaign V slice V8: the Vulkan arm's render-transaction measurement. +/// +/// V6h left the Vulkan arm on NullRenderFrameGpuMeasurement, +/// which meant was never called at +/// all — so a Vulkan run produced no [frame-prof] line, no frame-history +/// CSV and no allocation-per-frame column. That is not a missing nicety: the R6 +/// soak waits on [frame-prof] boundaries to time its samples, so the +/// campaign's performance vehicle could not be pointed at the backend it was +/// meant to judge. V8 cannot measure what it cannot instrument, so the +/// instrument lands first. +/// +/// The bracket is deliberately the SAME one GL uses. On GL, +/// begins a TimeElapsed query +/// at and ends it at , spanning +/// resource preparation, the world scene and private presentation but not the +/// swapchain present. This adapter opens and closes a Vulkan timestamp scope at +/// exactly those two points, so gpu_ms means the same thing in both +/// columns of the V8 table. Comparing two differently-bracketed numbers would +/// have been worse than reporting none. +/// +/// Timestamps resolve two or three frames late, which is why the sample +/// carries the profiler frame index that ISSUED it +/// () rather than being +/// credited to the frame that happened to read it — the same pairing +/// GpuFrameTimer performs internally on the GL arm. +/// +internal sealed class VulkanFrameGpuMeasurement : IRenderFrameGpuMeasurement +{ + private readonly FrameProfiler _profiler; + private readonly VulkanGpuDevice _device; + + internal VulkanFrameGpuMeasurement(FrameProfiler profiler, VulkanGpuDevice device) + { + _profiler = profiler ?? throw new ArgumentNullException(nameof(profiler)); + _device = device ?? throw new ArgumentNullException(nameof(device)); + } + + public void BeginFrame() + { + _profiler.FrameBoundary(); + + // Drain first: these are measurements of frames that have already + // retired, and the queue is bounded by the flight count. + while (_device.TryTakeFrameGpuSample(out int frameIndex, out long elapsedUs)) + _profiler.RecordGpuSample(frameIndex, elapsedUs); + + _device.BeginFrameTimerScope(_profiler.CurrentFrameIndex); + } + + public void EndFrame() => _device.EndFrameTimerScope(); +} diff --git a/src/AcDream.App/Rendering/Gpu/Vk/VulkanGpuDevice.Resources.cs b/src/AcDream.App/Rendering/Gpu/Vk/VulkanGpuDevice.Resources.cs index a2f140cc..71af91f4 100644 --- a/src/AcDream.App/Rendering/Gpu/Vk/VulkanGpuDevice.Resources.cs +++ b/src/AcDream.App/Rendering/Gpu/Vk/VulkanGpuDevice.Resources.cs @@ -32,6 +32,23 @@ internal sealed unsafe partial class VulkanGpuDevice private VulkanGpuPassEncoder? _openPass; private bool _openPassIsBackbuffer; + /// + /// Campaign V slice V8: name of the whole-frame GPU timer scope. One scope + /// spanning the frame's entire command buffer is the Vulkan equivalent of + /// GL's TimeElapsed query around the render transaction, and is what + /// makes the two backends' gpu_ms columns the same measurement. + /// + private const string FrameTimerScopeName = "frame"; + + /// + /// Profiler frame index the scope in each flight slot was opened under. The + /// timestamps resolve two or three frames later, so the sample has to carry + /// the index of the frame that ISSUED it rather than the one that read it. + /// + private int[] _frameTimerTags = []; + private readonly Queue<(int Tag, long ElapsedUs)> _frameGpuSamples = new(); + private IDisposable? _openFrameTimerScope; + private void InitialiseResources(string? shaderSpirvDirectory, string? pipelineCacheDirectory) { _shaderSpirvDirectory = shaderSpirvDirectory ?? string.Empty; @@ -47,6 +64,8 @@ internal sealed unsafe partial class VulkanGpuDevice _device, _flights.SlotCount, Capabilities.SupportsTimestampQueries); + _frameTimerTags = new int[_flights.SlotCount]; + Array.Fill(_frameTimerTags, -1); _textureTable = new VulkanTextureTable( _vk, _device, @@ -112,7 +131,64 @@ internal sealed unsafe partial class VulkanGpuDevice } } - private void BeginFrameResources(int slotIndex) => _timerPool?.BeginSlot(slotIndex); + private void BeginFrameResources(int slotIndex) + { + if (_timerPool is null) + return; + + // BeginSlot reads back whatever this slot recorded the last time it was + // used. That measurement belongs to the frame whose tag the slot still + // holds — read it BEFORE BeginFrameTimerScope overwrites the tag. + int issuingTag = _frameTimerTags[slotIndex]; + _timerPool.BeginSlot(slotIndex); + if (issuingTag >= 0 + && _timerPool.TryTakeResolved(FrameTimerScopeName, out double milliseconds)) + { + _frameGpuSamples.Enqueue((issuingTag, (long)(milliseconds * 1000d))); + } + } + + /// + /// Campaign V slice V8: opens the whole-frame timer scope on the open + /// frame's command buffer, tagged with the profiler frame index that will + /// own the delayed result. Called by the frame spine's measurement adapter + /// immediately after the frame opens and before any renderer records work, + /// which is exactly where GL's BeginQuery sits. + /// + internal void BeginFrameTimerScope(int frameIndex) + { + if (_openFrame is null || _timerPool is null || _openFrameTimerScope is not null) + return; + + int slot = _openFrame.SlotIndex; + _frameTimerTags[slot] = frameIndex; + _openFrameTimerScope = _timerPool.BeginScope(_commandBuffers[slot], FrameTimerScopeName); + } + + /// Closes the whole-frame timer scope. Idempotent. + internal void EndFrameTimerScope() + { + _openFrameTimerScope?.Dispose(); + _openFrameTimerScope = null; + } + + /// + /// Drains one completed whole-frame GPU measurement, with the profiler frame + /// index that issued it. Never blocks: a frame whose timestamps have not + /// landed yet simply is not in the queue. + /// + internal bool TryTakeFrameGpuSample(out int frameIndex, out long elapsedUs) + { + if (_frameGpuSamples.Count == 0) + { + frameIndex = -1; + elapsedUs = 0; + return false; + } + + (frameIndex, elapsedUs) = _frameGpuSamples.Dequeue(); + return true; + } /// Slice V6i: the descriptor-set arena for one flight slot. private VulkanFrameBindings FrameBindingsAt(int slotIndex) => _frameBindings[slotIndex]; @@ -121,6 +197,11 @@ internal sealed unsafe partial class VulkanGpuDevice { _ = slotIndex; _ = commands; + // Normally already closed by the measurement adapter, which brackets the + // same phases GL's TimeElapsed query does. This is the safety net: a + // scope left open would write its closing timestamp into a pool the next + // frame has already reset. + EndFrameTimerScope(); if (_openPass is not null) { throw new InvalidOperationException( @@ -131,6 +212,9 @@ internal sealed unsafe partial class VulkanGpuDevice private void DisposeResources() { + _openFrameTimerScope = null; + _frameGpuSamples.Clear(); + _frameTimerTags = []; foreach (VulkanFrameBindings bindings in _frameBindings) bindings.Dispose(); _frameBindings = []; diff --git a/src/AcDream.App/Rendering/Gpu/Vk/VulkanGpuTimerPool.cs b/src/AcDream.App/Rendering/Gpu/Vk/VulkanGpuTimerPool.cs index abe24bd4..6f08a3ec 100644 --- a/src/AcDream.App/Rendering/Gpu/Vk/VulkanGpuTimerPool.cs +++ b/src/AcDream.App/Rendering/Gpu/Vk/VulkanGpuTimerPool.cs @@ -170,6 +170,20 @@ internal sealed unsafe class VulkanGpuTimerPool : IGpuTimerPool, IDisposable public bool TryResolve(string scopeName, out double milliseconds) => _resolved.TryGetValue(scopeName, out milliseconds); + /// + /// Campaign V slice V8: reads a resolved value and CONSUMES it, so a caller + /// building a distribution counts each measurement exactly once. + /// deliberately reports the last known value + /// forever — right for a diagnostic readout, wrong for a percentile. + /// + internal bool TryTakeResolved(string scopeName, out double milliseconds) + { + if (!_resolved.TryGetValue(scopeName, out milliseconds)) + return false; + _resolved.Remove(scopeName); + return true; + } + public void Dispose() { if (_disposed)