Round-2 stability: profiler honesty, GI backend logging, crash-triage kit, test repairs

docs/crash-triage-windows.md

@@ -0,0 +1,59 @@
+# Windows crash triage — native AVs in Perry-compiled games
+
+Written after the 2026-07-04 round-2 audit, where the Bloom Shooter hit the
+same access violation in three scripted runs (`main.exe+0xe8e5`, read of an
+address 8 bytes below a page boundary, exception c0000005) and the fault
+could not be reproduced after a relink. Everything below is the kit that
+makes the *next* occurrence a five-minute diagnosis instead of a hunt.
+
+## What we know about the 2026-07 AV (EN-020)
+
+- Same faulting instruction offset in all three crashes; faulting address
+  `0x…FFF8` = a read that walked off the end of a heap allocation onto an
+  unmapped page. Classic buffer-overrun-read signature: the overrun likely
+  happens often and only faults when the allocator places the buffer at
+  the end of a page — which makes it **layout-sensitive**: any relink
+  reshuffles the odds. Our fishing runs on a rebuilt binary (60 s with the
+  same workloads, plus a 19-transition feature-toggle gauntlet) did not
+  reproduce.
+- Crash contexts (shooter audit tour): 20–56 s into runs that combined the
+  profiler (enabled), profiler-string FFI reads (`getProfilerOverlay` /
+  `getProfilerFrameHistory`), stage transitions, and in two cases runtime
+  feature disables. Toggles alone were exonerated by the gauntlet run;
+  string churn alone was exonerated by run 3 (crashed with only ~8 tiny
+  prints). No Rust panic output on stderr — this is raw UB, not a panic
+  (the engine builds with `panic = "abort"`, which would print first).
+- Suspect space: Perry runtime heap/string handling at the FFI boundary,
+  or an engine-side out-of-bounds read into a heap buffer. The faulting
+  module offset (0xe8e5, very low in `.text`) is consistent with a small
+  shared helper (memcpy-class) rather than a leaf feature.
+
+## Standing infrastructure on the dev box
+
+- **WER LocalDumps** (HKCU, no admin needed): full dumps for `main.exe`
+  land in `shooter/tools/.testout/dumps/`, dialog suppressed
+  (`Windows Error Reporting\DontShowUI = 1`). Configured 2026-07-04;
+  survives reboots. Every crash from now on leaves a `.dmp`.
+- **Symbols**: `native/windows/Cargo.toml` sets
+  `[profile.release] debug = "line-tables-only"`, so the staticlib carries
+  line tables at negligible cost. Link the game with
+  `perry compile src/main.ts -o main --debug-symbols` to get `main.pdb`
+  next to the exe (lld `/DEBUG`). Keep the exe+pdb pair that produced any
+  dump.
+- **Symbolisation** (LLVM is installed at `C:\Program Files\LLVM`):
+  `llvm-symbolizer --obj=main.exe --use-native-pdb-reader 0x<RVA>` maps
+  the WER event's module offset to a function/line. For a full stack,
+  open the `.dmp` in WinDbg (`winget install Microsoft.WinDbg`) with
+  `.sympath` pointing at the exe's folder, then `!analyze -v`.
+- The WER Application-log event (Id 1000) alone already gives the module
+  + offset — check it first:
+  `Get-WinEvent -FilterHashtable @{LogName='Application'; Id=1000} -MaxEvents 3`.
+
+## Repro harness
+
+The shooter's audit tour (`AUDIT` block for `src/main.ts`, preserved with
+the round-2 artifacts) drives the game unattended: scripted combat at the
+enemy-pool max, camera pose hops, profiler-string churn every 2 s, and an
+optional feature-toggle gauntlet. Historical crash probability was 3/3
+within 60 s on the af98dbe-era binary; treat every future tour run as a
+fishing run — the dump infrastructure is armed.

docs/tickets.md

@@ -661,3 +661,31 @@ test.
 **Blocked on:** access to a Windows 11 box with a HiDPI display
 (or a VM forwarding DPI), and a Linux dev with X11. Web checks
 can be done from any modern browser on the macOS dev box.
+
+## EN-020 — Native AV: heap read overrun, layout-sensitive 🔴
+
+**Symptom.** Bloom Shooter round-2 audit (2026-07-04): three scripted runs
+crashed with c0000005 at the same instruction (`main.exe+0xe8e5` on the
+af98dbe-era link), reading `0x…FFF8` — 8 bytes below a page boundary.
+No Rust panic output (engine builds `panic = "abort"`, which would print),
+so this is raw UB: something reads past the end of a heap allocation and
+faults only when the allocation abuts an unmapped page.
+
+**What is ruled out.** Runtime feature toggles alone (a 19-transition
+ssgi/shadows/profiler gauntlet under combat load survived); profiler
+string churn alone (one crash happened with only ~8 small prints);
+specific stages (three different ones). The fault did not reproduce after
+a relink (two 60 s fishing runs) — consistent with layout sensitivity,
+not with a fixed trigger.
+
+**Standing kit.** WER LocalDumps armed on the dev box (dumps →
+`shooter/tools/.testout/dumps/`, dialog suppressed), line tables in the
+staticlib (`debug = "line-tables-only"`), `perry compile --debug-symbols`
+emits `main.pdb`, LLVM symbolizer available. See
+[crash-triage-windows.md](crash-triage-windows.md). Next occurrence =
+symbolized stack; fix then.
+
+**Suspect space.** Perry-runtime heap/string handling at the FFI boundary
+(profiler overlay/history strings are the heaviest string traffic in the
+crashing runs), or an engine-side heap read overrun in a small shared
+helper. Audit report: `shooter/docs/audit-round2.md` finding F1.

native/shared/src/profiler.rs

@@ -57,6 +57,8 @@ pub struct Profiler {
     next_query: u32,
     // label -> (begin_index, end_index)
     pending_gpu: Vec<(&'static str, u32, u32)>,
+    /// One-shot warning guard for GPU timestamp-pair exhaustion.
+    budget_warned: bool,
 
     /// Phase 8 — last `ROLLING_FRAMES` frame totals (sum of all
     /// samples in `frame` at frame_end), in microseconds. Ring
@@ -74,11 +76,15 @@ struct RollingStats {
     has_gpu: bool,
     idx: usize,
     filled: usize,
+    /// Frame index of the most recent sample. A pass that stops running
+    /// (feature toggled off) must drop out of the readouts instead of
+    /// showing its frozen average forever.
+    last_frame: u64,
 }
 
 impl RollingStats {
     fn new() -> Self {
-        Self { cpu: [0.0; ROLLING_FRAMES], gpu: [0.0; ROLLING_FRAMES], has_gpu: false, idx: 0, filled: 0 }
+        Self { cpu: [0.0; ROLLING_FRAMES], gpu: [0.0; ROLLING_FRAMES], has_gpu: false, idx: 0, filled: 0, last_frame: 0 }
     }
     fn push(&mut self, cpu: f64, gpu: Option<f64>) {
         self.cpu[self.idx] = cpu;
@@ -113,6 +119,7 @@ impl Profiler {
             timestamp_period_ns: 1.0,
             next_query: 0,
             pending_gpu: Vec::new(),
+            budget_warned: false,
             frame_total_cpu_us: [0.0; ROLLING_FRAMES],
             frame_total_gpu_us: [0.0; ROLLING_FRAMES],
             histogram_idx: 0,
@@ -151,7 +158,20 @@ impl Profiler {
         self.gpu_enabled = true;
     }
 
-    pub fn set_enabled(&mut self, on: bool) { self.enabled = on; }
+    pub fn set_enabled(&mut self, on: bool) {
+        if on && !self.enabled {
+            // Fresh measuring session: without this, stats captured before
+            // a disable (potentially under a different feature set) show
+            // until the rolling window refills and skew the first seconds
+            // of every new session.
+            self.rolling.clear();
+            self.frame_total_cpu_us = [0.0; ROLLING_FRAMES];
+            self.frame_total_gpu_us = [0.0; ROLLING_FRAMES];
+            self.histogram_idx = 0;
+            self.histogram_filled = 0;
+        }
+        self.enabled = on;
+    }
     pub fn is_enabled(&self) -> bool { self.enabled }
     pub fn has_gpu(&self) -> bool { self.gpu_enabled }
 
@@ -175,7 +195,16 @@ impl Profiler {
     pub fn reserve_gpu_pair(&mut self, label: &'static str) -> Option<(u32, u32)> {
         if !self.enabled || !self.gpu_enabled { return None; }
         self.query_set.as_ref()?;
-        if self.next_query + 2 > MAX_GPU_PAIRS * 2 { return None; }
+        if self.next_query + 2 > MAX_GPU_PAIRS * 2 {
+            if !self.budget_warned {
+                self.budget_warned = true;
+                eprintln!(
+                    "bloom profiler: GPU timestamp budget ({} pairs) exhausted — later passes report CPU time only",
+                    MAX_GPU_PAIRS
+                );
+            }
+            return None;
+        }
         let begin = self.next_query;
         let end = self.next_query + 1;
         self.next_query += 2;
@@ -223,9 +252,11 @@ impl Profiler {
         }
     }
 
-    /// End-of-frame bookkeeping. Reads back GPU timestamps from the
-    /// previous frame (non-blocking map), folds samples into rolling
-    /// stats, and clears per-frame state for the next frame.
+    /// End-of-frame bookkeeping. Resolves this frame's GPU timestamps via
+    /// a BLOCKING map (map_async + poll(Wait) — serialises CPU⇄GPU, so
+    /// wall-clock fps is pessimistic while the profiler is enabled; see
+    /// docs/crash-triage-windows.md), folds samples into rolling stats,
+    /// and clears per-frame state for the next frame.
     pub fn frame_end(&mut self, device: &wgpu::Device) {
         if !self.enabled {
             self.frame.clear();
@@ -287,10 +318,15 @@ impl Profiler {
         self.histogram_idx = (self.histogram_idx + 1) % ROLLING_FRAMES;
         self.histogram_filled = (self.histogram_filled + 1).min(ROLLING_FRAMES);
 
+        let fc = self.frame_count;
         for s in self.frame.drain(..) {
             let entry = self.rolling.entry(s.label).or_insert_with(RollingStats::new);
             entry.push(s.cpu_us, s.gpu_us);
+            entry.last_frame = fc;
         }
+        // Drop entries that have not reported for several windows so a
+        // disabled feature's passes leave the map instead of lingering.
+        self.rolling.retain(|_, s| fc.saturating_sub(s.last_frame) <= (4 * ROLLING_FRAMES) as u64);
         self.open_cpu.clear();
         self.next_query = 0;
         self.pending_gpu.clear();
@@ -316,7 +352,9 @@ impl Profiler {
         if !self.enabled {
             return String::from("profiler: disabled\n");
         }
+        let fc = self.frame_count;
         let mut entries: Vec<(&&str, &RollingStats)> = self.rolling.iter()
+            .filter(|(_, s)| fc.saturating_sub(s.last_frame) <= ROLLING_FRAMES as u64)
             .map(|(k, v)| (k, v))
             .collect();
         entries.sort_by(|a, b| b.1.avg_cpu().partial_cmp(&a.1.avg_cpu()).unwrap_or(std::cmp::Ordering::Equal));
@@ -338,20 +376,28 @@ impl Profiler {
     /// Average total CPU frame time across the rolling window (sum of
     /// all phases). Useful for a single headline number.
     pub fn avg_frame_cpu_us(&self) -> f64 {
-        self.rolling.values().map(|s| s.avg_cpu()).sum()
+        let fc = self.frame_count;
+        self.rolling.values()
+            .filter(|s| fc.saturating_sub(s.last_frame) <= ROLLING_FRAMES as u64)
+            .map(|s| s.avg_cpu()).sum()
     }
 
     /// Average total GPU frame time where available.
     pub fn avg_frame_gpu_us(&self) -> f64 {
-        self.rolling.values().filter_map(|s| s.avg_gpu()).sum()
+        let fc = self.frame_count;
+        self.rolling.values()
+            .filter(|s| fc.saturating_sub(s.last_frame) <= ROLLING_FRAMES as u64)
+            .filter_map(|s| s.avg_gpu()).sum()
     }
 
     /// Snapshot the rolling averages in a stable, CPU-time-descending
     /// order. Games call this once per overlay-draw frame and pull
     /// label/cpu/gpu out via the accessors below — HashMap iteration
     /// order would jitter the overlay otherwise.
     pub fn snapshot(&mut self) -> Vec<(&'static str, f64, Option<f64>)> {
+        let fc = self.frame_count;
         let mut v: Vec<(&'static str, f64, Option<f64>)> = self.rolling.iter()
+            .filter(|(_, s)| fc.saturating_sub(s.last_frame) <= ROLLING_FRAMES as u64)
             .map(|(k, s)| (*k, s.avg_cpu(), s.avg_gpu()))
             .collect();
         v.sort_by(|a, b| b.1.partial_cmp(&a.1).unwrap_or(std::cmp::Ordering::Equal));
@@ -394,6 +440,36 @@ mod tests {
         assert_eq!(h[4].0, 500.0);
     }
 
+    #[test]
+    fn stale_labels_drop_out_of_snapshot_and_evict() {
+        let mut p = Profiler::new();
+        p.set_enabled(true);
+        // One label reports once, another keeps reporting.
+        p.frame.push(FrameSample { label: "once", cpu_us: 5.0, gpu_us: None });
+        p.frame_end_cpu();
+        for _ in 0..(ROLLING_FRAMES + 1) { fake_frame(&mut p, 1.0); }
+        let snap = p.snapshot();
+        assert!(snap.iter().any(|(l, _, _)| *l == "fake"));
+        assert!(
+            !snap.iter().any(|(l, _, _)| *l == "once"),
+            "a pass that stopped reporting must leave the snapshot"
+        );
+        for _ in 0..(4 * ROLLING_FRAMES) { fake_frame(&mut p, 1.0); }
+        assert!(!p.rolling.contains_key("once"), "stale label must eventually evict");
+    }
+
+    #[test]
+    fn reenable_starts_fresh_session() {
+        let mut p = Profiler::new();
+        p.set_enabled(true);
+        fake_frame(&mut p, 100.0);
+        assert!(!p.frame_history().is_empty());
+        p.set_enabled(false);
+        p.set_enabled(true);
+        assert!(p.frame_history().is_empty(), "histogram must clear on re-enable");
+        assert!(p.snapshot().is_empty(), "rolling stats must clear on re-enable");
+    }
+
     #[test]
     fn frame_history_wraps_oldest_first_at_capacity() {
         let mut p = Profiler::new();

native/shared/src/renderer/material_system_tests.rs

@@ -378,6 +378,13 @@ mod translucent_sort_tests {
             draw_slot: 0,
             view_depth,
             instance: None,
+            // Identity — the sort under test only reads view_depth.
+            model: [
+                [1.0, 0.0, 0.0, 0.0],
+                [0.0, 1.0, 0.0, 0.0],
+                [0.0, 0.0, 1.0, 0.0],
+                [0.0, 0.0, 0.0, 1.0],
+            ],
         }
     }
 

native/shared/src/renderer/mod.rs

@@ -979,6 +979,11 @@ pub struct Renderer {
     pub ssgi_radius: f32,
     /// SSGI master switch.
     pub ssgi_enabled: bool,
+    /// One-shot log guard: which SSGI trace backend was last reported to
+    /// stderr (hw-ray-query / sdf-clipmap / hiz-screen). The silent HW→SW
+    /// fallback made "why is bounce gray?" a debugger question during the
+    /// round-2 audit — keep it answerable from the log.
+    pub ssgi_backend_logged: Option<&'static str>,
 
     // --- Ticket 007a: Lumen-style screen-probe SSGI ---
 
@@ -6022,6 +6027,7 @@ impl Renderer {
             ssgi_intensity: 1.0,
             ssgi_radius: 20.0,
             ssgi_enabled: true,
+            ssgi_backend_logged: None,
             probe_grid_w,
             probe_grid_h,
             probe_header_buffer,
@@ -9426,6 +9432,11 @@ impl Renderer {
             }
         }
 
+        // CPU bracket over the composite + custom post-pass encode tail.
+        // The matching `end("post_fx")` below predates this begin — it was
+        // orphaned (a no-op) for months while comments claimed the phase
+        // covered scene_compose's cost.
+        profiler.begin("post_fx");
         let composite_src_view = self.composite_source_view();
 
         // composite_uniform_buffer carries per-frame composite state.

native/shared/src/renderer/ssgi_pass.rs

@@ -189,6 +189,14 @@ impl Renderer {
         let use_sdf = !use_hw
             && self.scene_sdf_clipmap_built
             && self.tlas_instance_data_buffer.is_some();
+        // Log the backend once (and again if it changes, e.g. clipmap
+        // finishing its first bake promotes hiz → sdf). Nothing else in
+        // the engine reveals which tier actually runs.
+        let backend = if use_hw { "hw-ray-query" } else if use_sdf { "sdf-clipmap" } else { "hiz-screen" };
+        if self.ssgi_backend_logged != Some(backend) {
+            self.ssgi_backend_logged = Some(backend);
+            eprintln!("bloom: ssgi trace backend = {}", backend);
+        }
 
         if use_hw {
             // Build the HW bind group lazily. V3 uses a per-

native/windows/Cargo.toml

@@ -33,6 +33,10 @@ image-extras = ["bloom-shared/image-extras"]
 # in native/macos/Cargo.toml.
 [profile.release]
 panic = "abort"
+# Line tables in the staticlib objects so `perry compile --debug-symbols`
+# can emit a usable PDB for crash triage (negligible runtime cost; the
+# symbols stay out of the exe unless /DEBUG is requested at link).
+debug = "line-tables-only"
 
 [dependencies]
 bloom-shared = { path = "../shared", default-features = false, features = ["mp3"] }

native/windows/src/lib.rs

@@ -446,6 +446,20 @@ unsafe fn init_engine_for_hwnd(
             ..Default::default()
         })).expect("No adapter found");
 
+        {
+            // One line of boot truth: which GPU we got and whether the
+            // features that silently reshape the frame (HW ray query for
+            // GI, timestamps for the profiler) are available on it.
+            let info = adapter.get_info();
+            eprintln!(
+                "bloom: adapter '{}' ({:?}), ray_query={}, timestamps={}",
+                info.name,
+                info.backend,
+                adapter.features().contains(wgpu::Features::EXPERIMENTAL_RAY_QUERY),
+                adapter.features().contains(wgpu::Features::TIMESTAMP_QUERY),
+            );
+        }
+
         // Ticket 007b: HW ray-query via DXR 1.1 / VK_KHR_ray_query.
         let supported = adapter.features();
         let force_sw_gi = std::env::var("BLOOM_FORCE_SW_GI")