fabi/xenia-rs
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Merge xam-handle-stack-trace/p0-multiframe-walker (KRNBUG-AUDIT-002)

Browse Source 
Multi-frame back-chain capture at NtCreateEvent / NtCreateSemaphore /
NtCreateTimer / XamTaskSchedule, gated on --trace-handles-focus. Read-
only diagnostic; lockstep determinism unaffected.

Tests 576 → 581 green. --stable-digest -n 100M instructions=100000002.

Identifies: 0x1004 = 8-instance pool via static ctor at 0x8280F810;
0x100c = singleton inside main(); 0x15e0 = singleton in distinct
cluster. All three are silph-framework dispatchers; producer hunt
continues with vtable/RTTI readout next session.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
This commit is contained in:
MechaCat02
2026-05-03 20:41:12 +02:00
parent 9d45efe5d5 2a9fd1fc86
commit 6440261e2e
6 changed files with 403 additions and 7 deletions
Download Patch File Download Diff File Expand all files Collapse all files

191
audit-findings.md
View File

@@ -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`) | `<UNCREATED>` `<AUDIT_BLIND>` | 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`.

9
crates/xenia-app/src/main.rs
View File

@@ -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.

59
crates/xenia-kernel/src/audit.rs
View File

@@ -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<HandleAuditEntry>,
/// 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());
}
}

12
crates/xenia-kernel/src/exports.rs
View File

@@ -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 {

136
crates/xenia-kernel/src/state.rs
View File

@@ -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));
}
}

3
crates/xenia-kernel/src/xam.rs
View File

@@ -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,