Files
Sylpheed/docs/re/mission-freeze-resume-spin.md
Sylpheed RE agent 370cb2d535 docs: the resume-spin lead is refuted by its own control, and the freeze is a guest-side spin
The control this file never had: a run with the Kernel channel on, analysed WHILE
STILL FLYING, has 2738 refused resumes on one pair - more than the frozen run's
1171. The target's own lines show why. The game runs a self-suspending worker
(NtSuspendThread on itself, a manager thread resumes it, thousands of times), and
a self-suspended thread is not host-suspended, so the host Resume legitimately
returns false EVERY cycle: 3115 refusals against 3115 resumes.

The error is named rather than buried: the warning's commit says "~7 times in a
normal boot" and this file generalised that from boot to gameplay, where the
number is thousands. The 150x anomaly was an artefact of the baseline. The
zero-CPU threads go with it - the healthy run has four of those too.

What the instrumented reproduction DOES establish is sharper than the lead was.
The last kernel event in 690000 lines is "Thread F8000204 self-suspending", with
self-suspends 3116 against resumes 3115 - but the resumer never issues another
NtResumeThread at all, so nothing was dropped in flight; every thread stopped
together. And the guest is SPINNING, not deadlocked: over 10 s while frozen the
main thread is in state R gaining 409 ticks and guest threads gain ~680 in total
while making not one kernel call. So it is guest code waiting on something in
guest memory, and the next question is which guest PC.

Two corrections fall out: "the log stopped growing" is not a freeze detector (it
goes quiet for 25 s in normal flight), and 0xbdb59668 held the counter again -
4 of 6 runs now.

freeze_report.py makes the analysis repeatable, and refuses to answer "did this
thread ever run" when the Kernel channel was off rather than reporting a false NO.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01PMRJjbxLqZtsb5Vb7KunPE
2026-08-23 20:03:38 +00:00

8.6 KiB
Raw Blame History

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, 24 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 4587145874 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 onLOG_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 1557 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.