Sylpheed/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](upstream-baseline.md) — 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`](captures/stage02-freeze-at-time-0102.png)).

* Two screenshots six seconds apart: **byte-identical**, max delta 0
  ([`frozen.py`](../../tools/re-capture/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`](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`](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](canary-scripted-input-traps.md) 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`](captures/stage02-freeze-at-time-0337.png)),
and the log then tells a much more specific story
([`captures/stage02-freeze-kernel-tail.log`](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`](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 `sylpheed.db` (`tools/zq.py fn <pc>`) 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`](../../tools/re-capture/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 `exec`s
`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`](../../tools/re-capture/gdb_bt.sh)
(a wrapper that `exec`s `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`](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`](../../tools/re-capture/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`](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`:

```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 -9`s 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.

## ✅ 2026-08-25 — THE FROZEN CAPTURE, and `screen_id` was the wrong test all along

### First, a correction to the entry above

The previous entry ruled out a freeze because `screen_id` read `flight`. **That
is not a freeze test**, and `frozen.py`'s own docstring says why: a Stage 02 run
froze with `screen_id` still saying `flight`, the emulator still burning 212 %
CPU, and 724 s of identical state. The right test is two **byte-identical**
frames while the flight HUD is up.

Re-running that test on the saved frames says the conclusion was right anyway —
`fz-late1/2/3` and `fz-healthy/frozen` all come back `animating`,
`max_pixel_delta=254`. So the previous run really was healthy throughout. But it
was right by luck, and the "~270 s black-screen" it was planned around is not a
thing: the freeze does not black the screen and does not keep a clock. Measured
onsets in `BACKLOG.md` are **27/45/83/183/255 s**.

### The capture

`freeze_waitobj.sh` now splits into `boot` and `watch`, and `watch` waits for the
**event** (`frozen.py` + `in_flight`) instead of sleeping a guessed interval.
That got the capture on the first attempt. It is a hard stop, not a hitch: the
frame taken minutes after the capture is still `max_pixel_delta=0` against it.

Both captures, same run, same mission (`data/waitobj-s02.txt`):

| waited on | healthy | frozen |
|---|---|---|
| `XEvent` | 19 | **23** |
| `XSemaphore` | 8 | **7** |
| `XTimer` | 1 | 1 |
| wait frames | 20 | **24** |

**The signature is in which threads moved, not in the totals:**

| thread | healthy | frozen |
|---|---|---|
| T105, T67, T68 | *not waiting* | `Wait(XEvent)` |
| T69 | *not waiting* | `Wait(XSemaphore)` |
| T74, T75 | `Wait(XSemaphore)` | `Wait(XEvent)` |
| T50 | `WaitMultiple(XEvent,XEvent)` | `Wait(XEvent)` |

Every other thread — 17 of them — is on exactly the object it was on before. So
the freeze is **not** the whole emulator stalling: the established waiters are
untouched, and what changes is that **four threads that were running are now
parked**, and **two threads move off a semaphore onto an event**. T74/T75 are the
pair to chase — they are the only ones that changed *what kind* of thing they
wait for.

⚠️ "Not waiting" means not in a wait frame **at that instant**; those threads
existed and were running, they were not created by the freeze.

## 🟡 One data point that our own instrument provokes it — not proof

Worth stating because it changes what the freeze *is*. This run flew **~670 s
clean** with only the pilot attached. A heavy-CPU inducer (`heavy_read.py cpu`,
full-region Python word scan of guest memory) was then started at 08:59:54, and
the freeze landed at **09:00:48 — 54 s later**, inside the 27–255 s band the old
heavy-probe runs froze in.

That is consistent with the tally already in `BACKLOG.md` (heavy probe froze at
27/45/83/183/255 s; cheap probe with the rescan removed was clean past 200 s on 3
of 4 runs), and it is still **n=1 and not causal**. The obvious confounder is
simply elapsed mission time.

**Refuted along the way:** the I/O was never the cost. A full uncapped walk of
every allocated extent moves **371 MB in 0.1 s** — all page cache — so "32 MB
reads" was the wrong description of what the old probes spent. The cost is CPU:
unpacking and comparing every word in Python takes **~4.2 s per pass**.

**The experiment that would settle it:** alternate inducer-on and inducer-off
windows within one run, several runs, and compare freeze rate per unit of
*mission* time. Cheap now that `watch` is event-driven.

## ✅ 2026-08-25 — second freeze, and it REFUTES the signature I named

Ran the control's opposite: inducer **on from the moment flight begins**
(`freeze_waitobj.sh run` with `SYLPH_INDUCE=1`, launched detached so no `timeout`
can kill the process group).

| run | inducer | outcome |
|---|---|---|
| 1 | off for 670 s, then on | clean 670 s, then **frozen 54 s** after it started |
| 2 | **on from flight start** (10:07:20) | **frozen ~96 s later** (10:08:56) |

Both freezes land inside the 27–255 s band the old heavy-probe runs froze in,
and the one long clean stretch is the only window with no inducer. **n=2, and the
contrast is now sharp** — but it is still two runs, the confounder (elapsed
mission time) is untouched, and the alternating-window test is what would settle
it.

### 🔴 WITHDRAWN: "T74/T75 move off a semaphore onto an event"

Last iteration I called that "the pair to chase — the only threads that change
what *kind* of object they wait for". **It does not reproduce.** In run 2, T74
and T75 sit on `Wait(XEvent)` in the *healthy* capture and stay there when
frozen.

The reason is a sampling error I should have caught: the **healthy** state is not
fixed either. Run 1 happened to catch T74/T75 on a semaphore; run 2 caught them
on an event. A one-sample-per-state comparison cannot tell a freeze transition
from ordinary variation between two instants, and I read a difference of samples
as a difference of states.

### ✅ What DOES reproduce across both freezes

**T68 and T69 go from not-waiting to waiting, in both runs** — and T69 lands on
an `XSemaphore` both times, T68 on an `XEvent` both times. Everything else is
run-specific: run 1 also parked T105/T67, run 2 instead dropped T36 out of its
wait.

And in both runs the great majority of threads are untouched — 17 of 24 in run 1,
**21 of 24** in run 2 — which keeps the one structural claim that has now
survived two independent captures: **the freeze is not a whole-emulator stall.**

Data: `data/waitobj-s02.txt` (run 1), `data/waitobj-s02-inducer.txt` (run 2).

**Still open:** whether T68/T69 are cause or consequence; one sample per state
cannot say. The fix for the error above applies here too — **repeat the capture
several times within a single healthy run** to learn which thread states are
stable before reading any frozen diff as meaningful.

## 🔴 2026-08-25 — the control run kills the signature: NOTHING survives

Six wait-object captures across a **single healthy run**, 40 s apart, to learn
which thread states are stable before reading any frozen diff as meaningful
(`data/waitobj-healthy-stability.txt`). The answer is that most are not:

```
12 stable, 13 vary across healthy play
```

**Every thread I had reported as a freeze signature is in the VARIES set.**

| thread | across six *healthy* captures |
|---|---|
| T74, T75 | `Wait(XSemaphore)` → `--` → `Wait(XEvent)` ×4 |
| T68 | `--`, `--`, `--`, `Wait(XEvent)`, `--`, `Wait(XEvent)` |
| T69 | `--`, `--`, `--`, `Wait(XSemaphore)`, `--`, `Wait(XSemaphore)` |
| T50, T67, T36 | drift in and out of a wait |

So the T74/T75 withdrawal was right — and **T68/T69, which I kept as "what
reproduces across both freezes", is withdrawn too.** Those two threads park and
unpark repeatedly during ordinary play, including landing on exactly the objects
they held when frozen. Seeing them parked in a frozen capture is not evidence of
anything.

**Net: no thread-level freeze signature has survived.** Both frozen diffs are
consistent with healthy variation, and the method as run — one sample per state —
was never capable of telling them apart. Two iterations of "the thing to chase"
were noise.

### ✅ What is still standing

* The **12 stable threads** — T133, T80, T79, T77, T76, T71, T66, T65, T64, T63,
  T62, T61 — hold the same object in all six captures. **Only these can carry a
  signature.** In both frozen captures, none of them moved, which is what
  "17 of 24 / 21 of 24 unchanged" was really measuring.
* So **"the freeze is not a whole-emulator stall" survives** — but it now rests
  on the stable set being undisturbed, not on the count of unchanged threads.

### ⚠️ And gdb thread numbers are not comparable across runs

This run's threads include T132–T142, which no earlier run had, while earlier
runs had T104–T106 that this one does not. Thread *numbering* is per-process, so
a "T74" in two runs need not be the same guest thread. Every comparison so far
was within one run, which is sound — but any future cross-run comparison must key
on something else (the object address, or the guest thread id), not the gdb
number.

### What would actually work

Compare **distributions**, not samples: N healthy captures vs N frozen ones, and
call a thread a signature only if its frozen distribution lies outside its
healthy range. The harness now does the healthy half; the frozen half needs a run
that freezes while being sampled repeatedly.

## 🔴 2026-08-25 (run 3) — a counter-example to my own inducer hypothesis

Third run, inducer **on from flight start**, watched for **900 s**:
**it did not freeze.** So the tally is now **2 for, 1 against**:

| run | inducer | outcome |
|---|---|---|
| 1 | off 670 s, then on | clean 670 s, frozen **54 s** after it started |
| 2 | on from flight start | frozen **~96 s** |
| 3 | on from flight start | **no freeze in 900 s** |

**A confound, stated rather than used as an excuse:** the inducer was far weaker
this run. Each CPU pass took **~47–50 s** against **~4.2 s** in run 2, because
two analysis subagents were saturating the box, so it completed **22** passes in
15 minutes instead of the ~150 run 2's rate implies. That is consistent with
"less contention reached the emulator, so no freeze" — but it is equally
consistent with "the inducer never mattered and runs 1 and 2 were luck". One run
cannot separate those, and I am not going to score it as a confirmation.

What it does establish: **the inducer is not sufficient**, so any future run must
report the inducer's *measured* rate, not merely that it was enabled.

## 🔴 The STABLE set is itself run-dependent

The second healthy sample (6 more captures, `data/waitobj-healthy-stability-run2.txt`)
gives **9 stable / 14 vary**, against **12 / 13** in the first. Intersecting the
two stable sets leaves **8 threads** — T77, T76, T66, T65, T64, T63, T62, T61.
T80, T79 and T71 were stable in run A and vary in run B; T36 is the reverse.

So the "only a stable thread can carry a signature" rule is right, but the stable
set **must be measured within the run it is used in** — it does not transfer.
That is the same lesson as the gdb thread numbering, one level up: nothing about
thread identity or behaviour carries across runs for free.

**Net for the distribution experiment:** the healthy half now has two independent
samples; the frozen half is **still uncollected**, because run 3 never froze.

## 🟡 2026-08-25 — my own probe is now the strongest freeze correlate

The `phase_watch.py` runs give a much sharper tally than the earlier
inducer experiment did, because the difference between the two groups is a
single tool:

| probe attached | runs | outcome |
|---|---|---|
| pilot only | 2 | **clean to 936 s and 1064 s** |
| pilot + `phase_watch.py` | **3** | **froze at ~70 s, ~253 s, ~126 s** |

Five runs, same boot path, same pilot, same mission. Every run carrying the
script probe froze inside ~4 minutes; neither run without it froze in ~16.

**What `phase_watch` does that the pilot does not:** `find_mission()` performs
**two full sweeps of guest memory** at startup — one for the `.ssb` header, one
for every word equal to the code base — and then ~130 small reads every 5 s. The
full sweeps are the obvious suspect, and they are the same *shape* as the
`heavy_read.py` scans that the earlier n=2 experiment implicated.

⚠️ **Still correlation.** Three-versus-two is suggestive, not causal, and the
earlier inducer test already produced one clean counter-example when the box was
loaded. But it is now the best-supported version of "the instrument provokes the
freeze", and it is *my* instrument, which makes it actionable rather than
academic.

**The cheap test:** `find_mission` only needs to run once, and its result could
be passed in on later samples — so run the same watch with the sweeps replaced by
a hard-coded address from a prior run. If the freezes stop, the sweeps are the
cause; if they continue, the per-sample reads are.

**Cost so far:** three attempts to observe a phase advance, all truncated inside
four minutes by a freeze the probe itself may be causing. The arrival transition
at ~143 s was caught only because it happens early.

## 🟡 2026-08-25 — a counter-example weakens the probe correlation

The previous entry made the probe the leading suspect on a clean 3-versus-2
split. **A pilot-only run has now frozen too**, and it came from an accident: the
sweep-free experiment aborted at startup (below), so the run flew with *no*
script probe attached at all. Its pilot state went identical at **t ≈ 150.7 s**
and `frozen.py` confirms `max_pixel_delta=0`.

| probe attached | clean | frozen |
|---|---|---|
| pilot only | 936 s, 1064 s | **150 s** |
| pilot + `phase_watch.py` | — | 70 s, 126 s, 253 s |

So it is **3-of-3 with the probe versus 1-of-3 without**, not 3-versus-0. That is
still a lean, but it is no longer the clean separation the last entry described,
and I am marking it down rather than keeping the stronger reading. This is the
fourth time in this investigation a freeze conclusion has had to be softened by
one more run.

**What would actually settle it** is unchanged and now clearly worth the cost:
alternate probe-on and probe-off windows *within* a single run, several runs, and
compare freeze rate per unit of mission time. Between-run comparisons at n≈3
keep producing splits that the next run erodes.

## 🔴 The sweep-free test could not run: the ScriptMission moves

The plan was to skip `find_mission()`'s two memory sweeps by passing an address
from an earlier run. It does not survive: `0xBC7A2A20` read back **all zeros**
this run, and the cheap self-consistency check (`[m+44]` must equal the phase's
`[+244]`) **rejected it** rather than reporting garbage — which is the one thing
that went right here.

So the object is re-allocated per run and a hard-coded address is not viable.
The sweeps still need replacing to run the experiment; the cheaper version is a
**bounded** pointer scan — every ScriptMission seen so far sat in
`0xBC79xxxx–0xBC7Axxxx`, so scanning ~32 MB instead of the full ~371 MB would cut
the cost roughly tenfold while still finding it. Not yet implemented.

## 🔴 2026-08-25 — the freeze is now the dominant cost, and it blocked the control run

This iteration set out to run the **positive control** the poke experiments
need — poke the player's hull (`position + 0x154`, which the pilot logs every
sample) and confirm the guest sees it. **It did not run.** The bind needed two
attempts (the first returned `fwd_cos = -0.94`, a bad orientation; the second
`1.0`), and by the time the player's entity was being located the guest had
frozen: `entities2 self` reported **"0 moving triples"** and `frozen.py`
confirmed `max_pixel_delta = 0`.

### The session's freeze tally

| outcome | observed |
|---|---|
| froze | ~70 s, ~126 s, ~150 s, ~253 s, ~610–682 s, and this run |
| ran clean | 694 s (ended by the game), 936 s, 1064 s |

Roughly **two runs in three freeze**, and each costs a ~5-minute boot plus the
observation window. Across this session the freeze has truncated more
experiments than every other cause combined: three phase-advance attempts, one
distribution capture, and now the control.

### 🟡 It is probably not ours

Worth restating against the temptation to keep hunting our own tooling: the
mission-end freeze is recorded as **pre-existing in both our Canary build and the
official AppImage** ([canary-build-verified-env-confound](canary-build-verified-env-confound.md)),
and this session produced a **pilot-only** freeze at 150 s with no probe attached
at all. The probe-correlation lead (3-of-3 with, 1-of-3 without) is real but has
not survived as a clean split, and the bounded scan improved it without removing
it.

**Consequence for planning:** any experiment needing more than ~2 minutes of
live mission should be built to **checkpoint and resume**, or to detect the
freeze and re-run itself, rather than assuming a run completes. Every tool in
this line now witnesses the freeze; none of them yet *survives* it.