diff --git a/CMakeLists.txt b/CMakeLists.txt index d89e018..65bbc40 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -438,6 +438,7 @@ add_executable(test_fire_engine tests/render/test_descriptors.cpp tests/render/test_device_plan.cpp tests/render/test_pipeline_config.cpp + tests/render/test_gpu_profiler.cpp tests/render/test_shadow_raster_policy.cpp tests/render/test_vdpm_gpu.cpp tests/render/test_vdpm_gpu_front.cpp diff --git a/README.md b/README.md index 8b5cacc..62b267e 100644 --- a/README.md +++ b/README.md @@ -28,7 +28,7 @@ I've no doubt these are all solved problems nowadays with the Unreal engine et a - **Temporal anti-aliasing (TAA)** — sub-pixel Halton(2,3) projection jitter plus velocity-buffer history accumulation anti-aliases geometry edges *and* specular/shading shimmer (unlike MSAA, which only covers geometry edges). The forward + transmission passes write a screen-space motion-vector attachment; the resolve reprojects the previous frame's history along it (`historyUV = uv − velocity`), neighbourhood-clamps to the current 3×3 to suppress ghosting/disocclusion, and blends. Motion vectors are jitter-free so the jitter cancels in accumulation. Per-node previous-world-matrix tracking feeds rigid + animated motion (skinned deformation is camera-motion-only in v1); particles render after the resolve, kept out of history. `--no-taa` reverts to the raw image, `--debug-velocity` visualises the buffer - **Frustum culling (camera + shadow casters)** — built on a reusable fat-AABB BVH (`AabbBvh`, the same core the physics broadphase and static-mesh triangle index use). Two stages: a **persistent scene BVH** (`SceneCuller`, an `AabbBvh` over rigid renderables) pre-culls each frame against the union of the camera frustum and every shadow caster's frustum, so off-screen nodes skip draw-building entirely (no UBO writes, no per-vertex bounds) — `O(log N + visible)` instead of `O(N)`; then a **precise per-pass cull** drops the survivors that fall outside a given pass's frustum (`buildDrawBuckets` for the camera, per-cascade/spot/point-face in the shadow pass). Frustums are 6 Gribb–Hartmann planes (Vulkan `[0,1]` depth) with a conservative positive-vertex AABB test (no false negatives). Deformable (skinned/morph) meshes skip the coarse BVH (bind-pose bounds under-cover the animated pose) and rely on the precise stage's exact per-frame world bounds. The coarse union is a strict superset of what any pass keeps, so culling never drops a visible draw. Live overlay toggle + tracked/visible/culled counts; off submits everything (A/B + regression escape hatch) - **Progressive mesh level-of-detail (discrete → VIPM → VDPM)** — a from-scratch **attribute-aware Garland–Heckbert quadric-error simplifier** (`graphics/mesh_simplifier`) records an ordered edge-collapse stream per static mesh at load time; all levels index the *same* vertex buffer (only index data is added). The error quadric lives in **R⁵ (position + weighted UV)**, so collapses that would stretch the texture parameterisation are ordered *last*; **position welding** restores connectivity across glTF's seam-split vertices, a **wedge-preserving emit** keeps each corner's own UV (nearest-wedge), and a **chart veto** stops a collapse from crossing a UV/normal seam. That one collapse stream drives three selectable modes (overlay: Discrete / Continuous / View-dependent): **Discrete** picks the coarsest whole-mesh level whose screen-space error fits a pixel budget; **Continuous (VIPM)** geomorphs the collapsing vertices' full render attributes into the exact next level to dissolve the pop; **View-dependent (VDPM)** promotes the stream to a per-instance **vertex forest + active front** that refines *different regions of one mesh to different detail* each frame — from four screen-space channels (geometry, UV-seam, shading-normal, tangent) plus silhouette boost and a conservative back-face gate, with a joint refinement-only foldover/coverage repair — so it matches the discrete mesh's silhouette and shading at a fraction of the triangles. Overlay toggle + mode selector + pixel error budget slider + triangles-drawn readout + a per-LOD debug tint; `--lod-mode discrete|continuous|view-dependent` selects the starting mode at launch. VDPM draws are issued via **`drawIndexedIndirect`** from a per-instance indirect-command buffer (the count on the GPU) — the plumbing the GPU-driven front consumes; every other draw stays direct. A **GPU-driven front** backend (the **"GPU-driven front" overlay checkbox** in the Mesh LOD panel — a reload-free runtime toggle, needs `--lod-mode view-dependent` and a compute-capable device; shown "unsupported" otherwise) runs the whole per-frame front lifecycle — score, refine/coarsen, foldover/coverage repair, and seam-preserving emit — on the GPU in compute, and the draw consumes the GPU-emitted index/indirect buffers directly (the per-instance CPU front work is skipped); the CPU front is retained as an automatic per-mesh fallback and the same-camera A/B reference. It is **on by default** wherever the device supports it; force it with `--vdpm-gpu` or disable it with `--no-vdpm-gpu` (repeated flags are last-one-wins). See [`docs/lod.md`](docs/lod.md) -- **Debug + profiling overlay (Dear ImGui)** — a runtime overlay (Dear ImGui 1.92 on the Vulkan dynamic-rendering backend, drawn into the swapchain after post-process) toggled with **F1** (`--overlay` to start visible). Shows a **CPU frame-time/FPS plot** and **per-pass GPU timings** via a timestamp `VkQueryPool` (`GpuProfiler`, with graceful fallback when the device/queue doesn't support timestamps), plus a **live tunables panel** (`RenderTunables`) for TAA (history blend, sharpen, on/off), frustum culling (on/off + tracked/visible/culled counts), mesh LOD (on/off + mode + pixel error budget + triangles-drawn + a reload-free GPU-driven-front backend toggle), a **Shadows (SH-01)** panel (per shadow-view-family and per physical slot: raster passes, drawn/candidate draws + triangles, per-view LOD histograms, and the family's GPU time), the debug-view dropdown (incl. a **LOD tint** (`--debug-lod`), a **Shadow LOD tint** (`--debug-shadow-lod`, with `--no-shadow-lod` as the full-detail control and `--shadow-budget` / `--shadow-ratio` to sweep the calibration — see `tools/shadow_lod_sweep.sh`, with `--shadow-focus :` to pick the view it follows — e.g. `cascade:3`, `point:0:4` — resolved once at startup to that slot's logical view and then followed across slot compaction) that colours each mesh by the level ONE shadow view picked for it — the view focused in the Shadows panel, or cascade 0 by default, since after SH-03 a caster holds a different level per view — with neutral grey for meshes that view has no level for, and a **Joints** view — `--debug-joints` — that replaces the scene mesh with a per-link RGB axis gizmo + "index: bone-name" labels to identify ragdoll joints for hinge authoring) + no-shadows, bloom/diffuse-IBL/specular-IBL/sun-intensity, and particle emitter rate/lifetime/size — all editable without a recompile. Camera input is suppressed while a widget is being driven +- **Debug + profiling overlay (Dear ImGui)** — a runtime overlay (Dear ImGui 1.92 on the Vulkan dynamic-rendering backend, drawn into the swapchain after post-process) toggled with **F1** (`--overlay` to start visible). Shows a **CPU frame-time/FPS plot** and **per-pass GPU timings** via a timestamp `VkQueryPool` (`GpuProfiler`), which distinguishes a device that cannot time (zero `timestampPeriod` / `timestampValidBits`, reported once at startup with both numbers) from a ring slot that has nothing to report yet — the panel says which. Every pass stamps both boundaries at bottom-of-pipe, so the values are consecutive deltas on one timeline, and deltas are modular in the queue's `timestampValidBits` (Vulkan defines timestamp overflow as wrapping inside that width). The figure below the rows is labelled **measured pass sum**, not a total: it adds the instrumented passes only, plus a **live tunables panel** (`RenderTunables`) for TAA (history blend, sharpen, on/off), frustum culling (on/off + tracked/visible/culled counts), mesh LOD (on/off + mode + pixel error budget + triangles-drawn + a reload-free GPU-driven-front backend toggle), a **Shadows (SH-01)** panel (per shadow-view-family and per physical slot: raster passes, drawn/candidate draws + triangles, per-view LOD histograms, and the family's GPU time), the debug-view dropdown (incl. a **LOD tint** (`--debug-lod`), a **Shadow LOD tint** (`--debug-shadow-lod`, with `--no-shadow-lod` as the full-detail control and `--shadow-budget` / `--shadow-ratio` to sweep the calibration — see `tools/shadow_lod_sweep.sh`, with `--shadow-focus :` to pick the view it follows — e.g. `cascade:3`, `point:0:4` — resolved once at startup to that slot's logical view and then followed across slot compaction) that colours each mesh by the level ONE shadow view picked for it — the view focused in the Shadows panel, or cascade 0 by default, since after SH-03 a caster holds a different level per view — with neutral grey for meshes that view has no level for, and a **Joints** view — `--debug-joints` — that replaces the scene mesh with a per-link RGB axis gizmo + "index: bone-name" labels to identify ragdoll joints for hinge authoring) + no-shadows, bloom/diffuse-IBL/specular-IBL/sun-intensity, and particle emitter rate/lifetime/size — all editable without a recompile. Camera input is suppressed while a widget is being driven - **Reproducible frame capture** — `--capture ` writes the numbered frame (`--capture-frame N`, counted in frames rather than seconds, so any machine captures the same render ordinal — identical *content* additionally needs a static scene, since animation and physics still advance on wall-clock `dt`) and exits (non-zero if the file could not be written), copying the **final swapchain image** — post-process and overlay included — straight before present. Swapchain `TRANSFER_SRC` is requested only when capture is asked for, after checking the surface supports it; 8-bit BGRA/RGBA formats are supported and anything else is rejected rather than guessed. With `--no-lod` (full detail, forward *and* shadow selection) it makes an A/B pair, which is how the shadow-LOD reference images in [`docs/acceptance-testing.md`](docs/acceptance-testing.md) are regenerated - **Runtime logging** — diagnostics route through `core/log.hpp` with `debug`/`info`/`warn`/`error`/`off` levels and categories (`app`, `general`, `gltf`, `physics`, `ragdoll`, `render`). `FE_LOG` controls the global threshold and per-category overrides, e.g. `FE_LOG=ragdoll:debug` for ragdoll settle diagnostics or `FE_LOG=render:debug` for Vulkan extension dumps - **Keyframe animation** with per-channel interpolation (LINEAR with SLERP for quaternions, STEP, CUBICSPLINE with in/out tangents) across rotation, translation, scale, and morph weight channels; looping playback; runtime animation selection via `AnimationState` diff --git a/docs/lod.md b/docs/lod.md index 0c76411..f43b415 100644 --- a/docs/lod.md +++ b/docs/lod.md @@ -914,8 +914,12 @@ at a fraction of the triangles. The remaining residuals and follow-ons, in rough (full / apply-only / zero-split), shuffled order, N=1, a job-array growth boundary, and two frame slots. **Measured (state-fair GPU-timestamp benchmark, 13 fronts, `[.][gpu][BatchBench]`): apply serial 3.07 → batched 0.25 ms (~12×), repair serial 4.99 → batched 0.41 ms (~12×)** — the serialised multi-front cost - collapses toward the concurrent floor. (The benchmark is authoritative because the in-app `VdpmCompute` - GPU timestamp reads `gpuValid=false` on heavier multi-front frames.) 0-VUID on TransmissionTest + + collapses toward the concurrent floor. (The benchmark was authoritative because the in-app `VdpmCompute` + GPU timestamp read `gpuValid=false` on heavier multi-front frames — **now explained and fixed**: the + readback treated `VK_NOT_READY` as failure, which a frame containing any pass that did not run + always produces, so EVERY in-app per-pass timing was suppressed rather than these frames + specifically. See `render/gpu_profiler.cpp`. The benchmark numbers above stand; the in-app timing is + now usable as a cross-check.) 0-VUID on TransmissionTest + DamagedHelmet + DamagedHelmetBlend (`--vdpm-gpu`; AlphaBlendModeTest sits below the VDPM eligibility threshold, so it does not exercise this path). - **Apply+repair FUSION — SKIPPED (complexity/value judgment).** A fused kernel (apply then repair per diff --git a/docs/onboarding.md b/docs/onboarding.md index 87d276a..b803fa5 100644 --- a/docs/onboarding.md +++ b/docs/onboarding.md @@ -556,7 +556,11 @@ The render layer is where most difficult bugs live. (dynamic rendering, after post-process) and forwards `WantCaptureMouse/Keyboard` so the main loop can gate camera input. Non-movable (owns ImGui global state). - `GpuProfiler`: timestamp `VkQueryPool` ring. Each pass writes a begin/end pair; results are read - back a frame-cycle later into a `FrameStats`. Disabled gracefully when timestamps are unsupported. + back a frame-cycle later into a `FrameStats`. Disabled gracefully when timestamps are unsupported — + and `FrameStats::gpuTiming` says WHICH of unsupported / warming-up / valid applies, because + collapsing those three into one "unavailable" message is how a readback bug (see § Sharp Edges) + survived as a supposed driver limitation. The pure half — availability policy and tick arithmetic — + is the free `resolveTimestampWords`, unit-tested without a GPU. - `RenderTunables` (`render_tunables.hpp`): the live, overlay-editable render parameters (TAA, debug view, bloom/IBL/sun, particle scales, cloth solver substeps/compliance/damping/gravity/wind). Seeded from `constants.hpp` + the CLI debug flags; the `Renderer` reads it every frame instead of @@ -581,7 +585,11 @@ Per-frame render order: 12. draw the ImGui debug overlay over the swap image, then transition it to present 13. submit and present -Each GPU pass is bracketed by `GpuProfiler` timestamp writes; the results feed the overlay one frame-cycle later. +Each GPU pass is bracketed by `GpuProfiler` timestamp writes — both boundaries at bottom-of-pipe, so +the per-pass values are consecutive deltas along one timeline rather than a mix of conventions — and +the results feed the overlay one frame-cycle later. The panel's figure is labelled **"Measured pass +sum"**, not "Total": it adds the instrumented passes only, and a frame also contains setup, present +and anything nobody bracketed, so it is not GPU frame latency. Interesting detail: shadow rendering replays compatible draw commands through different pipelines. Skinning and morph targets still run in the shadow vertex shader so animated @@ -1177,6 +1185,16 @@ the same change — most have a test or guard that will catch you, but not all. ## Sharp Edges - `graphics/` must remain Vulkan-free, and `render/`/`scene/` are siblings that meet only through `graphics/` — enforced by the `layering_guards` CTest case (`cmake/check_layering.cmake`): `graphics/` and `scene/` *headers* must not include `render/`, and `render/` headers must not include `scene/` (CR-09). The scene reaches the renderer through the Vulkan-free `graphics/renderable_scene.hpp` `RenderableScene` interface, not a concrete type. Shared GPU data-layout limits live in `graphics/gpu_limits.hpp` so graphics headers can size arrays without reaching into `render/`. Graphics `.cpp` files may still include `render/resources.hpp` to allocate GPU resources. +- **`VK_NOT_READY` from `vkGetQueryPoolResults` is not an error — it is the expected result of a + polling read.** Without `VK_QUERY_RESULT_WAIT_BIT` the call returns it whenever ANY query in the + requested range is unavailable, and with `VK_QUERY_RESULT_WITH_AVAILABILITY_BIT` the per-query + availability words are written anyway, which is the whole point of asking for them. `GpuProfiler` + treated it as failure and returned early, so per-pass GPU timings were dead on every device and + every driver — a frame always has passes that did not run (no transmissive draw, no spot light, no + VDPM front), and their queries stay reset and unavailable for that slot. The symptom ("GPU + timestamps unavailable" under both MoltenVK and KosmicKrisp) read as a platform limitation and was + parked as one for months. If you add a query-pool read, decide explicitly whether you are polling + (accept NotReady, filter on availability) or waiting (`WAIT` bit, and accept the stall). - Vulkan-Hpp is built with `VULKAN_HPP_NO_CONSTRUCTORS`; use designated initializers. - Vulkan structs often contain pointers. Keep pointed-to arrays and descriptor infos alive until the Vulkan call using them has returned. diff --git a/docs/review-order.md b/docs/review-order.md index dd5007f..6a15d46 100644 --- a/docs/review-order.md +++ b/docs/review-order.md @@ -212,7 +212,7 @@ Read these first when a change touches build configuration, CI, or local tooling | `render/particle_system.hpp` + `particle_system.cpp` | Renderer-owned GPU particle system. Pooled SSBO partitioned per emitter; compute sim (`particle_simulate.comp`) → buffer barrier → instanced additive billboards into HDR (soft particles via sampled scene depth). Records after the TAA resolve (un-jittered, kept out of history), before post-process. | | `render/soft_body_system.hpp` + `soft_body_system.cpp` | **High-attention.** GPU XPBD cloth solver. Descriptor-free: four compute pipelines (`cloth_predict`/`solve`/`collide`/`finalize`) take every buffer as a `bufferDeviceAddress` pointer in the push constant — per-cloth particle/constraint buffers + the render vertex buffer + a per-frame collider buffer, all `eShaderDeviceAddress`. `recordSolve` = per-substep `predict → per-colour solve → collide`, then `finalize` writes solved positions + normals (recomputed from the per-cloth CSR adjacency, arbitrary topology) into the cloth's storage vertex buffer (compute-write → vertex-input-read barrier). Reads `ClothSimParams` (overlay; compliance is a global multiplier on each constraint's authored per-type stiffness); colliders from `PhysicsWorld::gatherColliders`. Cloths come from the `-c` demo or glTF `extras.Cloth`. | | `render/render_tunables.hpp` | Plain struct of live, overlay-editable render params (TAA, **`cullingEnabled`**, **`lodEnabled`/`lodPixelErrorBudget`**, debug view, bloom/IBL/sun, particle scales) + the `DebugView` enum (incl. `Lod` and `ShadowLod` tints and `Joints` — the latter has no shader branch: it suppresses the scene mesh and draws the ragdoll joint gizmo/labels instead, and maps to `None` for the shader, so keep it LAST after any new shader-backed view) + `kDebugViewNames` beside it with a count `static_assert`, so adding a view without naming it fails to compile. Seeded from `constants.hpp` + CLI flags; the renderer reads it instead of the `constexpr`s. Read this first — it's the contract between the overlay and the renderer. | -| `render/gpu_profiler.hpp` + `gpu_profiler.cpp` | Timestamp `VkQueryPool` ring (`kMaxFramesInFlight` slots). `begin/end(pass)` write a pair; `resolve` reads the slot a cycle later (safe — the acquire timeline-wait guarantees that frame finished) into `FrameStats`. `slotUsed_` guards reading never-reset queries; `eWithAvailability` skips passes that didn't run. Disabled when `timestampPeriod==0` / `timestampValidBits==0`. `FrameStats` also carries the frustum-cull tracked/culled counts (populated in `collectDrawCommands`, shown a frame later) and `vdpmGpuAvailable` (B5c-3 — set there from `vdpmManager_ != nullptr`, i.e. device capability independent of whether the GPU front is currently active; drives the overlay's backend checkbox enable/label). | +| `render/gpu_profiler.hpp` + `gpu_profiler.cpp` | Timestamp `VkQueryPool` ring (`kMaxFramesInFlight` slots). `begin/end(pass)` write a pair, BOTH at bottom-of-pipe — one convention engine-wide, because a top-of-pipe begin fires while the previous pass is still draining and two adjacent sub-millisecond passes then each report time the other spent (the shadow families already stamped bottom-to-bottom, so the frame sum used to mix conventions). The trade is stated in the header: a bubble before a pass is charged to it. Deltas are MODULAR in the queue's `timestampValidBits` — Vulkan leaves the upper bits undefined and defines overflow as wrapping inside that width, so a decreasing raw pair is a wrap, not an anomaly. `resolve` reads the slot a cycle later (safe — the acquire timeline-wait guarantees that frame finished) into `FrameStats`. `slotUsed_` guards reading never-reset queries; `eWithAvailability` skips passes that didn't run. **`vk::Result::eNotReady` is the NORMAL result of that read and must not be treated as failure** — without `WAIT`, `vkGetQueryPoolResults` returns it whenever ANY query in the range is unavailable, and some always are (a pass that did not run leaves its pair reset and unwritten), while the availability words are still written. Bailing on it is what kept per-pass timing dark on every device for months and got the feature parked as a MoltenVK limitation. The arithmetic and the availability policy live in the free `resolveTimestampWords`, which is Vulkan-free and unit-tested (`tests/render/test_gpu_profiler.cpp`) — the GPU call is the only part that needs a device. `GpuTimingState` distinguishes Unsupported / WarmingUp / Valid so the overlay cannot report a live bug as a device limitation again. `FrameStats::gpuMeasuredPassSumMs` is named for what it is — the instrumented passes only, not frame latency. Disabled (with a WARN naming both numbers) when `timestampPeriod==0` / `timestampValidBits==0`. `FrameStats` also carries the frustum-cull tracked/culled counts (populated in `collectDrawCommands`, shown a frame later) and `vdpmGpuAvailable` (B5c-3 — set there from `vdpmManager_ != nullptr`, i.e. device capability independent of whether the GPU front is currently active; drives the overlay's backend checkbox enable/label). | | `render/debug_overlay.hpp` + `debug_overlay.cpp` | Dear ImGui owner (context + GLFW/Vulkan backends, dynamic rendering). `buildUi(stats, tunables)` builds the panels (incl. the **Culling** group: `cullingEnabled` toggle + tracked/visible/culled readout); `record` draws into the swap image (loadOp Load). `drawWorldLabels(labels, viewProj)` projects world-anchored `DebugLabel`s (ragdoll joint index:name) into the ImGui **foreground draw list** — call it after buildUi and after the frame's `viewProj` is finalised; it maps via `DisplaySize` (retina-correct, not the pixel extent). The Mesh LOD panel's view-dependent block carries the **B5c-3 "GPU-driven front" backend checkbox** (writes `tunables.vdpmGpuBackend`, a reload-free flip — see the manager construction invariant); gated on `stats.vdpmGpuAvailable`, else a disabled checkbox + explicit "(unsupported on this device)" label rather than a silent disable. The **Shadows (SH-01)** panel prints `FrameStats::shadow` per view family and physical slot: raster passes + drawn/candidate draws and triangles (work) kept visually separate from the L0..L3+ columns (LOD selections of DRAWN casters — rejected candidates are never resolved and have no level — counted once per *logical* view, since the self families rasterise twice and are sampled once). Note the two d/c pairs mean different things since SH-03: draws are drawn-over-offered (the cull yield), triangles are drawn-over-FULL-DETAIL (culling and LOD together). Clicking a slot row writes `RenderTunables::shadowViewFocus` — the row's LOGICAL identity plus its group, never its slot, because punctual/self slots compact and a slot-keyed focus would silently retarget to the replacement light (worse once slice 5's tint reads the same focus: the panel shows a completed ring frame while the tint samples the current one). `ShadowFrameStats::focused` therefore SEARCHES the group for that identity and returns the slot it was found in, which is what the header labels. Three outcomes are worded differently on purpose: the rollup, "selection is not a valid view" (structurally unaddressable — `addressable()` also rejects an identity whose KIND cannot occur in the group, e.g. a cascade id under Spot, which would otherwise look valid and then never be found), and "not present in this frame" (well-formed but not found — deliberately silent on whether it returns, since a deleted light and a view that merely did not rasterise are indistinguishable without scene liveness). `beginRasterPass` validates BEFORE mutating and refuses a second, different identity on a row (returning false, changing nothing); the shadow pass treats that as terminal, because merging two views' counters under one name yields a row that reads like a measurement of something that never existed. Column weights are explicit — proportional sizing starved the level columns to one ellipsised character. Timing cells come from `shadowProfilePass(group)`; a slot row shows an em dash (timestamps bracket a family, not a map), and the whole panel shows "pending" while `shadowValid` is false rather than a zeroed table. Point rows decode the flat slot back to `slot / 6` + `slot % 6` and are labelled *slots*, not lights — slot assignment is per-frame order, not an identity. Non-movable (ImGui global state). ImGui core plus GLFW/Vulkan backends come from the vcpkg `imgui[glfw-binding,vulkan-binding]` manifest dependency; `cmake/fireengine_imgui.cmake` wraps the ImGui archive so `fireengine` keeps direct ownership of Vulkan/GLFW linkage. | | `render/renderer.hpp` + `src/render/renderer.cpp` | **Capstone.** `drawFrame` = named phases (`updateFrameLighting`/`collectDrawCommands`/`recordShadowPass`/`recordForwardPass`/`recordTransmissionPass`/`recordPostProcessing`) plus the inline `taa_.recordResolve`, `recordParticlePass`, `overlay_.record`, and `transitionSwapchainToPresent` (present-split: post-process leaves the swap image in colour-attachment layout). Each pass is wrapped in a `profiler_` scope. Reads `tunables_` for debug view, IBL/bloom/sun, TAA params, particle scales. Study pass ordering, the jitter-free `currentViewProj_`/`previousViewProj_` matrices, `recreateSwapchain` + `buildGlobalDescriptorRequest`. `collectDrawCommands` runs the coarse frustum pre-cull (builds camera + shadow frustums → `scene.cull`); `buildDrawBuckets` does the precise per-camera cull. **Forward command-order invariant:** when a forward pipeline becomes active, push set 0 before binding allocated sets 1/2 through that same layout; higher-set binds preserve set 0. Keep this in sync with transmission recording. | diff --git a/docs/roadmap.md b/docs/roadmap.md index cc2f2e6..6dbcad8 100644 --- a/docs/roadmap.md +++ b/docs/roadmap.md @@ -114,8 +114,6 @@ the plan; the priority order is its § Suggested priority. containing one falls back to the legacy depth range for every directional cascade. Closing this needs a conservative simulation or authored envelope for storage geometry; until then the fallback is marked `LegacyStaleFallback` in the fit result and the panel, not silently taken. -- **GPU-timestamp diagnostics** — parked before SH-07 (invalid timestamps observed under both - MoltenVK and KosmicKrisp, so not driver-specific). SH-07's per-view cost claims want it working. - **SH-04's proxy half** — `Object::shadowGeometry` was removed rather than documented as unsafe, so there is currently no way to author a shadow proxy at all. diff --git a/docs/shadowplans.md b/docs/shadowplans.md index 090f019..bb9a937 100644 --- a/docs/shadowplans.md +++ b/docs/shadowplans.md @@ -1014,8 +1014,10 @@ depth span is no longer a fixed constant. Four things stay open behind it and ar roadmap rather than blocking it: the historical half-ellipse (unexplained, and NOT a depth clip — measured), the cloth `LegacyStaleFallback` (needs a conservative envelope for storage geometry), SH-04's proxy half, and SH-05's masked-LOD policy (which needs a cutout carrying a real LOD chain -before its pin can even be priced). The GPU-timestamp diagnostics branch is still parked and should -land before SH-07's cost claims. +before its pin can even be priced). The GPU-timestamp diagnostics SH-07's cost claims need are now +WORKING (branch `gpu-timestamp-diagnostics`, 2026-08-05): the readback treated `VK_NOT_READY` as a +failed read, so the panel said "unavailable" on every device — our bug, not MoltenVK's. Per-pass GPU +milliseconds are live in the overlay, which SH-07 should use rather than re-deriving cost. **The post-merge sweep is done** (2026-08-04): SH-05 and SH-06 were each measured without the other and move the same figures in opposite directions, so the table in `render/constants.hpp` is now the diff --git a/include/fire_engine/render/gpu_profiler.hpp b/include/fire_engine/render/gpu_profiler.hpp index 78522e8..7538a63 100644 --- a/include/fire_engine/render/gpu_profiler.hpp +++ b/include/fire_engine/render/gpu_profiler.hpp @@ -2,6 +2,7 @@ #include #include +#include #include #include @@ -32,8 +33,8 @@ enum class ProfilePass : uint32_t VdpmEmit, // The five shadow families, timed separately (SH-01): a single Shadow total could not say // whether a change moved cost between cascades, punctual lights, or self-shadowing. They are - // disjoint spans — there is no outer Shadow timer to overlap them — so the frame total sums - // them like any other pass. + // disjoint spans — there is no outer Shadow timer to overlap them — so the measured-pass sum + // adds them like any other pass. ShadowCascades, ShadowWorldOnly, ShadowSelf, @@ -90,10 +91,11 @@ static_assert(kProfilePassNames.size() == kProfilePassCount, return ProfilePass::Count; } -// Whether a pass's time belongs in the frame total. The four VDPM breakdown rows are SUBRANGES of -// VdpmCompute, so summing them alongside it double-counts that work; every other pass is a disjoint -// span and contributes. Pure, so the overlay and any future consumer share one policy. -[[nodiscard]] constexpr bool profilePassContributesToTotal(ProfilePass pass) noexcept +// Whether a pass's time belongs in the measured-pass sum. The four VDPM breakdown rows are +// SUBRANGES of VdpmCompute, so summing them alongside it double-counts that work; every other pass +// is a disjoint span and contributes. Pure, so the overlay and any future consumer share one +// policy. +[[nodiscard]] constexpr bool profilePassContributesToMeasuredSum(ProfilePass pass) noexcept { switch (pass) { @@ -107,6 +109,27 @@ static_assert(kProfilePassNames.size() == kProfilePassCount, } } +// What the GPU timing half of FrameStats is currently able to say. Three states, kept DISTINCT +// because they call for different responses and the overlay used to render all of them as +// "GPU timestamps unavailable" — which is how a live bug in the readback (see resolve()) spent +// months looking like a device limitation, on two different drivers. +enum class GpuTimingState : std::uint8_t +{ + // The device or its graphics queue cannot write timestamps (zero timestampPeriod or zero + // timestampValidBits). Nothing will ever arrive; the overlay should say so and stop. + Unsupported, + // Supported, but this ring slot has nothing to report yet: it has not been reset a full cycle + // ago, or no span in it had both ends available. Transient — the next cycles fill in. + WarmingUp, + // At least one pass resolved to a real span. `passMs` is meaningful (0 for passes that did not + // run this cycle). + Valid, +}; + +// Queries per frame slot: a begin and an end for every pass. Public because the pure resolver below +// is specified in terms of it, and its tests build buffers of exactly this shape. +inline constexpr std::uint32_t kProfileQueriesPerFrame = kProfilePassCount * 2; + // Resolved per-frame timings consumed by the overlay. struct FrameStats { @@ -116,8 +139,19 @@ struct FrameStats // didn't run this cycle (e.g. transmission with no transmissive draws) // reports 0. std::array passMs{}; - float gpuTotalMs{0.0f}; - bool gpuValid{false}; + // Sum of the INSTRUMENTED passes, and deliberately not called a total: a frame also contains + // command-buffer setup, present, the gaps between passes, and any pass nobody bracketed. + // Reading it as GPU frame latency would overstate how much of the frame is accounted for here. + // A dedicated outer span is the honest way to get that number if it is ever wanted. + float gpuMeasuredPassSumMs{0.0f}; + // ONE field for the timing state, with the boolean derived from it — the overlay and the VDPM + // log line both used to read a bare `gpuValid`, which could not distinguish "this device + // cannot" from "not yet". + GpuTimingState gpuTiming{GpuTimingState::Unsupported}; + [[nodiscard]] bool gpuValid() const noexcept + { + return gpuTiming == GpuTimingState::Valid; + } // SH-01 shadow diagnostics from the COMPLETED frame whose ring slot this is (see // Renderer::shadowStatsRing_). `shadowValid` is false during ring warm-up and is entirely // independent of `gpuValid` — the counters are CPU-side and survive a device with no timestamp @@ -206,20 +240,26 @@ class GpuProfiler // Reset this frame's query range. Must be recorded outside a render pass, // before any begin()/end() for the frame. void beginFrame(vk::CommandBuffer cmd, uint32_t frameIndex); + + // Both boundaries stamp at BOTTOM-of-pipe, and that uniformity is the point. + // + // A top-of-pipe begin fires when the command reaches the top of the pipe, which on a pipelined + // GPU is while the PREVIOUS pass is still draining — so the span silently absorbs part of its + // predecessor, and two adjacent sub-millisecond passes each report time the other spent. The + // shadow families already stamped bottom-to-bottom for exactly that reason, which left the + // measured-pass sum adding two conventions together. With one convention every passMs is a + // consecutive delta along a single timeline, which is what makes comparing and summing them + // honest. + // + // The cost of the convention, stated so nobody rediscovers it as a bug: a pass's span starts + // when the preceding work DRAINED, so a bubble before it is charged to it. That is the right + // default for "what did this pass cost the frame". void begin(vk::CommandBuffer cmd, uint32_t frameIndex, ProfilePass pass) const; void end(vk::CommandBuffer cmd, uint32_t frameIndex, ProfilePass pass) const; - // Write a pass's begin (`end`=false) or end (`end`=true) query at BOTTOM-of-pipe. begin() uses - // top-of-pipe, which is fine for a coarse whole-pass span but bleeds badly across adjacent - // SUB-millisecond stages (a stage's top-of-pipe begin fires while the prior stage is still - // draining). For the VDPM per-stage breakdown the boundaries are stamped bottom-of-pipe on BOTH - // sides — the shared boundary written as one stage's end AND the next stage's begin — so each - // resolved passMs is a clean consecutive delta. resolve() is unchanged (end − begin per pass). - void stampBottom(vk::CommandBuffer cmd, uint32_t frameIndex, ProfilePass pass, bool end) const; - - // Read back the results currently held in `frameIndex`'s slot (written a full - // ring-cycle ago) into out.passMs / gpuTotalMs / gpuValid. No-op when timing - // is unsupported. + // Read back the results currently held in `frameIndex`'s slot (written a full ring-cycle ago) + // into out.passMs / gpuMeasuredPassSumMs / gpuTiming. Leaves `Unsupported` when the device + // cannot time. void resolve(uint32_t frameIndex, FrameStats& out) const; [[nodiscard]] bool enabled() const noexcept @@ -234,15 +274,52 @@ class GpuProfiler return frameIndex * kQueriesPerFrame + static_cast(pass) * 2 + (end ? 1u : 0u); } - static constexpr uint32_t kQueriesPerFrame = kProfilePassCount * 2; + static constexpr uint32_t kQueriesPerFrame = kProfileQueriesPerFrame; const vk::raii::Device* device_{nullptr}; vk::raii::QueryPool pool_{nullptr}; float timestampPeriodNs_{0.0f}; + // Meaningful low bits of a timestamp on the graphics queue. KEPT, not merely checked against + // zero at construction: the delta arithmetic is modulo 2^this. + std::uint32_t timestampValidBits_{0}; bool enabled_{false}; // A slot must be reset (beginFrame) at least once before its results may be // read, or validation flags reading uninitialised queries on the first cycle. std::array slotUsed_{}; }; +// The width of a meaningful timestamp, as a mask. Vulkan guarantees only the LOW +// `timestampValidBits` of a query result carry data — the upper bits are undefined — and it defines +// overflow as wrapping to zero within that width. So a delta is modular arithmetic in +// 2^timestampValidBits, not a 64-bit subtraction. +// +// The 64 case is branched, not shifted: `1ull << 64` is undefined behaviour, and a device reporting +// the full width is the common case (this Mac's MoltenVK does). +[[nodiscard]] constexpr std::uint64_t timestampMask(std::uint32_t timestampValidBits) noexcept +{ + return timestampValidBits >= 64 ? ~std::uint64_t{0} + : (std::uint64_t{1} << timestampValidBits) - 1; +} + +// The PURE half of resolve(): turn one slot's interleaved query words into per-pass milliseconds. +// +// `words` is `kProfileQueriesPerFrame * 2` entries — for each pass, the begin query's value then +// its availability, then the end query's value and availability — exactly the layout +// `VK_QUERY_RESULT_WITH_AVAILABILITY_BIT` writes with a two-word stride. A span counts only when +// BOTH ends are available; anything else leaves that pass at 0, and the VDPM breakdown rows are +// excluded from the SUM because they are subranges of VdpmCompute +// (`profilePassContributesToMeasuredSum`). +// +// `timestampValidBits` comes from the graphics queue family. Both values are MASKED to that width +// and the delta taken modulo it, which is what makes an end value numerically below its begin a +// legitimate WRAP rather than an anomaly — the reason there is no "malformed span" count here. A +// queue reporting fewer than 64 bits is not exotic, and on one the raw upper bits are undefined, so +// comparing or subtracting the full words would manufacture garbage spans on exactly those devices. +// +// Free and Vulkan-free by design: the arithmetic and the availability policy are where the mistakes +// live, and this way they are tested headlessly (tests/render/test_gpu_profiler.cpp) instead of +// only on whatever GPU the developer happens to have. +void resolveTimestampWords(std::span words, float timestampPeriodNs, + std::uint32_t timestampValidBits, FrameStats& out) noexcept; + } // namespace fire_engine diff --git a/src/render/debug_overlay.cpp b/src/render/debug_overlay.cpp index 83db624..1c5445c 100644 --- a/src/render/debug_overlay.cpp +++ b/src/render/debug_overlay.cpp @@ -251,7 +251,7 @@ void drawShadowDiagnostics(const FrameStats& stats, RenderTunables& tunables) // "n/a", not the word: the column is narrow enough that "unavailable" clipped, and a // clipped diagnostic is one nobody reads. The banner above already says why. char timing[32] = "n/a"; - if (stats.gpuValid) + if (stats.gpuValid()) { // A family that never rasterised has no bracketed span this frame — its resolved // time is 0 because nothing ran, which is a different fact from "not measured". @@ -295,7 +295,7 @@ void drawShadowDiagnostics(const FrameStats& stats, RenderTunables& tunables) // The five families are disjoint spans (there is no outer shadow timer), so their sum IS // the frame's shadow time. char totalTiming[32] = "n/a"; - if (stats.gpuValid) + if (stats.gpuValid()) { float shadowMs = 0.0f; for (std::size_t g = 0; g < kShadowViewGroupCount; ++g) @@ -405,7 +405,7 @@ void DebugOverlay::buildUi(const FrameStats& stats, RenderTunables& tunables) 0.0f, 33.3f, ImVec2(0.0f, 50.0f)); ImGui::Separator(); - if (stats.gpuValid) + if (stats.gpuValid()) { ImGui::Text("GPU passes (ms):"); if (ImGui::BeginTable("gpu", 2, ImGuiTableFlags_SizingStretchProp | ImGuiTableFlags_RowBg)) @@ -420,15 +420,28 @@ void DebugOverlay::buildUi(const FrameStats& stats, RenderTunables& tunables) } ImGui::TableNextRow(); ImGui::TableNextColumn(); - ImGui::TextUnformatted("Total"); + // NOT "Total": this is the sum of the passes that are INSTRUMENTED, and the frame + // contains work that is not — command-buffer setup, present, anything between passes, + // and any pass nobody bracketed. Calling it a total invites reading it as GPU frame + // latency, which it is not. A dedicated outer span would be the honest way to show that + // number; until one exists the label says what the figure actually is. + ImGui::TextUnformatted("Measured pass sum"); ImGui::TableNextColumn(); - ImGui::Text("%.3f", stats.gpuTotalMs); + ImGui::Text("%.3f", stats.gpuMeasuredPassSumMs); ImGui::EndTable(); } } + else if (stats.gpuTiming == GpuTimingState::Unsupported) + { + // The device genuinely cannot: zero timestampPeriod or zero queue timestampValidBits. The + // startup WARN carries both numbers. + ImGui::TextDisabled("GPU timestamps unsupported on this device"); + } else { - ImGui::TextDisabled("GPU timestamps unavailable"); + // Supported, nothing to show yet. Distinguished from the above because the two used to + // render identically, and a readback bug spent months looking like a device limitation. + ImGui::TextDisabled("GPU timings warming up..."); } ImGui::Separator(); diff --git a/src/render/gpu_profiler.cpp b/src/render/gpu_profiler.cpp index d95be03..60566c0 100644 --- a/src/render/gpu_profiler.cpp +++ b/src/render/gpu_profiler.cpp @@ -1,5 +1,6 @@ #include +#include #include namespace fire_engine @@ -13,12 +14,19 @@ GpuProfiler::GpuProfiler(const Device& device) // The graphics queue must support timestamps for our writeTimestamp2 calls. const auto queueFamilies = device.physicalDevice().getQueueFamilyProperties(); - const uint32_t validBits = queueFamilies[device.graphicsFamily()].timestampValidBits; + timestampValidBits_ = queueFamilies[device.graphicsFamily()].timestampValidBits; + const uint32_t validBits = timestampValidBits_; if (timestampPeriodNs_ == 0.0f || validBits == 0) { - // Timestamps unsupported (some MoltenVK setups) — stay disabled; the - // overlay falls back to CPU frame timing only. + // Genuinely unsupported — the overlay falls back to CPU frame timing only. Logged at WARN + // with both numbers, because this is the ONLY reason per-pass GPU timings should ever be + // missing, and for months it was blamed for a readback bug instead (see resolve()). + log::warn( + log::category::render, + "GPU timestamps unsupported on this device (timestampPeriod={} ns, graphics-queue " + "timestampValidBits={}) — per-pass GPU timings disabled", + timestampPeriodNs_, validBits); return; } @@ -28,6 +36,9 @@ GpuProfiler::GpuProfiler(const Device& device) }; pool_ = vk::raii::QueryPool(*device_, ci); enabled_ = true; + log::debug(log::category::render, + "GPU timestamps enabled: timestampPeriod={} ns, validBits={}, {} queries per frame", + timestampPeriodNs_, validBits, kQueriesPerFrame); } void GpuProfiler::beginFrame(vk::CommandBuffer cmd, uint32_t frameIndex) @@ -46,7 +57,8 @@ void GpuProfiler::begin(vk::CommandBuffer cmd, uint32_t frameIndex, ProfilePass { return; } - cmd.writeTimestamp2(vk::PipelineStageFlagBits2::eTopOfPipe, *pool_, + // BOTTOM-of-pipe, like end() — see the header for why the two boundaries share one convention. + cmd.writeTimestamp2(vk::PipelineStageFlagBits2::eBottomOfPipe, *pool_, queryIndex(frameIndex, pass, false)); } @@ -60,64 +72,108 @@ void GpuProfiler::end(vk::CommandBuffer cmd, uint32_t frameIndex, ProfilePass pa queryIndex(frameIndex, pass, true)); } -void GpuProfiler::stampBottom(vk::CommandBuffer cmd, uint32_t frameIndex, ProfilePass pass, - bool end) const +void GpuProfiler::resolve(uint32_t frameIndex, FrameStats& out) const { + out.gpuTiming = GpuTimingState::Unsupported; + out.gpuMeasuredPassSumMs = 0.0f; + out.passMs.fill(0.0f); if (!enabled_) { return; } - cmd.writeTimestamp2(vk::PipelineStageFlagBits2::eBottomOfPipe, *pool_, - queryIndex(frameIndex, pass, end)); -} - -void GpuProfiler::resolve(uint32_t frameIndex, FrameStats& out) const -{ - out.gpuValid = false; - out.gpuTotalMs = 0.0f; - out.passMs.fill(0.0f); - if (!enabled_ || !slotUsed_[frameIndex]) + out.gpuTiming = GpuTimingState::WarmingUp; + if (!slotUsed_[frameIndex]) { return; // never reset yet (first cycle) — reading would be invalid } - // Two uint64s per query (timestamp value + availability). Availability lets us - // skip passes that didn't run this cycle (e.g. transmission with no draws) - // without the whole read failing. + // Two uint64s per query (timestamp value + availability), so an unavailable query is + // identifiable rather than fatal. constexpr uint32_t kStrideWords = 2; auto [result, data] = pool_.getResults( frameIndex * kQueriesPerFrame, kQueriesPerFrame, static_cast(kQueriesPerFrame) * kStrideWords * sizeof(uint64_t), kStrideWords * sizeof(uint64_t), vk::QueryResultFlagBits::e64 | vk::QueryResultFlagBits::eWithAvailability); - if (result != vk::Result::eSuccess) + + // eNotReady IS THE NORMAL RESULT HERE, and treating it as failure is the bug that kept this + // whole feature dark. Without VK_QUERY_RESULT_WAIT_BIT, vkGetQueryPoolResults returns + // VK_NOT_READY when ANY query in the range is unavailable — and some always are: a pass that + // did not run this frame (no transmissive draw, no spot light, no VDPM front) leaves its two + // queries reset and never written, so they stay unavailable for that slot. With + // VK_QUERY_RESULT_WITH_AVAILABILITY_BIT the per-query availability words are still written, + // which is the entire reason we ask for them — so a NotReady buffer is a PARTIAL result to + // filter, not a failed read. Bailing on it reported "unavailable" on every device and every + // driver, a symptom that looked like a MoltenVK limitation and was parked as one. + // + // Anything else IS a real error (a lost device, a bad range): leave the slot WarmingUp and say + // so rather than presenting whatever the buffer happens to hold. + if (result != vk::Result::eSuccess && result != vk::Result::eNotReady) + { + log::warn(log::category::render, "GPU timestamp readback failed for slot {}: {}", + frameIndex, vk::to_string(result)); + return; + } + + resolveTimestampWords(data, timestampPeriodNs_, timestampValidBits_, out); +} + +void resolveTimestampWords(std::span words, float timestampPeriodNs, + std::uint32_t timestampValidBits, FrameStats& out) noexcept +{ + constexpr std::size_t kStrideWords = 2; + out.gpuMeasuredPassSumMs = 0.0f; + out.passMs.fill(0.0f); + // No meaningful bits means no meaningful spans. The profiler refuses to enable in that case, so + // this is defensive — but a zero mask would otherwise turn every delta into 0 and report a + // frame of free passes, which is worse than reporting nothing. + if (timestampValidBits == 0) { - return; // results not ready yet (first cycle after create) — leave CPU-only + out.gpuTiming = GpuTimingState::WarmingUp; + return; + } + // A short buffer is a programming error at the call site, not something to half-read: report + // nothing rather than a total assembled from whatever fit. + if (words.size() < static_cast(kProfileQueriesPerFrame) * kStrideWords) + { + out.gpuTiming = GpuTimingState::WarmingUp; + return; } + const std::uint64_t mask = timestampMask(timestampValidBits); bool anyValid = false; - for (uint32_t p = 0; p < kProfilePassCount; ++p) + for (std::uint32_t p = 0; p < kProfilePassCount; ++p) { - const uint64_t beginVal = data[static_cast(p * 2 + 0) * kStrideWords]; - const uint64_t beginAvail = data[static_cast(p * 2 + 0) * kStrideWords + 1]; - const uint64_t endVal = data[static_cast(p * 2 + 1) * kStrideWords]; - const uint64_t endAvail = data[static_cast(p * 2 + 1) * kStrideWords + 1]; - if (beginAvail == 0 || endAvail == 0 || endVal < beginVal) + const std::size_t beginWord = static_cast(p) * 2 * kStrideWords; + const std::size_t endWord = beginWord + kStrideWords; + const std::uint64_t beginVal = words[beginWord]; + const std::uint64_t beginAvail = words[beginWord + 1]; + const std::uint64_t endVal = words[endWord]; + const std::uint64_t endAvail = words[endWord + 1]; + if (beginAvail == 0 || endAvail == 0) { - continue; // pass skipped this cycle, or wrapped — report 0 + continue; // pass did not run in this slot — report 0 } - const float ms = static_cast(endVal - beginVal) * timestampPeriodNs_ / 1.0e6f; + // MODULAR in the queue's timestamp width. Vulkan guarantees only the low + // `timestampValidBits` carry data and defines overflow as wrapping to zero inside that + // width, so `end < begin` on the raw words is a legitimate wrap, not an anomaly — and on a + // queue narrower than 64 bits the upper bits are undefined noise that must not reach the + // subtraction at all. Masking both ends and masking the difference handles both facts in + // one step: unsigned subtraction already wraps modulo 2^64, and the mask reduces it to + // 2^timestampValidBits. + const std::uint64_t ticks = ((endVal & mask) - (beginVal & mask)) & mask; + const float ms = static_cast(ticks) * timestampPeriodNs / 1.0e6f; out.passMs[p] = ms; // Only disjoint spans are summed: the VDPM breakdown rows sit INSIDE VdpmCompute, so adding - // them too would inflate the reported frame total by the whole VDPM cost whenever the - // single-front breakdown is populated. - if (profilePassContributesToTotal(static_cast(p))) + // them too would inflate the reported sum by the whole VDPM cost whenever the single-front + // breakdown is populated. + if (profilePassContributesToMeasuredSum(static_cast(p))) { - out.gpuTotalMs += ms; + out.gpuMeasuredPassSumMs += ms; } anyValid = true; } - out.gpuValid = anyValid; + out.gpuTiming = anyValid ? GpuTimingState::Valid : GpuTimingState::WarmingUp; } } // namespace fire_engine diff --git a/src/render/renderer.cpp b/src/render/renderer.cpp index 2613421..c85e527 100644 --- a/src/render/renderer.cpp +++ b/src/render/renderer.cpp @@ -1587,7 +1587,7 @@ void Renderer::drawFrame(Window& display, RenderableScene& scene, float dt) "VDPM GPU perf: record {:.3f} ms CPU | compute {:.3f} ms GPU (valid {}) | {} " "front(s), ~{} dispatches ({} apply + {} repair batched jobs), max {}/{} marked " "rounds", - stats_.vdpmRecordCpuMs, gpuMs, stats_.gpuValid, stats_.vdpmFrontsRecorded, + stats_.vdpmRecordCpuMs, gpuMs, stats_.gpuValid(), stats_.vdpmFrontsRecorded, stats_.vdpmAnalyticDispatches, stats_.vdpmApplyJobs, stats_.vdpmRepairJobs, stats_.vdpmMaxMarkedRounds, stats_.vdpmRepairRoundBudget); // Per-stage breakdown (apply-kernel checkpoint). CPU ms is summed over the frame's @@ -1625,8 +1625,9 @@ void Renderer::drawFrame(Window& display, RenderableScene& scene, float dt) particles_.update(emitterScratch_, view_, unjitteredProj, dt, currentFrame_); // No outer Shadow span: the five families are timed individually with bottom-to-bottom - // boundaries inside recordPass, and an enclosing top-to-bottom timer would overlap them (and - // would then have to be excluded from the frame total to avoid double-counting). + // boundaries inside recordPass, and an enclosing timer would overlap them (and would then have + // to be excluded from the measured-pass sum to avoid double-counting, like the VDPM stage + // rows). recordShadowPass(cmd, buckets); // The levels the shadow views just chose are the tint's subject matter, and the forward draws diff --git a/src/render/shadows.cpp b/src/render/shadows.cpp index 6a8a93f..d0dde67 100644 --- a/src/render/shadows.cpp +++ b/src/render/shadows.cpp @@ -382,14 +382,15 @@ void Shadows::recordPass(vk::CommandBuffer cmd, std::span sha bool renderWorldShadow, ShadowFrameStats& stats, const GpuProfiler& profiler, uint32_t frameIndex) const { - // Bottom-to-bottom group timing (the VDPM sub-stage pattern): both boundaries are - // bottom-of-pipe stamps, so adjacent sub-millisecond groups cannot overlap and inflate each - // other the way repeated top-to-bottom spans do. A group that records nothing leaves its two - // stamps unwritten and reports 0. - // `active` gates the STAMPS, not the body: a family that renders nothing this frame must leave - // its two timestamps unwritten so the pass reports 0, rather than recording an empty span that - // reads as a small real cost and inflates the frame total. An active family with zero candidate - // draws is still timed — its clears and layout barriers are real GPU work. + // Bottom-to-bottom group timing: both boundaries are bottom-of-pipe stamps, so adjacent + // sub-millisecond groups cannot overlap and inflate each other the way top-to-bottom spans do. + // Every pass in the engine stamps this way now — begin() itself is bottom-of-pipe — so this is + // no longer a shadow-only convention, just the convention. A group that records nothing leaves + // its two stamps unwritten and reports 0. `active` gates the STAMPS, not the body: a family + // that renders nothing this frame must leave its two timestamps unwritten so the pass reports + // 0, rather than recording an empty span that reads as a small real cost and inflates the frame + // total. An active family with zero candidate draws is still timed — its clears and layout + // barriers are real GPU work. const auto timeGroup = [&](ProfilePass pass, bool active, auto&& body) { if (!active) @@ -397,9 +398,9 @@ void Shadows::recordPass(vk::CommandBuffer cmd, std::span sha body(); // no-op for an inactive family, but keeps the control flow in one place return; } - profiler.stampBottom(cmd, frameIndex, pass, false); + profiler.begin(cmd, frameIndex, pass); body(); - profiler.stampBottom(cmd, frameIndex, pass, true); + profiler.end(cmd, frameIndex, pass); }; const vk::ClearValue depthClear{.depthStencil = diff --git a/src/render/vdpm_gpu.cpp b/src/render/vdpm_gpu.cpp index 3b003aa..711e52a 100644 --- a/src/render/vdpm_gpu.cpp +++ b/src/render/vdpm_gpu.cpp @@ -1272,18 +1272,26 @@ void VdpmGpuFront::recordFrame( throw std::logic_error("VdpmGpuFront::recordFrame: front is not a runtime front"); } - // Per-stage timing (no-ops unless stageProfile is set). The GPU boundaries are stamped - // BOTTOM-of-pipe and SHARED — the timestamp after stage i is written as both stage i's end and - // stage i+1's begin — so each resolved passMs is a clean consecutive delta with no top-of-pipe - // bleed across these sub-millisecond stages. `gpuBoundary(pass, end)` writes one such stamp - // (only when a single front is recorded — the query slots are one-shot per frame). CPU timing - // is independent: steady_clock around each record call, accumulated into cpuMs[idx]. + // Per-stage timing (no-ops unless stageProfile is set). The GPU boundaries are SHARED — the + // timestamp after stage i is written as both stage i's end and stage i+1's begin — so each + // resolved passMs is a clean consecutive delta. Every profiler stamp is bottom-of-pipe now + // (begin() included), so these stages no longer need a special entry point to get that. + // `gpuBoundary(pass, end)` writes one such stamp (only when a single front is recorded — the + // query slots are one-shot per frame). CPU timing is independent: steady_clock around each + // record call, accumulated into cpuMs[idx]. const bool gpuStage = stageProfile != nullptr && stageProfile->gpu != nullptr; auto gpuBoundary = [&](ProfilePass pass, bool end) { if (gpuStage) { - stageProfile->gpu->stampBottom(cmd, stageProfile->gpuFrameIndex, pass, end); + if (end) + { + stageProfile->gpu->end(cmd, stageProfile->gpuFrameIndex, pass); + } + else + { + stageProfile->gpu->begin(cmd, stageProfile->gpuFrameIndex, pass); + } } }; auto cpuAccumulate = [&](std::size_t idx, std::chrono::steady_clock::time_point t0) diff --git a/tests/render/test_gpu_profiler.cpp b/tests/render/test_gpu_profiler.cpp new file mode 100644 index 0000000..434d6f8 --- /dev/null +++ b/tests/render/test_gpu_profiler.cpp @@ -0,0 +1,209 @@ +#include +#include + +#include +#include + +#include + +using namespace fire_engine; + +// --------------------------------------------------------------------------- +// The timestamp readback's arithmetic and availability policy, tested headlessly. +// +// This is where the bug lived that kept per-pass GPU timing dark on every device for months: the +// readback asked for per-query availability words and then threw them away, because +// `vkGetQueryPoolResults` returns VK_NOT_READY whenever ANY query in the range is unavailable — and +// some always are, since a pass that did not run leaves its two queries reset and never written. +// The Vulkan call itself needs a device; this half does not, and it is the half that was wrong. +// --------------------------------------------------------------------------- + +namespace +{ + +constexpr std::size_t kStrideWords = 2; +constexpr std::size_t kWordCount = static_cast(kProfileQueriesPerFrame) * kStrideWords; + +// One slot's raw buffer, everything unavailable — the shape the driver writes for a frame in which +// nothing has completed. +std::vector emptySlot() +{ + return std::vector(kWordCount, 0); +} + +// Fill one pass' begin/end pair as available, spanning [begin, end] ticks. +void writeSpan(std::vector& words, ProfilePass pass, std::uint64_t begin, + std::uint64_t end) +{ + const std::size_t beginWord = static_cast(pass) * 2 * kStrideWords; + words[beginWord] = begin; + words[beginWord + 1] = 1; + words[beginWord + kStrideWords] = end; + words[beginWord + kStrideWords + 1] = 1; +} + +[[nodiscard]] float passMs(const FrameStats& stats, ProfilePass pass) +{ + return stats.passMs[static_cast(pass)]; +} + +} // namespace + +TEST_CASE("GpuProfiler.AnEmptySlotIsWarmingUpNotValid", "[GpuProfiler]") +{ + // Nothing available yet. The distinction that matters: this is NOT `Unsupported` — the device + // can time, it just has nothing to say — and the overlay renders the two differently now. + FrameStats stats; + resolveTimestampWords(emptySlot(), 1.0f, 64, stats); + + CHECK(stats.gpuTiming == GpuTimingState::WarmingUp); + CHECK_FALSE(stats.gpuValid()); + CHECK(stats.gpuMeasuredPassSumMs == Catch::Approx(0.0f)); +} + +TEST_CASE("GpuProfiler.PassesThatDidNotRunAreSkippedRatherThanFailingTheRead", "[GpuProfiler]") +{ + // THE regression test for the parked bug. A real frame always mixes available and unavailable + // queries — no transmissive draw, no spot light, no VDPM front — and that mixture is exactly + // what makes the Vulkan call return VK_NOT_READY. The resolver must report the passes that DID + // run. + auto words = emptySlot(); + writeSpan(words, ProfilePass::ShadowCascades, 1'000, 3'000); + writeSpan(words, ProfilePass::Forward, 10'000, 15'000); + + FrameStats stats; + resolveTimestampWords(words, 1.0f, 64, stats); // 1 ns per tick, full-width queue + + CHECK(stats.gpuTiming == GpuTimingState::Valid); + CHECK(stats.gpuValid()); + CHECK(passMs(stats, ProfilePass::ShadowCascades) == Catch::Approx(0.002f).margin(1e-6f)); + CHECK(passMs(stats, ProfilePass::Forward) == Catch::Approx(0.005f).margin(1e-6f)); + // Everything else stays 0 — reported as "did not run", not as missing data. + CHECK(passMs(stats, ProfilePass::Transmission) == Catch::Approx(0.0f)); + CHECK(passMs(stats, ProfilePass::ShadowSpot) == Catch::Approx(0.0f)); + CHECK(stats.gpuMeasuredPassSumMs == Catch::Approx(0.007f).margin(1e-6f)); +} + +TEST_CASE("GpuProfiler.OneEndAvailableIsNotASpan", "[GpuProfiler]") +{ + // Half-written pairs are the shape of a pass whose begin landed in this slot and whose end did + // not. Counting it would invent a span from a garbage value. + auto words = emptySlot(); + const std::size_t beginWord = static_cast(ProfilePass::Forward) * 2 * kStrideWords; + words[beginWord] = 5'000; + words[beginWord + 1] = 1; // begin available + words[beginWord + kStrideWords] = 999; // end value present but... + words[beginWord + kStrideWords + 1] = 0; // ...not available + + FrameStats stats; + resolveTimestampWords(words, 1.0f, 64, stats); + + CHECK(stats.gpuTiming == GpuTimingState::WarmingUp); + CHECK(passMs(stats, ProfilePass::Forward) == Catch::Approx(0.0f)); +} + +TEST_CASE("GpuProfiler.ADecreasingPairIsAWrapNotAnAnomaly", "[GpuProfiler]") +{ + // Vulkan defines timestamp overflow as wrapping to zero within `timestampValidBits`, so an end + // value numerically below its begin is ORDINARY on a narrow queue — 8 bits at any real period + // wraps constantly. Treating it as malformed (as this resolver first did) would report 0 ms for + // every span that happened to straddle the wrap, i.e. silently drop real cost. + auto words = emptySlot(); + writeSpan(words, ProfilePass::Forward, 250, 5); // wraps through 256 + + FrameStats stats; + resolveTimestampWords(words, 1.0f, 8, stats); + + CHECK(stats.gpuTiming == GpuTimingState::Valid); + // 256 - 250 + 5 = 11 ticks. + CHECK(passMs(stats, ProfilePass::Forward) == Catch::Approx(11.0e-6f).margin(1e-9f)); +} + +TEST_CASE("GpuProfiler.BitsAboveTheValidWidthCannotAffectTheResult", "[GpuProfiler]") +{ + // Vulkan leaves the bits above `timestampValidBits` UNDEFINED. A queue that returns junk up + // there must produce the same span as one that returns zeros — otherwise the panel's numbers + // depend on what a driver happens to leave in memory. + auto clean = emptySlot(); + writeSpan(clean, ProfilePass::Forward, 250, 5); + auto noisy = emptySlot(); + writeSpan(noisy, ProfilePass::Forward, 0xDEAD'BEEF'0000'0000ull | 250, + 0xFACE'0000'0000'0000ull | 5); + + FrameStats cleanStats; + FrameStats noisyStats; + resolveTimestampWords(clean, 1.0f, 8, cleanStats); + resolveTimestampWords(noisy, 1.0f, 8, noisyStats); + + CHECK(passMs(noisyStats, ProfilePass::Forward) == + Catch::Approx(passMs(cleanStats, ProfilePass::Forward)).margin(1e-9f)); + CHECK(noisyStats.gpuMeasuredPassSumMs == + Catch::Approx(cleanStats.gpuMeasuredPassSumMs).margin(1e-9f)); +} + +TEST_CASE("GpuProfiler.AQueueWithNoValidBitsReportsNothing", "[GpuProfiler]") +{ + // Defensive: the profiler refuses to enable on such a queue, but a zero mask would otherwise + // turn every delta into 0 and present a frame of free passes — worse than reporting nothing. + auto words = emptySlot(); + writeSpan(words, ProfilePass::Forward, 0, 1'000'000); + + FrameStats stats; + resolveTimestampWords(words, 1.0f, 0, stats); + + CHECK(stats.gpuTiming == GpuTimingState::WarmingUp); + CHECK(stats.gpuMeasuredPassSumMs == Catch::Approx(0.0f)); +} + +TEST_CASE("GpuProfiler.TicksAreScaledByTheDevicesTimestampPeriod", "[GpuProfiler]") +{ + // The period is nanoseconds per tick and varies by device (1 on this Mac's MoltenVK, ~40 on + // some desktop GPUs). Getting it wrong scales every number in the panel by a constant nobody + // would notice — the totals would simply look plausible and wrong. + auto words = emptySlot(); + writeSpan(words, ProfilePass::Forward, 0, 1'000'000); // 1e6 ticks + + FrameStats oneNs; + resolveTimestampWords(words, 1.0f, 64, oneNs); + CHECK(passMs(oneNs, ProfilePass::Forward) == Catch::Approx(1.0f).margin(1e-4f)); + + FrameStats fortyNs; + resolveTimestampWords(words, 40.0f, 64, fortyNs); + CHECK(passMs(fortyNs, ProfilePass::Forward) == Catch::Approx(40.0f).margin(1e-3f)); +} + +TEST_CASE("GpuProfiler.VdpmBreakdownRowsReportButDoNotSumIntoTheMeasuredSum", "[GpuProfiler]") +{ + // The four VDPM stage rows are SUBRANGES of VdpmCompute. Adding them to the sum would inflate + // it by the whole VDPM cost whenever the single-front breakdown is populated — and it is + // populated exactly when someone is measuring VDPM, i.e. when the number matters most. + auto words = emptySlot(); + writeSpan(words, ProfilePass::VdpmCompute, 0, 4'000'000); // 4 ms + writeSpan(words, ProfilePass::VdpmScore, 0, 1'000'000); + writeSpan(words, ProfilePass::VdpmApply, 1'000'000, 2'000'000); + writeSpan(words, ProfilePass::VdpmRepair, 2'000'000, 3'000'000); + writeSpan(words, ProfilePass::VdpmEmit, 3'000'000, 4'000'000); + writeSpan(words, ProfilePass::Forward, 0, 2'000'000); // 2 ms, disjoint + + FrameStats stats; + resolveTimestampWords(words, 1.0f, 64, stats); + + CHECK(passMs(stats, ProfilePass::VdpmScore) == Catch::Approx(1.0f).margin(1e-4f)); + CHECK(passMs(stats, ProfilePass::VdpmEmit) == Catch::Approx(1.0f).margin(1e-4f)); + // 4 (compute) + 2 (forward), NOT 4 + 4 (its stages) + 2. + CHECK(stats.gpuMeasuredPassSumMs == Catch::Approx(6.0f).margin(1e-3f)); +} + +TEST_CASE("GpuProfiler.AShortBufferReportsNothingRatherThanAPartialSum", "[GpuProfiler]") +{ + // A caller that passes the wrong range gets no answer, not one assembled from whatever fit. + auto words = emptySlot(); + writeSpan(words, ProfilePass::Forward, 0, 1'000'000); + words.resize(words.size() / 2); + + FrameStats stats; + resolveTimestampWords(words, 1.0f, 64, stats); + + CHECK(stats.gpuTiming == GpuTimingState::WarmingUp); + CHECK(stats.gpuMeasuredPassSumMs == Catch::Approx(0.0f)); +}