Syplheed-Reborn/docs/re/mission-freeze-resume-spin.md

The in-mission freeze — the resume-spin lead is DEAD, and the freeze is a guest-side spin

Status: 🔴 the reading this file was named for is REFUTED (2026-08-23, later the same day) — see the last section. What survives is a much sharper picture of what a frozen run is doing. The original reading is kept in full below, because the refutation is only legible next to it.

Status of the original claim: 🟡 a strong lead with one inference in it, not a diagnosis. Measured 2026-08-23 on the upstream baseline — the build that already carries the lost-resume fix (c1b57f93b).

What a frozen run looks like

Stage 02, in flight, frozen at TIME 01:02.62 with a radio line caught mid-word — "Katana, Brandon Is ..." (captures/stage02-freeze-at-time-0102.png).

• Two screenshots six seconds apart: byte-identical, max delta 0 (frozen.py).
• The emulator is not dead — it holds ~200 % CPU and its main thread is in state R.
• Everything that normally notices is satisfied: screen_id.py says flight, the process-liveness check passes.

What the log says

The Canary log ends in a spin, and then stops growing at all:

i> F8000008 XThreadF80002AC (3A) Stack: 70B30000-70B70000     <- line 5383
w> F80002AC XThread::Resume: host resume was refused for thread F8000240
w> F80002AC XThread::Resume: host resume was refused for thread F8000240
... 1171 identical lines, to the end of the file ...

(captures/stage02-freeze-resume-spin.log)

• 1 200 refusals in the run; 1 171 of them the single pair F80002AC → F8000240. The remaining 29 are spread over 12 other targets, 2–4 each.
• The spin starts at line 5384, immediately after F80002AC is created.
• The warning's own commit says what normal looks like: "resuming a thread that is not suspended legitimately returns false, and it fires ~7 times in a normal boot". 1 171 on one pair is a 150× anomaly, not noise.
• F8000240 appears in the log exactly once besides the spin — its creation, XThreadF8000240 (37) Stack: 70AA0000-70AB0000. It never calls anything.

And several late threads never ran

Of the frozen process's 79 host threads, 11 have zero CPU time (captures/stage02-freeze-thread-cpu.txt), and four of them are consecutive, late-created guest threads (tids 45871–45874 against 42 9xx for everything else). Zero CPU on a freshly created guest thread is the exact signature of the lost resume that c1b57f93b fixed for the title screen's loader thread.

The inference, named as one: nothing here maps a guest handle (F8000240) to a host tid, so "the zero-CPU threads are the ones being resumed" is a reading of two consistent observations, not a measurement. It is the first thing the next pass should nail down.

What this suggests, and what it does not

The shape is: the game creates a worker CREATE_SUSPENDED, resumes it, the worker never runs, and a manager thread then resumes it again forever while the simulation waits on its result. c1b57f93b closed one window of that race — between publishing state_ and publishing suspend_count_ in ThreadStartRoutine. This freeze happens in a build that has that fix, so either there is a second window, or this is a different mechanism that merely looks alike.

🔴 Not established: that the freeze is caused by the refused resumes at all. The refusals could be the game's reaction to a worker that is stuck for an unrelated reason — a "kick it again" loop around a wait that never signals. The log cannot separate those two, because log_mask=13 has the Kernel channel disabled (a trap the corpus already recorded), so not one of F8000240's waits or its entry point is visible.

How often

Three Stage 02 runs today reached flight: one ran normally for minutes and stepped REMAINING OB twice; the other two froze — one about ten seconds in, this one at TIME 01:02. So roughly two in three, matching the ~1-in-3 success rate the title-screen lost resume used to have.

The next experiment, stated concretely

Reproduce with the Kernel channel on — LOG_MASK=12 LOG_LEVEL=3, the combination the earlier work found necessary — and then:

1. map F8000240 to a host tid (its ExCreateThread entry point and the XThread… comm name are both in reach) and confirm it is one of the zero-CPU threads;
2. read what it was created to do and what it waits on;
3. check whether NtResumeThread on it ever returns before the spin.

Until that is done this file is a lead, not a cause.

---

🔴 REFUTED, the same day — and what the freeze actually looks like

The refused-resume spin is normal

A run with the Kernel channel on (LOG_MASK=12 LOG_LEVEL=3) was analysed while it was still flying happily, as the control this file never had. It had 2 738 refused resumes on a single pair — more than the 1 171 the frozen run showed — and the target thread's own lines say exactly what the pattern is:

d> F8000204 NtSuspendThread(F8000204, 70AAFE50(00000000), ContextArg)
d> F8000204 Thread F8000204 self-suspending
d> F800026C NtResumeThread(F8000204, 70B6FBF0(00000000))
w> F800026C XThread::Resume: host resume was refused for thread F8000204
d> F8000204 Thread F8000204 resumed

The game runs a self-suspending worker: it suspends itself, a manager thread resumes it, thousands of times. A self-suspended thread is not host-suspended, so the host Resume() legitimately returns false every cycle and the warning fires every cycle. 3 115 refusals against 3 115 resumes in that run — one per cycle, exactly.

Where the error came from, stated so it is not repeated: the warning's commit says "it fires ~7 times in a normal boot", and this file generalised that from boot to gameplay, where the number is thousands. The "150× anomaly" was an artefact of comparing gameplay against a boot-time baseline. The frozen run's 1 171 was never anomalous — it is simply what was in flight when everything stopped, and the log ends in it because nothing else came after.

Also withdrawn: "11 of 79 host threads have zero CPU" is not evidence either. The healthy run has 4 threads created and never executed too.

What a freeze actually is — measured with the Kernel channel on

The freeze reproduced in the instrumented run, at TIME 03:37.83 (captures/stage02-freeze-at-time-0337.png), and the log then tells a much more specific story (captures/stage02-freeze-kernel-tail.log):

• The last kernel event in the entire 50 MB, 690 000-line log is Thread F8000204 self-suspending.
• self-suspending 3 116 against resumed 3 115 — exactly one self-suspend never matched.
• But the resumer never calls NtResumeThread again at all. So the resume was not issued and dropped; the resumer stopped too. Everything stopped together, and this thread's self-suspend just happens to be last.
• 🔴 So "a lost resume froze it" is not supported. What is left is a stall that silences every thread at once.

The guest is spinning, not deadlocked

Sampled over 10 s while frozen (captures/stage02-freeze-cpu-while-frozen.txt): the main thread is in state R and gains 409 ticks — ~40 % of a core — and several guest threads gain 15–57 each, ~680 ticks total, while not one kernel call is made. A host-side deadlock in the kernel layer would show blocked threads and no CPU. This is guest code going round a loop, waiting on something in guest memory that never changes.

Two smaller corrections from the same run

• 🔴 "The log stopped growing" is not a freeze detector. The kernel log goes quiet for 25 s and more during perfectly normal flight. Only frozen.py's frame comparison distinguished the two here, and it was right both times.
• ✅ 0xbdb59668 again: RAM 12 against HUD 012 on this run — 4 of the 6 runs measured.

The next experiment

The question is now narrow: which guest PC is the spinning thread executing? Canary knows every XThread's PPC context, so a diagnostic that dumps each thread's guest PC on demand (or after N seconds without a frame) would name the loop, and xenia-rs/sylpheed.db can then say what function it is in. That is a build-canary run plus a reproduction — the cost is worth stating up front, and it is the only avenue that does not involve guessing.

---

The frozen world is quieter, not silent — the delta measured at last

The measurement live_delta.py was written for, taken on a run that froze mid-probe (2026-08-23):

state	words changed	window	share of the 357.7 MB of data
running	1 863 296	4 s	2.08 %
frozen	180 952 – 235 973	6 s	0.20 – 0.26 %

So a frozen guest is about 12× quieter per second than a live one, and still changing ~30 000 words a second. Whatever is spinning is doing real work.

Where, by 1 MB region, while frozen:

0xbf900000   83 246 words        0xbe000000    5 902
0xbfa00000   55 515              0xbe300000    3 978
0xbe100000   15 914              0x70400000    2 371
0xbe200000    9 882              0x70500000    2 366

The 0x704…/0x705… pages are guest thread stacks — every XThread…Stack: line in the boot log is in 0x70xxxxxx — which is what a spinning thread's frame churn looks like. The two big blocks at 0xbf900000/0xbfa00000 are the bulk of it, and one visible cluster there is a long run of identical floats stepping together (0x39174083 → 0x39174079 across hundreds of consecutive words), which reads like a buffer being refilled rather than a lock being polled.

🔴 Not yet interpretable, and the reason is stated rather than glossed: there is no matched region breakdown for the running case — the control was taken before the region summary existed, so "these regions are busy while frozen" has nothing to be compared against. The regions may simply be the busiest regions in the game at all times. That comparison is one run away and is the obvious next measurement.

---

2026-08-24 — scoping the "which guest PC is spinning" experiment

The next step this file named turns out to be more expensive than it looked, and the reason is worth writing down before someone starts it:

• 🔴 Xenia's stack walker is a stub on POSIX. stack_walker_posix.cc is twenty lines: StackWalker::Create logs "Stack walker unimplemented on posix" and returns nullptr. So ThreadDebugInfo::guest_pc — the field the debugger would fill — is never populated on this platform, and the clean in-emulator route does not exist.
• 🔴 PPCContext carries no live PC either. The guest PC lives in host registers between block boundaries; there is no field to read.
• 🟡 A reverse host→guest map is buildable but is a real feature. The code cache already learns the mapping when it emits code (X64CodeCache::OnCodePlaced(guest_address, function_info, …)); a sorted host-range → guest-function index would make a host RIP interpretable. That is ~50 lines plus a way to sample another thread's RIP, which on POSIX means piggybacking on the signal machinery xenia already uses to suspend threads.

The cheap route that exists instead: gdb. It is installed (/usr/bin/gdb), and ptrace_scope is 1, so a debugger may only attach to its own descendants — which means gdb -p <pid> on a running emulator will be refused, but launching the emulator under gdb works. run-canary execs $XENIA_BIN, so pointing XENIA_BIN at a small wrapper that execs gdb --args <real binary> "$@" keeps the lockfile and the flags intact and makes gdb the parent. A thread apply all bt on a frozen run would not name JIT frames, but it would immediately separate "spinning inside guest JIT code" from "spinning in a xenia loop" — which is the fork this investigation is stuck on.

Not attempted here; recorded so the next pass starts from the right end.

---

✅ 2026-08-24 — the freeze, seen from inside: every thread is in a WAIT

The gdb route works. run-canary execs $XENIA_BIN, so /sylph-home/re/bin/gdb-wrap/xenia_canary (a wrapper that execs gdb --args <real binary> "$@") keeps the lockfile, the flags and the process name intact — gdb forks and execs the real binary, so ps -C xenia_canary still finds the inferior — and being the parent satisfies ptrace_scope=1. The Release binary is not stripped (26 595 symtab entries), so frames carry names. handle SIGSEGV/SIGBUS/SIG32-35 nostop noprint pass is mandatory: xenia uses SIGSEGV for guest memory watches and the real-time signals for thread suspend, and without those lines gdb stops the world on the first one and the boot never happens.

A Stage 02 run froze after ~4 minutes of flight (screen still flight, not GAME OVER), and gdb_bt.sh took backtraces of all 79 threads (captures/stage02-freeze-gdb-backtraces.txt).

Every single one is in a wait. Not one thread is executing guest code or sitting in a xenia loop:

• the guest threads are in KeWaitForSingleObject / NtWaitForSingleObjectEx / XThread::SelfSuspend, i.e. PosixConditionBase::Wait → pthread_cond_wait;
• the GPU command processor is parked in its own Wait, idle;
• the main thread is in poll().

But it is still burning CPU — in the wait path

Over 10 s while frozen, /proc/<tid>/stat shows 1 253 ticks spread over the process:

ticks / 10 s	thread	where it is
403	xenia_canary (the TimerQueue thread)	nanosleep inside TimerQueue::TimerThreadMain
290	XThreadD61F96C0	KeWaitForSingleObject
274	XThreadD45FF6C0	KeWaitForSingleObject
59	XMA Decoder	—

A thread genuinely blocked in pthread_cond_wait cannot burn 28 % of a core. So those two guest threads are cycling: a timed wait that keeps expiring and being re-entered, with the TimerQueue thread servicing the timers hot. Three samples minutes apart show them in exactly the same frames.

🔴 This refines the earlier reading rather than confirming it. "The guest is spinning, not deadlocked" was right that CPU is burned and wrong about where: the burn is in the wait path inside the kernel layer, not in guest code. The shape is a guest event that never gets signalled, with its waiters looping through short timed waits.

Next, and now cheap: read which object those two threads are waiting on — the handle is an argument to KeWaitForSingleObject, one info args-equivalent away now that a debugger can be attached at will — and find who was supposed to signal it.

🔴 2026-08-24 — reading the wait target from the log does not work: the flag is too expensive

The obvious next move — find which object those two threads wait on by logging KeWaitForSingleObject — is blocked by its own cost, and the numbers are worth recording so nobody pays them twice.

KeWaitForSingleObject is declared kHighFrequency (xboxkrnl_threading.cc, DECLARE_XBOXKRNL_EXPORT3(..., kHighFrequency)), and shim_utils.h suppresses those unless --log_high_frequency_kernel_calls=true. That flag exists, so it was tried:

	without the flag	with it
KeWaitForSingleObject lines	0 (the corpus's "kHighFrequency waits are simply unlogged" note, confirmed)	1 944 in the first 40 s
log growth	~1 MB / 25 s	157 MB in 10 minutes, 175 MB in 17
boot progress	title in ~3 min	17 minutes and the screen was still BLACK — not even the intro movie, 0 movie probes from skip_intro

So the flag does not merely add volume, it slows the emulator past usability: the first attempt was scored BOOT FAILED purely because skip_intro's fixed 600 s budget expired. That is now a knob (SKIP_INTRO_TIMEOUT), and EXTRA_FLAGS passes one-off cvars — but a 2 400 s budget did not help either, because the boot was not going to finish.

What to do instead, in order of cost:

1. A targeted log line in Canary. Log the object pointer only when a wait has already timed out N times on the same thread — the freeze's signature is a wait that expires and re-enters, so a counter makes it self-selecting and costs nothing on a healthy run. One small patch plus a build-canary, and the build is already configured.
2. gdb, reading the shim argument. A debugger can be attached at will now, but the Release binary has no DWARF (No debugging symbols found — symtab only), so info args is unavailable and the PPCContext* would have to be dug out of a stack frame by hand. Fragile, but free.

✅ 2026-08-24 (later) — the instrument exists: --log_stuck_waits

Canary branch auto/re-wait-timeout-probe (820696c11, off the upstream baseline) adds a counter in xeKeWaitForSingleObject: consecutive X_STATUS_TIMEOUT results on the same object, per thread, logged at 100 and then every 500. It is self-selecting — a wait that is being satisfied never builds a streak — so it can be left on where the global high-frequency flag cannot. Binary archived at /sylph-home/re/bin/waitprobe/xenia_canary; drive it with EXTRA_FLAGS=--log_stuck_waits=true.

Healthy-run baseline, which is what a frozen run has to be compared against. Over a 25-minute Stage 02 run that never froze, the probe emitted 27 lines, all of them the same pair:

w> F800004C [wait-probe] thread F800004C has timed out N times in a row on
   object BE56BB5C (type 2), timeout=18446744073709251616

— one thread polling one Event (XObject::Type 2) at guest VA BE56BB5C with a relative timeout of -300 000 × 100 ns ≈ 30 ms. That is a legitimate poller, not a symptom, and its streak reached 8 000 while the game was running perfectly.

🔴 Corrected before it became folklore: the cvar's help text first claimed the probe is silent on a healthy run. It is not — it is quiet, and one poller dominates. The freeze signal will therefore be the appearance of a new (thread, object) pair, not the presence of output.

Not settled: the freeze did not reproduce in this run, so there is no frozen sample to compare yet. That is the whole of the next step, and the instrument and its control are now in place for it.

2026-08-24 — the control holds on a second run; the freeze did not come

A second Stage 02 run with --log_stuck_waits=true, watched end to end by freeze_watch.sh: NO FREEZE within 1500s — about 25 minutes of flight, and the probe again reported exactly one pair, thread F800004C on object BE56BB5C (type 2), 24 lines against the first run's 27.

So the healthy-run control is now measured twice, independently, and it is the same single legitimate poller both times. Anything else the probe prints during a freeze is signal.

🟡 And the cost of catching one is worth stating. Two consecutive runs did not freeze; the freezes earlier in the day came in a cluster. Across the session roughly half the runs that reached flight ended early (freeze or GAME OVER), but they are not evenly distributed, so "wait for a freeze" is a ~30-minute lottery ticket per run rather than a reliable step. The instrument, the watcher and the control are all in place; what is missing is one frozen sample.

🔴 2026-08-24 — a freeze WAS caught, and the stuck-wait probe says nothing

The fourth run froze 9 seconds into the watcher's window, in flight (freeze_watch.sh confirmed the HUD was still on screen), and the probe built for exactly this moment reported the healthy-run baseline and nothing else (captures/stage02-freeze-stuck-wait-probe.txt):

FROZEN IN FLIGHT at 9s
=== stuck-wait probe: (thread, object) pairs ===
     25 thread F8000048 on object BE56BB5C (type 2)

One pair — the same poller, on the same object VA as every healthy run (only the thread handle differs, handles being per-run). No new (thread, object) pair appeared. The hypothesis the probe was built to catch is refuted: the freeze is not a guest thread looping on KeWaitForSingleObject timeouts against one object.

And the CPU signature is unchanged from the gdb run, so the burn is real:

CPU over 10 s while FROZEN: 1 255 ticks over 79 threads
  401  xenia_canary      (the TimerQueue thread), state R
  292  XThreadA91FF6C0
  280  XThreadA81FE6C0

What the probe's blind spots leave

Two readings survive, and each is a specific blind spot of the instrument rather than a vague "something else":

• The waits cycle over DIFFERENT objects. The counter only advances while the object is the same, so a thread rotating over two or more handles never builds a streak and is invisible. This is the likelier of the two.
• The waits SUCCEED. A signal/wait ping-pong returns X_STATUS_SUCCESS, not X_STATUS_TIMEOUT, so there is nothing for a timeout counter to count — which would also fit the log evidence from the kernel-channel run, where the self-suspending worker cycled thousands of times successfully.

Next: a second version that counts calls per thread per second regardless of object or result, and logs a thread whose rate is absurd along with the object and the return value. That is a small edit to the same hook plus another build — and, as ever, another run of the freeze lottery, which this time paid out on the first attempt.

✅ 2026-08-24 — the call-rate probe, and what its baseline already proves

log_stuck_waits v2 (canary auto/re-wait-timeout-probe 597740046) counts every call to KeWaitForSingleObject per thread in a one-second window, records how many distinct objects it saw, and logs the last object and the last result when the rate passes 500/s. That covers both blind spots the v1 streak counter left.

The healthy-run baseline is itself a result. Over a full ~22-minute Stage 02 run that ended in GAME OVER rather than a freeze:

thread	windows over 500/s	peak	distinct objects
F8000008 (main)	224	1 235 calls/s	up to 13
F8000234	47	919	up to 10
F800025C	41	819	up to 7
F8000204, F8000270	1 each	562 / 730	2 / 1

and the last result was 00000000 — X_STATUS_SUCCESS — in all 314 windows. Not one timeout.

So the game's normal mode is exactly what v1 could not see: hundreds of waits a second, over up to thirteen different objects, all succeeding. That confirms blind spot (b) directly and explains why a timeout-streak counter reported the same single poller during a freeze as during healthy play — it was measuring a phenomenon the game barely exhibits.

🟡 Consequence for the instrument: 500/s is not self-selecting; the main thread clears it 224 times in a normal run. The freeze signal has to be a different shape — a thread far above 1 235/s, or a new thread, or a window whose result is not SUCCESS. That comparison needs a frozen sample, which run 5 did not provide (GAME OVER at ~22 min).

🔴 A THIRD failure mode: EMULATOR GONE — the process dies with no crash marker

Run 6 (2026-08-24) ended neither in a freeze nor in GAME OVER. freeze_watch.sh reported EMULATOR GONE at 810s, and the Canary log simply stops in the middle of ordinary activity:

i> F8000008 [file-pad] #3421 buttons=0000 lt=0 rt=0 lx=-7412 ly=-3620 rx=0 ry=0
w> F8000254 XThread::Resume: host resume was refused for thread F80001E8
w> F8000254 XThread::Resume: host resume was refused for thread F80001E8   <- end of file

Zero occurrences of CRASH, Access Violation, GUEST-THROW, assert, Fatal or abort in the whole 1.1 MB log. No shutdown line either. The process is just gone.

And on the next occurrence the shell named it: Killed. Run 8 died 54 s into its boot, and launch_mission.sh printed

line 74: 176880 Killed   nohup run-canary --apu=sdl --log_mask=13 ...

which is bash reporting SIGKILL. So this is not an internal fault at all — something outside the process is killing it.

Memory pressure is a suspect, and only a suspect

The container's cgroup, read immediately after, with no emulator running:

memory.max	7 516 192 768 (7 GiB)
memory.peak	7 516 196 864 — the ceiling was reached
memory.events: max	4 421 allocation stalls at the limit
memory.events: oom_kill	0
memory.stat: file (page cache)	4.68 GB
memory.stat: shmem	358 MB (leftover /dev/shm/xenia_memory_*)
memory.stat: anon	683 MB

So the box really was running at its ceiling, and page cache — inflated by the disc-wide format sweeps, which read every .pak — was most of it. 🔴 But oom_kill is 0, so the cgroup OOM killer did not do it, and nothing here shows what did. Recorded as an unexplained third failure mode rather than an OOM story, because the counter that would have proved OOM says zero.

🔴 Checked again immediately after run 8's SIGKILL, and it is still not OOM. oom_kill remained 0 and the max (allocation-stall) counter did not move from 4 421 — so during run 8 the cgroup never even reached its limit, memory.current being 5.35 GB of 7 GiB. The host had 13.8 GB available when checked. Two kills, no OOM evidence either time.

So the cause is genuinely unidentified, and the next occurrence is now instrumented rather than reconstructed: freeze_watch.sh samples host MemAvailable, the cgroup's memory.current and its oom_kill counter on every poll, and dumps the last five samples when it sees the process disappear.

Hygiene that follows either way: /dev/shm/xenia_memory_* survives a dead run (342 MB resident here) and run-canary only clears it at launch; and vm.drop_caches is not writable in the container (read-only /proc/sys), so page cache can only be left to the kernel to reclaim. Clearing the stale shm files between runs is the one lever available.

The v2 baseline holds on a second healthy run (run 7)

NO FREEZE within 1100s, and the same shape as run 5 — so the control is measured twice:

thread	run 5 windows / peak / objects	run 7 windows / peak / objects
F8000008 (main)	224 / 1 235 / 13	167 / 947 / 13
F8000234	47 / 919 / 10	35 / 830 / 8
F800025C	41 / 819 / 7	28 / 737 / 7
result	SUCCESS ×314	SUCCESS ×230

Same three threads, same ceiling of 13 distinct objects, and not one non-SUCCESS window in 544 across both runs. The v1 stuck-wait side reported its usual single pair (BE56BB5C) and nothing else.

Run tally since v2: three runs, no frozen sample — GAME OVER at ~22 min (run 5), EMULATOR GONE at 810 s (run 6), and no freeze in 1 100 s (run 7).

🔴 A third kill, with a contemporaneous trace — and it REFUTES memory pressure

Run 9 died the same way at t=486 s, and this time the watcher's own sampler had been running the whole time:

EMULATOR GONE at 486s
t=344s host_avail=12159MiB cgroup=6388MiB oom_kill=0
t=382s host_avail=12061MiB cgroup=6490MiB oom_kill=0
t=411s host_avail=12001MiB cgroup=6533MiB oom_kill=0
t=453s host_avail=12066MiB cgroup=6489MiB oom_kill=0
t=486s host_avail=13163MiB cgroup=5375MiB oom_kill=0   <- after the kill

At the moment of death the cgroup held 6.5 GB of its 7.0 GB — not at the limit — the host had 12 GB free, and oom_kill was 0. 🔴 So the memory suspicion recorded above is refuted: three kills, no OOM record on any of them, and the one with a full trace shows headroom on both the cgroup and the host.

What was also checked and found clean: no stray process of mine was running (only the pilot), and the kills do not fall on a clock — 08:31, 09:00, 09:14, so gaps of ~29 and ~14 minutes rather than a period.

Stated as a container-level blocker rather than chased further: something outside the emulator SIGKILLs it, roughly one run in three, and nothing available in here attributes a SIGKILL to its sender (no dmesg, no audit, and ptrace_scope=1 limits strace to my own descendants). The practical response is to stop designing experiments that need a long run: the counter transitions the OB work needs all happen in the first minutes of flight.

---

✅ 2026-08-24 — THE KILL IS SOLVED, and it was never the game: a Stop hook

Everything above about the EMULATOR GONE / SIGKILL failure mode has a one-line cause, and it is not in the emulator, the container runtime or the kernel. It is in this project's own Claude Code configuration — /work/.claude/settings.json:

"Stop": [{ "hooks": [{ "type": "command", "command":
  "for name in xenia_canary xenia-rs; do pids=$(pgrep -x \"$name\"); ...
   kill $pids; sleep 0.2; kill -9 $pids; ... 'Stop hook killed %d stale xenia process(es)'"
}]}]

A Stop hook fires at the end of every agent turn and kill -9s any running xenia_canary. So every run that "died mysteriously" died at a turn boundary, which is exactly why the timings looked random from inside the run (810 s, 54 s, 486 s) and why nothing in the guest, the cgroup or the host explained them.

What survives from the investigation is only the measurement, not the story: the memory readings were real and did refute memory pressure as a cause — the cgroup was at 6.5 GB of 7.0 and the host had 12 GB free at the moment of a kill. That refutation was correct; it just was not pointing at anything.

🔑 The method lesson, which is the part worth keeping

When a process dies at a session boundary, check the harness before instrumenting the guest. Three iterations went into this: a failure mode documented, a memory hypothesis raised, a per-poll memory sampler written and committed, host and cgroup counters read — all of it downstream of an assumption that the kill came from outside the agent. The one place not looked at was the agent's own configuration, and that is where it was. The systemMessage the hook prints ("Stop hook killed 1 stale xenia process(es)") is surfaced to the user after each turn, so the answer had been on screen the whole time.

The rule that follows

An emulator experiment must complete inside a single turn. Nothing survives the turn boundary, so:

• do not "leave a run going for the next tick" — it will be killed;
• prefer experiments whose evidence arrives in the first minutes of flight (the REMAINING OB transitions all do — that is why the two-pass bit-level test succeeded where the long freeze-watches did not);
• a watcher armed for 1 500 s can only ever watch for the rest of this turn.

---

2026-08-25 — one new data point: a freeze with zero refused resumes

The refuted-resume-spin section above rests on refused resumes being normal — thousands during gameplay, more in a healthy run than a frozen one. A run from today strengthens that refutation from the other side.

run	XThread::Resume: host resume was refused	outcome
2026-08-24 (probe-canary.stdout, 7933 lines)	2447, ending the log	—
2026-08-25 (launch_mission-canary.stdout, 1147 lines)	0	froze at t ≈ 267 s, black screen

A mission can freeze with not one refused resume in the whole log. The earlier refutation said the warning is too common to be the cause; this says it is not even necessary. The two together close the lead properly.

Also checked and refuted today, before finding this file: the burst of BaseHeap::Release failed because address is not a region start at the end of the short log looks like a freeze signature, and is not — in the longer log the same failures span lines 1044–5210 and the log continues for 2 700 lines afterwards. They start at mission load in both runs and are routine.

🔴 Method: this ground was covered before, and the index is why it was covered again

Both of the above were re-derived today from raw logs, and both were already settled in this file — as was 0xbdb59668, which a previous iteration "discovered" independently. That is twice in one session.

The cause is mechanical rather than a lapse of memory: docs/re/INDEX.md listed 20 of 43 notes, and none of the recent ones, so searching the index for prior work on the freeze returned nothing. The corpus was searched; the search was simply blind.

Fixed: INDEX.md now carries a generated table of every note under docs/re/, 59 entries with title and status, and says outright that it should be searched before starting an investigation. Regenerating it is a few lines of Python and should be redone whenever notes are added.

---

2026-08-25 — the wait is confirmed as KeWaitForSingleObject, but info args will not work

Two corrections to the plan this file leaves for the next pass, both cheap to establish and both worth having before a run is spent on them.

✅ Verified: the export in the frozen frame is KeWaitForSingleObject

The backtrace's shim frame carries its ordinal as a template parameter:

xe::kernel::shim::ExportRegistrerHelper<(KernelModuleId)0, (unsigned short)176, …>

176 decimal is 0xB0, and xboxkrnl_table.inc:190 reads:

XE_EXPORT(xboxkrnl, 0x000000B0, KeWaitForSingleObject, kFunction),

So the two hot threads really are in KeWaitForSingleObject — previously read off the frame names, now pinned by ordinal.

🔴 Corrected: there is no DWARF, so the handle is not one info args away

This file's next step says the wait target is "one info args-equivalent away now that a debugger can be attached at will". That is not true of this binary:

readelf -S xenia_canary | grep -c 'debug_info|debug_line'   -> 0
.debug* sections                                            -> none
symtab entries                                              -> 27 807

The Release build is not stripped, which is why frames carry function names, but it has no debug info at all. gdb can therefore name a frame and nothing inside it — no info args, no p *this, no struct members. The earlier note conflated "not stripped" with "has debug info"; they are different things.

The two routes that remain, with their real costs

1. Prologue-guided stack read. XObject::Wait's this arrives in RDI and is almost certainly spilled to a known stack slot. Disassembling the prologue (x/20i) locates the slot, and the frozen frame's RBP/RSP then give the pointer, from which the object's vtable identifies its type. No rebuild, but it is per-frame archaeology and must be redone if the binary changes.
2. A RelWithDebInfo build via build-canary. Makes info args, p *this and member access work as the note assumed, at the price of a full compile and a binary that is not the one every other measurement in this corpus was taken against.

Route 1 is cheaper and keeps the oracle identical; route 2 is what makes this and every future freeze question easy. Neither is attempted here — recorded so the next pass picks with the costs visible instead of discovering the missing DWARF mid-run.

✅ 2026-08-25 — route 1 is viable: this lives in %rbx, and .eh_frame can restore it

The prologue-guided route turns out to need no archaeology at all, and the groundwork is pure static analysis — no run spent finding it out.

XObject::Wait keeps this in a callee-saved register, not a stack slot:

8fbc90 <xe::kernel::XObject::Wait(unsigned int, unsigned int, unsigned int, unsigned long*)>:
  8fbc90  push %rbp / push %r15 / push %r14 / push %rbx / push %rax
  8fbc97  mov  %r8,%r15
  8fbc9a  mov  %ecx,%ebp
  8fbc9c  mov  %rdi,%rbx        <-- `this`

And the binary has full unwind information, which is what makes that recoverable from a deep frame. .eh_frame is present with 127 231 FDEs — it survives in Release builds because C++ exceptions need it — and the FDE covering Wait tracks rbx explicitly:

FDE pc=00000000008fbc90..00000000008fbde2
   LOC           CFA      rbx   rbp   r14   r15   ra
   8fbc90        rsp+8    u     u     u     u     c-8
   8fbc91        rsp+16   u     u     u     u     c-8

So from a frozen thread parked in pthread_cond_wait, frame 3 (the XObject::Wait frame) plus info registers rbx yields the XObject* being waited on — gdb reconstructs callee-saved registers during the unwind from .eh_frame alone. Reading x/gx $rbx then gives the vtable pointer, and vtable symbols are in the symtab (_ZTVN2xe6kernel6XEventE and friends), so the object's concrete type is identifiable without any debug info.

Revises the previous entry, which listed route 1 as "per-frame archaeology" and route 2 (a RelWithDebInfo rebuild) as the way to make this easy. Route 1 is neither expensive nor fragile: two gdb commands per thread, no rebuild, and the oracle stays byte-identical to the binary every other measurement used.

Not yet executed on a frozen run — that is the next step, and it is now a small one.

✅ 2026-08-25 — the technique works end to end: the waited object is an XEvent

Executed on a live run under gdb. For every thread whose frame 3 is XObject::Wait:

(gdb) === T106 ===
#3  0x0000555555e4fd80 in xe::kernel::XObject::Wait(...)
(gdb) rbx            0x7ffd097178d0
(gdb) 0x7ffd097178d0:   0x00005555562db8f0

0x5555562db8f0 minus the PIE base 0x555555554000 is 0xd878f0, and the symbol table has:

0000000000d878e0 D vtable for xe::kernel::XEvent

The stored pointer is the vtable symbol +16 — offset-to-top and RTTI come first — so it matches exactly. The object being waited on is an xe::kernel::XEvent, and the same vtable appears for every waiting thread sampled (T106, T97, T96, T80, …), while the this pointers differ, i.e. many threads waiting on different XEvent instances.

The whole chain — frame 3 → rbx → x/1gx → symtab — needs no DWARF and no rebuild, exactly as the static groundwork predicted.

🟡 Two honest caveats

This is a healthy-play snapshot, not the freeze. The capture landed at 195 s of flight and screen_id reported flight with mean=(17.4, 19.1, 25.1) — not the black screen. Boot under gdb costs ~300 s and the whole experiment must fit in one call (a timeout kills the process group, taking the emulator with it — an earlier attempt lost its run that way), which left too little time to reach the ~267 s freeze. So this says what threads wait on during normal play. That is the control the frozen capture never had, but it is not the frozen case.

The this addresses look like host stack, which is odd. 0x7ffd097178d0, 0x7ffc8c1c2f10 and the rest sit in the range host thread stacks occupy, not where a heap-allocated kernel object would. Either xenia places these objects somewhere unusual, or rbx at frame 3 is not Wait's this after the unwind and the vtable match is a coincidence — an exact +16 match on a known symbol is hard to get by accident, but the address range is not what was expected and is recorded rather than explained away.

The check that would settle it: read the same value two ways — compare rbx against the object pointer recovered from the shim frame above, or dump a few words at $rbx and see whether they look like an XEvent (a vtable, then a KernelState*, then handle/type fields) or like saved registers.

🟡 2026-08-25 — refined: two object types, and the read is self-checking

Re-extracting the same capture per thread rather than by grep changes the picture, and qualifies the previous entry.

Of 18 threads whose frame 3 is XObject::Wait:

[rbx]	count	resolves to
0x5555562db8f0	8	vtable for xe::kernel::XEvent + 16
0x5555562dbb40	2	vtable for xe::kernel::XSemaphore + 16
a pointer into the mmap region	8	not a vtable — see below

So the waits are on XEvent and XSemaphore objects, two distinct kernel types, and the earlier "the object is an XEvent" was right for the majority but not the whole picture.

✅ The 8 non-vtable readings are the method checking itself

For eight threads [rbx] is something like 0x7ffd08bcdeb0 — inside the mmap region, not in the binary's .data where vtables live. A polymorphic object's first word is always a vtable pointer, so those reads are simply not this: rbx could not be restored for that thread's frame, and the unwind handed back whatever the register happened to hold.

That is a useful property rather than a flaw. The read validates itself: a value is a genuine object pointer only if [rbx] lands in the binary's vtable range and resolves to a vtable for … symbol. Anything else is discarded rather than interpreted. Ten of eighteen resolve; the rest are honestly unknown.

This also answers the previous entry's worry about the 0x7ffc…/0x7ffd… addresses looking like stack. They are the shared mmap region, which holds thread stacks and large allocations, and the vtable check — not the address range — is what separates an object from a stack slot.

🔴 The follow-up run never booted

The run that would have added /proc/<pid>/maps classification and a wider x/8gx dump died immediately: EMULATOR GONE at 0s (before the window appeared), BOOT FAILED (skip_intro exit 4). Most likely a stale emulator or lockfile from the preceding gdb session — the gdb wrapper leaves a differently-parented process tree and the usual cleanup did not catch it. So the map classification and the multi-word object dump are still unrun, and the frozen-state capture still has not been taken.

✅ 2026-08-25 — WITHDRAWN: the 8 "unrestorable rbx" readings are a second function

The entry above is wrong where it matters, and the disassembly says so plainly. rbx was restored perfectly for all 18 threads. Eight of them are not in XObject::Wait at all — they are in XObject::WaitMultiple, and %rbx does not mean the same thing in the two functions. The grep that produced the table matched XObject::Wait as a substring, so WaitMultiple frames were pooled in with Wait frames and read with the wrong rule.

Reading the two prologues settles it (baseline c1b57f93b, no run needed):

8fbc90 XObject::Wait(this, ...)                  8fbfc0 XObject::WaitMultiple(count, objects, ...)
  push %rbp/%r15/%r14/%rbx/%rax                    push %rbp/%r15/%r14/%r13/%r12/%rbx
  mov  %r8,%r15                                    sub  $0x218,%rsp
  mov  %ecx,%ebp                                   mov  %rsi,%rbx      <-- rbx = XObject** objects
  mov  %rdi,%rbx      <-- rbx = this               mov  %edi,%ebp      <-- ebp = count

and the loop just below WaitMultiple's prologue confirms what rbx points at by using it:

8fbff0:  mov (%rbx,%r15,8),%rdi     ; rdi = objects[i]
8fbff4:  mov (%rdi),%rax            ; rax = objects[i]->vtable
8fbff7:  call *0x20(%rax)           ; a virtual call on it

So for a WaitMultiple frame [rbx] is objects[0] — an XObject*, not a vtable — which is exactly the shape of the eight "misses": pointers into the mmap region where the kernel objects live. They needed two derefs, not one. The correct read is [[rbx + 8i]] for i < ebp.

Predicted values from the healthy capture, to be checked against the next run: objects[0] was 0x7ffd08bcdeb0 for threads 79 and 80 and 0x7ffcfc0911f0 for thread 78 — two threads sharing one object is itself consistent with a group of workers waiting on the same handle.

What survives from the previous entry: the two confirmed object types (XEvent ×8, XSemaphore ×2) and the self-validating read — a value counts only if it resolves to a vtable for … symbol. What is withdrawn: "rbx could not be restored for eight threads", and with it the claim that the reading is only 10/18 reliable. The unwind was never the problem; the parser was.

freeze_waitobj.sh now parses the function name and frame index out of the backtrace instead of assuming frame 3, and applies the matching rule to each.

✅ 2026-08-25 — the WaitMultiple read confirmed, and a third object type

Ran it. The prediction from the section above holds: applying the second deref to WaitMultiple frames turns every one of the former "misses" into a resolved object. Full table in data/waitobj-s02.txt; 23 wait frames, 30 objects, and nothing unresolved.

waited on	count
xe::kernel::XEvent	20
xe::kernel::XSemaphore	9
xe::kernel::XTimer	1

XTimer is new — it never appeared before because the only thread waiting on one (T76) is a WaitMultiple thread, and those were exactly the frames the old parser read wrongly.

Every WaitMultiple thread waits on a pair, never more: six on (XEvent, XSemaphore), one on (XEvent, XTimer), one on (XEvent, XEvent). Threads 78/79/80 share one objects array contents and 64/65 another, so these are worker groups on a common handle.

🟡 %ebp is not a usable count

The plan was to bound the array with the count in %ebp. It reads 0x0 on every frame, and the disassembly says why: WaitMultiple reuses ebp at 8fc158 (mov 0x10(%rax),%ebp) once it is past the prologue, so the count is gone by the time these captures interrupt. The array is bounded instead by reading until an entry stops resolving — past the last real object the words are 0x0 and gdb reports Cannot access memory at address 0x0. Same self-validating rule as everywhere else here, and it needs no register.

🔴 The frozen capture STILL has not been taken — the freeze did not happen

The second capture is labelled frozen and is not. screen_id reads flight at the capture (green=0.0140 mean=(30.3,31.4,36.4)), 367 s into the mission, and three follow-up screenshots out to ~470 s of flight also read flight with a drifting frame mean, so the picture was still moving. The mission simply did not black-screen this run.

So the healthy -> frozen diff in the data file is two healthy captures, and its 20 -> 18 / 9 -> 8 is three threads (T105, T68, T69) having exited — normal churn, not a freeze signature. Recorded as-is rather than presented as a result.

This also puts a question against the "black-screens at ~4.5 min" bound used to plan these runs. One confound is named and not ruled out: this run is under gdb, which slows the emulator (boot to title took 207 s), so 470 s of wall-clock may be well short of 270 s of guest time. Until that is measured the honest statement is that the ~270 s figure is a wall-clock observation from ungated runs and does not reproduce under gdb, not that it is wrong.

Next: get a freeze under gdb at all — either drive the mission to the end condition that produces it instead of waiting on a clock, or measure guest time under gdb so the wait can be set in the units the freeze actually follows.