diff --git a/docs/crash-triage-windows.md b/docs/crash-triage-windows.md new file mode 100644 index 0000000..e7b26f0 --- /dev/null +++ b/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` 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. diff --git a/docs/tickets.md b/docs/tickets.md index 3d05c36..e227841 100644 --- a/docs/tickets.md +++ b/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. diff --git a/native/shared/src/profiler.rs b/native/shared/src/profiler.rs index cdc54d2..3e41629 100644 --- a/native/shared/src/profiler.rs +++ b/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) { 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,12 +376,18 @@ 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 @@ -351,7 +395,9 @@ impl Profiler { /// 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)> { + let fc = self.frame_count; let mut v: Vec<(&'static str, f64, Option)> = 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(); diff --git a/native/shared/src/renderer/material_system_tests.rs b/native/shared/src/renderer/material_system_tests.rs index 6266cbf..54583d9 100644 --- a/native/shared/src/renderer/material_system_tests.rs +++ b/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], + ], } } diff --git a/native/shared/src/renderer/mod.rs b/native/shared/src/renderer/mod.rs index 3bc9933..ad66ec3 100644 --- a/native/shared/src/renderer/mod.rs +++ b/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. diff --git a/native/shared/src/renderer/ssgi_pass.rs b/native/shared/src/renderer/ssgi_pass.rs index 203dcd9..2e18295 100644 --- a/native/shared/src/renderer/ssgi_pass.rs +++ b/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- diff --git a/native/shared/tests/golden/lit_primitives_3d.png b/native/shared/tests/golden/lit_primitives_3d.png index 271c1b4..c42d8b7 100644 Binary files a/native/shared/tests/golden/lit_primitives_3d.png and b/native/shared/tests/golden/lit_primitives_3d.png differ diff --git a/native/shared/tests/golden/many_point_lights_clustered_scene.png b/native/shared/tests/golden/many_point_lights_clustered_scene.png index 23e65aa..d81c9fb 100644 Binary files a/native/shared/tests/golden/many_point_lights_clustered_scene.png and b/native/shared/tests/golden/many_point_lights_clustered_scene.png differ diff --git a/native/windows/Cargo.toml b/native/windows/Cargo.toml index a76ecf8..0b472b1 100644 --- a/native/windows/Cargo.toml +++ b/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"] } diff --git a/native/windows/src/lib.rs b/native/windows/src/lib.rs index c3cf180..eee9783 100644 --- a/native/windows/src/lib.rs +++ b/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")