diff --git a/audit-findings.md b/audit-findings.md index 080c7cc..fdfbfcc 100644 --- a/audit-findings.md +++ b/audit-findings.md @@ -4117,3 +4117,194 @@ Per the producer-hunt charter the remaining strong candidates are routing**. Timer DPC is the next-strongest because the parked handles are explicit `Event/Manual`s with no current waker, and Xbox 360 timer-driven DPCs are a common signal source. + +### KRNBUG-AUDIT-002 — multi-frame stack capture at handle creation + +**Status:** landed (diagnostic only; no behaviour change). Walker +verified end-to-end against the analysed call graph for every +captured frame. + +**Site:** `crates/xenia-kernel/src/audit.rs` (new +`record_create_with_stack`, new `created_stack: Vec<(u32,u32)>` on +`HandleAuditTrail`); `crates/xenia-kernel/src/state.rs` (new +`audit_create_with_ctx` helper + free function +`walk_guest_back_chain(sp, lr, mem, max)`); `nt_create_event` / +`nt_create_semaphore` / `nt_create_timer` / `xam_task_schedule` now +route through the new helper. Dump in `crates/xenia-app/src/main.rs` +prints `created stack (N frames)` under the per-handle FOCUS report. + +**Why it exists:** KRNBUG-AUDIT-001 told us the producer is missing +for handles `0x1004` / `0x100c` / `0x15e4` (later corrected to +`0x15e0` — see below) but couldn't tell us *which subsystem owns +each handle*. The wrapper at `lr=0x824a9f6c` is the same +`silph::Event` ctor for 83 unique callers, so the immediate LR is +useless for subsystem identification. The new walker captures up to +6 stack frames at create time, gated on the focus set so the cost +is one `HashSet::contains` on the unfocused hot path. + +**Walker correctness:** PPC EABI back-chain (`[r1] = prev_sp`, +saved-LR-of-prev-frame at `[prev_sp - 8]`). Frame 0 is the live +`(ctx.gpr[1], ctx.lr)` since the wrapper hasn't spilled its own LR +yet. Sentinels: 0, 0xFFFFFFFF, self-loop. Read-only via +`MemoryAccess::read_u32` — guest memory and CPU state are not +mutated, so lockstep determinism is unaffected. + +**Verification:** +- Workspace tests: 576 → 581 (+5: 2 new in `audit.rs` exercising the + `record_create_with_stack` path including the disabled-no-op case; + 3 new in `state.rs` exercising synthetic 3-level back-chain, + self-loop sentinel, zero sentinel). +- `--stable-digest -n 50M` lockstep oracle (`sylpheed_n50m`): + bit-identical to checked-in golden (re-confirmed twice). +- End-to-end: every captured frame's saved-LR matches a `bl` + instruction one address earlier in the named function (cross-checked + against `sylpheed.db`'s `instructions` table for all 18 captured + PCs across handles `0x1004` / `0x100c` / `0x15e0`). + +### Producer-trace finding (KRNBUG-AUDIT-002 deliverable) + +Run: `exec sylpheed.iso --halt-on-deadlock --trace-handles-focus=0x1004,0x100c,0x15e0,0x42450b5c -n 500_000_000`. + +**0x1004 (tid=10 waiter):** static C++ ctor → 8-instance pool + +``` +[0] sub_824A9F18 +0x54 silph::Event ctor wrapper (83 callers) +[1] sub_821783D8 +0x120 per-instance subsystem-init (RtlInitializeCSAndSpinCount + Event ctor) +[2] sub_8217C850 +0x58 single per-pool-element bridge ctor +[3] (no func) +0x14 static ctor at 0x8280F810; calls sub_8217C850 EIGHT times +[4] sub_824ACB38 +0xb8 the CRT static-init driver (walks 0x82870010..0x828708d4) +[5] entry_point +0x60 the standard CRT entry stub +``` + +The 8-instance call from frame 3 is the smoking gun: `0x8280F810` +is a single C++ static constructor that builds an 8-element array +of objects, each of which gets its own Critical Section + Event + +worker thread. This is a **thread pool**, constructed before +`main()` runs. + +**0x100c (tid=2 waiter):** runtime init in `main()` → singleton + +``` +[0] sub_824A9F18 +0x54 silph::Event ctor wrapper +[1] sub_82181750 +0x70 per-instance subsystem-init (same shape: CS + Event) +[2] sub_821800D8 +0x3c single-call bridge ctor +[3] sub_82181C20 +0x38 subsystem driver +[4] sub_8216EA68 +0x3c (top-level main; called from entry_point + 0x194 with r3=r4=r5=0) +[5] entry_point +0x198 right after `bl 0x8216EA68` +``` + +Different code cluster (`0x82181xxx`), single instance, constructed +**inside `main()` itself** — not from C++ static init. This is a +runtime-allocated singleton subsystem. + +**0x15e0 (tid=16 waiter):** runtime init via a third distinct cluster + +``` +[0] sub_824A9F18 +0x54 silph::Event ctor wrapper +[1] sub_821701C8 +0x48 per-instance subsystem-init (CS + Event, callees mirror 0x100c's path) +[2] sub_8216F618 +0x44 bridge +[3] sub_821707C0 +0x38 driver +[4] (no func) +0x? 0x821C5418 — analyser missed this function entry +[5] sub_82172BA0 +0x1ec upper-level subsystem driver +``` + +Third distinct C++ class in cluster `0x82170xxx`. Same per-instance +shape (CS + Event + worker thread); different call site than 0x100c. + +**Cross-check on the project memory list:** the prior memory listed +the third handle as `0x15e4`; the actual handle on this run is +`0x15e0` (off-by-4 in the prior session's transcription). The +parked-waiter set as of HEAD `9d45efe` is: + +| Handle | Tid | Waits via | Trail status | Note | +|--------|-----|-----------|--------------|------| +| 0x1004 | 10 | `do_wait_single` | primary | static-ctor pool (8 entries) | +| 0x100c | 2 | `do_wait_single` | primary | runtime singleton | +| 0x15e0 | 16 | `do_wait_single` | primary | runtime singleton, distinct class | +| 0x12f4 | 13,14 | `do_wait_single` | primary | shared Semaphore — 2 waiters | +| 0x15f8 | 18 | `do_wait_multiple` | primary | Event/Auto | +| 0x1038 | 4 | `do_wait_multiple` | primary | Event/Auto, in WaitAny[0x1038, 0x103c] | +| 0x10b0 | 5 | `do_wait_multiple` | primary | Event/Auto, in WaitAny[0x10b0, 0x10b4] | +| 0x42450b5c | 6 | (non-`do_wait_single`) | `` `` | guest-memory addr (heap range), bypasses Nt-side audit entirely | + +**0x42450b5c is qualitatively different.** Address `>= 0x40000000` +is the guest user heap range, not a kernel handle table value +(which start at 0x1000 and increment by 4). tid=6 is parking on a +guest pointer — almost certainly an embedded `KEVENT` reached via +`KeWaitForSingleObject(*PDISPATCHER_HEADER)` rather than via a +handle. Our audit didn't see the wait either (`waits=0` while +`waiter_count=1`), so the wait path itself bypasses +`do_wait_single`. Treat as a separate bug class. + +### Subsystem identification + +All three Event/Manual creators (sub_821783D8, sub_82181750, +sub_821701C8) follow the **identical 4-callee pattern**: + +1. `RtlInitializeCriticalSectionAndSpinCount` (init the per-instance CS) +2. `sub_824A9F18` (the silph::Event ctor wrapper → `NtCreateEvent`) +3. + 1-2 silph internal helpers (`sub_82172370`, `sub_824AA3E0`, + `sub_8217E948`, `sub_82274C70`, etc.) which initialize a queue + and spawn a worker thread + +Each parked worker does the same prologue: `silph::Thread::SetProcessor(CURRENT, 5)` +(via `sub_824AA658(r3=-2, r4=5)`), then either an `lwarx`/`stwcx` +CAS-spinlock + `RtlEnterCriticalSection` + check for queued work. + +This is the canonical **work-queue worker pattern**: a producer +posts a message to an instance's queue (under the CS) and signals +the Event; the worker wakes, drains, parks again. The producer +that should call `Nt/KeSetEvent(handle)` is **never executed** +within 500M instructions for any of the 3 handles. + +The PE's RTTI string table lists thread-related class names in the +`SilpheedSCS` namespace: `WorkHudThread2`, `WorkHudThreadTaskCaller`, +`COLLISION_THREAD_PARAM`, `UPDATER_THREAD_PARAM`, `CRenderCommandQueue`, +`CTaskUpdater`. The 8-element static-init pool for 0x1004 most +plausibly maps to one of the multi-instance worker classes in this +list (likely `WorkHudThread2` family — the only `Thread`-suffixed +multi-instance candidate); the singletons 0x100c and 0x15e0 most +plausibly map to two of `CTaskUpdater` / `CRenderCommandQueue` / +similar singletons. Without a live debugger pass to read the +vtable+RTTI block at the `this` pointer of each worker, the exact +class assignment is heuristic. + +### Recommended next session — surgical producer hunt + +The producer for each Event is the **call site that owns the +matching message-push code path**. Steps: + +1. **For each Event handle (0x1004, 0x100c, 0x15e0)**, dump the + first 12 bytes of the `this` pointer to read the vtable address + (the `this` is in `r3` at the worker's ABI entry — captured in + the wait diagnostic as the first arg). Then read vtable[-1] to + resolve the RTTI Type Descriptor, which gives the class name. + This pinpoints exactly which `SilpheedSCS::*` class each + subsystem is. +2. **Then xref the class name** in the binary to find the + producer-side method (`Push*`, `Submit*`, `EnqueueMessage*`, + `Notify*`). That method's signal call (likely + `silph::Event::Set` → `NtSetEvent` thunk) is what should fire. +3. **Trace that producer's caller chain** to find the upstream + gate. Two failure modes are equally likely: + - **(A)** The producer DOES run but signals via `KeSetEvent` on + an embedded `KEVENT` field (not the handle-table side), and + our HLE `KeSetEvent` doesn't route to the handle-table waiter + list. Same family as 0x42450b5c. Smoking gun: `kernel.calls` + metric for `KeSetEvent` is non-zero but the audit shows zero + signals. + - **(B)** The producer is gated by an upstream condition that + doesn't trigger — e.g. UI-system message that never arrives, + timer-DPC that never fires, vsync interrupt with the wrong + APC routing. Smoking gun: `kernel.calls{KeSetEvent}` is zero + for that handle. +4. **0x42450b5c** is a separate bug. Add a parallel + `audit_create_with_ctx` hook to whichever wait path tid=6 takes + (it's NOT `do_wait_single`); the function span at PC=0x824cd4f4 + isn't even in the analyser's `functions` table. Likely the + `KeWaitForSingleObject(*PDISPATCHER_HEADER)` wrapper. Once the + wait path is audited, repeat the producer-trace. + +The walker is reusable: any handle added to `--trace-handles-focus` +will get a 6-frame stack at creation time. Add new candidates +freely — cost on the unfocused hot path is one `HashSet::contains`. diff --git a/crates/xenia-app/src/main.rs b/crates/xenia-app/src/main.rs index 747c4b2..227ab3e 100644 --- a/crates/xenia-app/src/main.rs +++ b/crates/xenia-app/src/main.rs @@ -3207,6 +3207,15 @@ fn dump_thread_diagnostic(kernel: &xenia_kernel::KernelState, quiet: bool) { " created cycle={} tid={} lr={:#010x} src={}", t.created.cycle, t.created.tid, t.created.lr, t.created.source, ); + if !t.created_stack.is_empty() { + println!(" created stack ({} frames):", t.created_stack.len()); + for (i, (fp, lr)) in t.created_stack.iter().enumerate() { + println!( + " [{:>2}] fp={:#010x} lr={:#010x}", + i, fp, lr, + ); + } + } } // Producer-class classification. Source strings are stable // labels passed to `record_signal` at the export sites. diff --git a/crates/xenia-kernel/src/audit.rs b/crates/xenia-kernel/src/audit.rs index db6594b..f287a71 100644 --- a/crates/xenia-kernel/src/audit.rs +++ b/crates/xenia-kernel/src/audit.rs @@ -51,6 +51,14 @@ pub struct HandleAuditTrail { pub kind: &'static str, /// When/who/where the handle was minted. pub created: HandleAuditEntry, + /// KRNBUG-AUDIT-002 producer-trace. Captured frames at allocation + /// time, only populated when the handle is in `HandleAudit::focus` + /// AND the create site routed through the `_with_stack` variant. + /// Frame layout: `(frame_pointer, saved_lr_for_caller_of_that_frame)`. + /// Index 0 is the live frame: `(ctx.gpr[1], ctx.lr)`. Index 1+ comes + /// from walking the PPC back-chain. An empty vec means either the + /// handle wasn't in focus or the create site didn't capture a stack. + pub created_stack: Vec<(u32, u32)>, /// Bounded ring of signal events. pub signals: VecDeque, /// Bounded ring of wait-entry events (one per `Wait*` call). @@ -64,6 +72,7 @@ impl HandleAuditTrail { Self { kind, created, + created_stack: Vec::new(), signals: VecDeque::with_capacity(AUDIT_RING_CAPACITY), waits: VecDeque::with_capacity(AUDIT_RING_CAPACITY), wakes: VecDeque::with_capacity(AUDIT_RING_CAPACITY), @@ -121,6 +130,26 @@ impl HandleAudit { .insert(handle, HandleAuditTrail::new(kind, entry)); } + /// Same as `record_create`, but additionally stores a captured guest + /// stack trace on the trail (`created_stack`). Intended for handles + /// in `focus` so the dump can name the actual subsystem caller of the + /// kernel API rather than just the immediate wrapper return. + #[inline] + pub fn record_create_with_stack( + &mut self, + handle: u32, + kind: &'static str, + entry: HandleAuditEntry, + stack: Vec<(u32, u32)>, + ) { + if !self.enabled { + return; + } + let mut trail = HandleAuditTrail::new(kind, entry); + trail.created_stack = stack; + self.trails.insert(handle, trail); + } + #[inline] pub fn record_signal(&mut self, handle: u32, entry: HandleAuditEntry) { if !self.enabled { @@ -268,4 +297,34 @@ mod tests { let a = HandleAudit::default(); assert!(a.counts(0x10FC).is_none()); } + + #[test] + fn create_with_stack_stores_frames() { + let mut a = HandleAudit { enabled: true, ..HandleAudit::default() }; + let frames = vec![ + (0x7000_0100, 0x824a_9f6c), + (0x7000_0200, 0x824a_b020), + (0x7000_0300, 0x82bb_aa00), + ]; + a.record_create_with_stack( + 0x1004, + "Event/Manual", + entry(0, "NtCreateEvent"), + frames.clone(), + ); + let trail = &a.trails[&0x1004]; + assert_eq!(trail.created_stack, frames); + } + + #[test] + fn create_with_stack_disabled_is_noop() { + let mut a = HandleAudit::default(); + a.record_create_with_stack( + 0x1004, + "Event/Manual", + entry(0, "NtCreateEvent"), + vec![(0x7000_0000, 0x8200_0000)], + ); + assert!(a.trails.is_empty()); + } } diff --git a/crates/xenia-kernel/src/exports.rs b/crates/xenia-kernel/src/exports.rs index 40ee9e5..6725cf3 100644 --- a/crates/xenia-kernel/src/exports.rs +++ b/crates/xenia-kernel/src/exports.rs @@ -1462,10 +1462,11 @@ fn nt_create_event(ctx: &mut PpcContext, mem: &GuestMemory, state: &mut KernelSt signaled, waiters: Vec::new(), }); - state.audit_create( + state.audit_create_with_ctx( handle, if manual_reset { "Event/Manual" } else { "Event/Auto" }, - ctx.lr as u32, + ctx, + mem, "NtCreateEvent", ); if handle_ptr != 0 { @@ -1484,7 +1485,7 @@ fn nt_create_semaphore(ctx: &mut PpcContext, mem: &GuestMemory, state: &mut Kern max, waiters: Vec::new(), }); - state.audit_create(handle, "Semaphore", ctx.lr as u32, "NtCreateSemaphore"); + state.audit_create_with_ctx(handle, "Semaphore", ctx, mem, "NtCreateSemaphore"); if handle_ptr != 0 { mem.write_u32(handle_ptr, handle); } @@ -1516,10 +1517,11 @@ fn nt_create_timer(ctx: &mut PpcContext, mem: &GuestMemory, state: &mut KernelSt callback_arg: 0, waiters: Vec::new(), }); - state.audit_create( + state.audit_create_with_ctx( handle, if timer_type == 0 { "Timer/Manual" } else { "Timer/Auto" }, - ctx.lr as u32, + ctx, + mem, "NtCreateTimer", ); if handle_ptr != 0 { diff --git a/crates/xenia-kernel/src/state.rs b/crates/xenia-kernel/src/state.rs index 8dc6d55..7d9c840 100644 --- a/crates/xenia-kernel/src/state.rs +++ b/crates/xenia-kernel/src/state.rs @@ -455,6 +455,41 @@ impl KernelState { self.audit.record_create(handle, kind, entry); } + /// KRNBUG-AUDIT-002. Variant of `audit_create` that additionally + /// captures a 6-frame guest stack trace at allocation time when the + /// handle is in `audit.focus`. Outside the focus set this falls back + /// to plain `audit_create` (no stack walk → no extra cost on the hot + /// path of unfocused handle creation). + /// + /// The walk reads the PPC EABI back-chain: `[r1] = prev_sp`, and the + /// LR saved by *that* prev frame's prologue lives at `[prev_sp - 8]`. + /// Frame 0 is the live frame `(ctx.gpr[1], ctx.lr)`. Frames 1..N walk + /// upward. A read returning 0 / 0xFFFF_FFFF, or a self-loop, ends the + /// walk early. This is read-only — guest memory and CPU state are not + /// mutated, so lockstep determinism is unaffected (a parallel run with + /// no focus is byte-identical to one without this code path). + pub fn audit_create_with_ctx( + &mut self, + handle: u32, + kind: &'static str, + ctx: &PpcContext, + mem: &GuestMemory, + source: &'static str, + ) { + if !self.audit.enabled { + return; + } + let lr = ctx.lr as u32; + let entry = self.audit_entry(lr, source, 0); + if !self.audit.focus.contains(&handle) { + self.audit.record_create(handle, kind, entry); + return; + } + let stack = walk_guest_back_chain(ctx.gpr[1] as u32, lr, mem, 6); + self.audit + .record_create_with_stack(handle, kind, entry, stack); + } + /// Record a Set/Pulse/Release/etc. call against a handle. `aux` is the /// previous signal state (or per-export-specific data). pub fn audit_signal(&mut self, handle: u32, lr: u32, source: &'static str, aux: u64) { @@ -675,6 +710,47 @@ impl Default for KernelState { } } +/// Walk the PPC EABI back-chain starting from `sp` (the value in r1 at +/// the moment of capture). Returns up to `max_frames` entries of +/// `(frame_pointer, saved_lr)`. Index 0 is the live frame +/// `(sp, live_lr)` — `live_lr` is the caller-supplied current LR, since +/// it has not yet been spilled to memory by this frame's prologue. +/// +/// PPC convention reminder: a function's prologue stores the caller's +/// LR at `[old_sp - 8]` *before* bumping `r1` down to the new frame. So +/// from the live `sp`, `prev_sp = mem[sp]` and the LR saved in the +/// frame above is at `mem[prev_sp - 8]`. The walk stops on a +/// 0/0xFFFFFFFF/self-loop sentinel — those guard against +/// uninitialized stacks and the topmost frame. +/// +/// This is read-only; it never mutates guest memory or CPU state. +pub fn walk_guest_back_chain( + sp: u32, + live_lr: u32, + mem: &GuestMemory, + max_frames: usize, +) -> Vec<(u32, u32)> { + let mut frames = Vec::with_capacity(max_frames); + if max_frames == 0 { + return frames; + } + frames.push((sp, live_lr)); + let mut cur = sp; + while frames.len() < max_frames { + if cur == 0 || cur == 0xFFFF_FFFF { + break; + } + let prev = mem.read_u32(cur); + if prev == 0 || prev == 0xFFFF_FFFF || prev == cur { + break; + } + let saved_lr = mem.read_u32(prev.wrapping_sub(8)); + frames.push((prev, saved_lr)); + cur = prev; + } + frames +} + #[cfg(test)] mod tests { use super::*; @@ -759,4 +835,64 @@ mod tests { ); assert!(set.iter().all(|h| (h - 0x1000) % 4 == 0)); } + + /// KRNBUG-AUDIT-002: synthesize a 3-level back-chain in mapped guest + /// memory and walk it. Verifies that frame 0 is the live-LR frame and + /// that subsequent frames pull `prev_sp` from `[sp]` and the saved LR + /// from `[prev_sp - 8]`. + #[test] + fn back_chain_walker_resolves_synthetic_frames() { + let mem = GuestMemory::new().expect("memory init"); + let mut state = KernelState::new(); + let base = state.heap_alloc(0x4000, &mem).expect("scratch"); + // Lay out three frames inside the scratch page. Each frame gets + // its own 0x100-byte slot. Frame N's `[sp + 0]` points at frame + // N+1's sp, and frame N+1's `[sp - 8]` holds the LR saved by + // that frame for the call into frame N. + let sp0 = base + 0x100; + let sp1 = base + 0x300; + let sp2 = base + 0x500; + // Back-chain pointers + mem.write_u32(sp0, sp1); + mem.write_u32(sp1, sp2); + mem.write_u32(sp2, 0); // top of stack + // Saved LRs (the LR of the call that reached the *next* frame + // up are stored at the next frame's sp - 8) + mem.write_u32(sp1.wrapping_sub(8), 0xAAAA_BBBB); + mem.write_u32(sp2.wrapping_sub(8), 0xCCCC_DDDD); + + let frames = walk_guest_back_chain(sp0, 0x1111_2222, &mem, 6); + assert_eq!(frames.len(), 3); + assert_eq!(frames[0], (sp0, 0x1111_2222)); + assert_eq!(frames[1], (sp1, 0xAAAA_BBBB)); + assert_eq!(frames[2], (sp2, 0xCCCC_DDDD)); + } + + /// Walker must not loop on a self-referential back-chain (a corrupted + /// frame where `[sp] == sp`). + #[test] + fn back_chain_walker_stops_on_self_loop() { + let mem = GuestMemory::new().expect("memory init"); + let mut state = KernelState::new(); + let base = state.heap_alloc(0x1000, &mem).expect("scratch"); + let sp = base + 0x100; + mem.write_u32(sp, sp); // self-loop + let frames = walk_guest_back_chain(sp, 0x4242_4242, &mem, 6); + assert_eq!(frames.len(), 1); + assert_eq!(frames[0], (sp, 0x4242_4242)); + } + + /// Walker must terminate on the standard top-of-stack sentinel + /// (`[sp] == 0`) without spilling a bogus frame. + #[test] + fn back_chain_walker_stops_on_zero_sentinel() { + let mem = GuestMemory::new().expect("memory init"); + let mut state = KernelState::new(); + let base = state.heap_alloc(0x1000, &mem).expect("scratch"); + let sp = base + 0x100; + mem.write_u32(sp, 0); + let frames = walk_guest_back_chain(sp, 0x8242_0000, &mem, 6); + assert_eq!(frames.len(), 1); + assert_eq!(frames[0], (sp, 0x8242_0000)); + } } diff --git a/crates/xenia-kernel/src/xam.rs b/crates/xenia-kernel/src/xam.rs index 24bb912..0de162e 100644 --- a/crates/xenia-kernel/src/xam.rs +++ b/crates/xenia-kernel/src/xam.rs @@ -215,7 +215,6 @@ fn xam_task_schedule(ctx: &mut PpcContext, mem: &GuestMemory, state: &mut Kernel let message_ptr = ctx.gpr[4] as u32; let optional_ptr = ctx.gpr[5] as u32; let handle_ptr = ctx.gpr[6] as u32; - let lr = ctx.lr as u32; if optional_ptr != 0 { let v1 = mem.read_u32(optional_ptr); @@ -266,7 +265,7 @@ fn xam_task_schedule(ctx: &mut PpcContext, mem: &GuestMemory, state: &mut Kernel if handle_ptr != 0 { mem.write_u32(handle_ptr, handle); } - state.audit_create(handle, "Thread", lr, "XamTaskSchedule"); + state.audit_create_with_ctx(handle, "Thread", ctx, mem, "XamTaskSchedule"); tracing::info!( "XamTaskSchedule: tid={} handle={:#x} hw={} callback={:#010x} message={:#010x}", tid,