docs: the in-mission freeze ends in 1171 refused resumes of one thread
A Stage 02 run froze at TIME 01:02 with a radio line caught mid-word. The emulator was alive at ~200% CPU with its main thread in state R, two screenshots six seconds apart were byte-identical, and the log ended in a spin: 1171 of the run's 1200 "host resume was refused" lines are the single pair F80002AC -> F8000240, starting at the line immediately after F80002AC is created, and the log never grows again. The commit that added that warning records what normal looks like - about 7 in a whole boot - so this is a 150x anomaly on one pair rather than noise. F8000240 itself appears exactly once outside the spin, at creation, and calls nothing. Eleven of the frozen process's 79 host threads have zero CPU, four of them consecutive late-created guest threads - the same signature as the lost resume that c1b57f93b fixed for the title screen. That fix IS in this build, so either there is a second window in that race or this only looks alike. The inference is named as one: nothing here maps a guest handle to a host tid, so "the zero-CPU threads are the ones being resumed" is a reading of two consistent observations. And the refusals could equally be the game's reaction to a worker stuck for another reason - log_mask=13 has the Kernel channel disabled, so not one of F8000240's waits is visible. The next experiment is written down concretely: reproduce with LOG_MASK=12 LOG_LEVEL=3 and map the handle to a tid. Also caps ob_hunt's survivor listing at 40 - an aborted run printed all 21482 and buried the line that mattered. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01PMRJjbxLqZtsb5Vb7KunPE
This commit is contained in:
Sylpheed RE agent
25
docs/re/captures/stage02-freeze-resume-spin.log
Normal file
25
docs/re/captures/stage02-freeze-resume-spin.log
Normal file
@@ -0,0 +1,25 @@
|
||||
# tail of the Canary log of a FROZEN Stage 02 run (log_mask=13, level=2)
|
||||
# 1200 'host resume was refused' lines total, 1171 of them the single pair
|
||||
# F80002AC -> F8000240; the spin begins at line 5384, immediately after
|
||||
# XThreadF80002AC is created, and the log then never grows again.
|
||||
|
||||
F> F8000090 HostPathDevice::ResolvePath(\c7951e39\f\060a28b)
|
||||
F> F8000008 HostPathDevice::ResolvePath(\69d8e45c\a\8619aa7)
|
||||
i> F8000008 XThreadF8000270 (38) Stack: 70880000-708C0000
|
||||
i> F8000008 XThreadF8000298 (39) Stack: 70AD0000-70B10000
|
||||
i> F8000008 XThreadF80002AC (3A) Stack: 70B30000-70B70000
|
||||
i> F8000008 XThreadF80002C0 (3B) Stack: 70B90000-70C10000
|
||||
F> F80002C0 HostPathDevice::ResolvePath(\e5f89243\8\1f28c4d)
|
||||
F> F80002C0 HostPathDevice::ResolvePath(\e5f89243\2\bb9feee)
|
||||
F> F80002C0 HostPathDevice::ResolvePath(\e5f89243\b\2c0b0e1)
|
||||
w> F80002AC XThread::Resume: host resume was refused for thread F8000240
|
||||
w> F80002AC XThread::Resume: host resume was refused for thread F8000240
|
||||
w> F80002AC XThread::Resume: host resume was refused for thread F8000240
|
||||
w> F80002AC XThread::Resume: host resume was refused for thread F8000240
|
||||
w> F80002AC XThread::Resume: host resume was refused for thread F8000240
|
||||
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] ...
|
||||
w> F80002AC XThread::Resume: host resume was refused for thread F8000240
|
||||
w> F80002AC XThread::Resume: host resume was refused for thread F8000240
|
||||
w> F80002AC XThread::Resume: host resume was refused for thread F8000240
|
||||
81
docs/re/captures/stage02-freeze-thread-cpu.txt
Normal file
81
docs/re/captures/stage02-freeze-thread-cpu.txt
Normal file
@@ -0,0 +1,81 @@
|
||||
# host threads of the FROZEN emulator: ticks(utime+stime), state, tid, comm
|
||||
# 79 threads, 11 with zero CPU
|
||||
0 S 42923 xenia_canary
|
||||
0 S 42950 xenia_c:disk$0
|
||||
0 S 42955 Audio Media Pla
|
||||
0 S 42967 Kernel Dispatch
|
||||
0 S 42978 Shader Storage
|
||||
0 S 42979 XThreadB73FC6C0
|
||||
0 S 42980 XThreadB53F96C0
|
||||
0 S 45871 XThread37FFF6C0
|
||||
0 S 45872 XThread36FFE6C0
|
||||
0 S 45873 XThread35FFD6C0
|
||||
0 S 45874 XThread2FFFF6C0
|
||||
1 S 42922 xenia_canary
|
||||
1 S 42996 XThread76FFE6C0
|
||||
5 S 42957 WSI swapchain e
|
||||
6 S 42981 XThreadA3FFF6C0
|
||||
10 S 42924 Emulator
|
||||
14 S 42965 Vulkan Pipeline
|
||||
15 S 42958 Vulkan Pipeline
|
||||
15 S 42960 Vulkan Pipeline
|
||||
16 S 42959 Vulkan Pipeline
|
||||
16 S 42962 Vulkan Pipeline
|
||||
16 S 42966 Vulkan Pipeline
|
||||
17 S 42961 Vulkan Pipeline
|
||||
17 S 42963 Vulkan Pipeline
|
||||
17 S 42964 Vulkan Pipeline
|
||||
45 S 45808 XThread41FFD6C0
|
||||
56 S 42905 xenia_canary
|
||||
60 S 42984 XThread9FFFA6C0
|
||||
61 S 45807 XThread42FFE6C0
|
||||
98 S 42952 GPU Frame limit
|
||||
105 S 45875 XThread2EFFE6C0
|
||||
158 S 42953 XMA Decoder (01
|
||||
159 S 42989 SDLAudioP2
|
||||
160 S 42954 Audio Worker (0
|
||||
274 S 45878 XThread1FFFF6C0
|
||||
288 S 42990 XThread953FC6C0
|
||||
513 S 45877 XThread2DFFD6C0
|
||||
537 S 45876 XThread3DFF96C0
|
||||
547 S 42956 WSI swapchain q
|
||||
853 S 42997 XThread75FFD6C0
|
||||
981 S 42994 XThread77FFF6C0
|
||||
994 S 42999 XThread66FFE6C0
|
||||
996 R 42998 XThread67FFF6C0
|
||||
997 S 42993 XThread85FFD6C0
|
||||
1027 S 42995 XThread87FFF6C0
|
||||
1314 S 42951 GPU Commands (0
|
||||
1913 S 42968 Main XThread (F
|
||||
2022 S 42921 Logging Writer
|
||||
2156 S 42925 Emulator
|
||||
3031 S 42987 XThread96BFE6C0
|
||||
3070 S 42982 XThreadA2FFE6C0
|
||||
3101 S 42983 XThreadA0FFB6C0
|
||||
3447 S 42986 XThread97BFF6C0
|
||||
3459 S 42939 Emulator
|
||||
3462 S 42943 Emulator
|
||||
3463 S 42942 Emulator
|
||||
3467 S 42944 Emulator
|
||||
3468 S 42938 Emulator
|
||||
3468 S 42948 Emulator
|
||||
3471 S 42940 Emulator
|
||||
3472 S 42946 Emulator
|
||||
3476 S 42941 Emulator
|
||||
3477 S 42945 Emulator
|
||||
3484 S 42947 Emulator
|
||||
3486 S 42949 Emulator
|
||||
6387 S 42936 llvmpipe-10
|
||||
6626 S 42937 llvmpipe-11
|
||||
6746 S 42935 llvmpipe-9
|
||||
7176 S 42934 llvmpipe-8
|
||||
7477 S 42933 llvmpipe-7
|
||||
7631 S 42932 llvmpipe-6
|
||||
7844 S 42926 llvmpipe-0
|
||||
7871 S 42931 llvmpipe-5
|
||||
7899 S 42928 llvmpipe-2
|
||||
7907 S 42930 llvmpipe-4
|
||||
7929 S 42929 llvmpipe-3
|
||||
8128 S 42927 llvmpipe-1
|
||||
28354 S 42919 xenia_canary
|
||||
28701 S 42985 XThread9C9F96C0
|
||||
92
docs/re/mission-freeze-resume-spin.md
Normal file
92
docs/re/mission-freeze-resume-spin.md
Normal file
@@ -0,0 +1,92 @@
|
||||
# The in-mission freeze looks like a *second* lost resume
|
||||
|
||||
**Status: 🟡 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.
|
||||
@@ -41,7 +41,12 @@ import gmem # noqa: E402
|
||||
import gworld # noqa: E402
|
||||
import ob_read # noqa: E402
|
||||
|
||||
VA = 0xBDB59668
|
||||
# The counter is NOT at a fixed address across runs — see
|
||||
# structures/mission-objective-counter.md. 0xbdb59668 is the value it takes in
|
||||
# 3 of the 5 runs measured; when it is wrong this script refuses to run rather
|
||||
# than reporting nonsense, and ob_hunt.py finds the run's own address in ~1 min
|
||||
# of flight. Override with OB_VA.
|
||||
VA = int(os.environ.get("OB_VA", "0xBDB59668"), 0)
|
||||
RADIUS = 0x400
|
||||
DELTA = 0x130
|
||||
|
||||
@@ -103,6 +108,15 @@ def main():
|
||||
|
||||
candA = {k: v for k, v in gA.items() if len(v) == nA}
|
||||
print(f"[A] offsets where exactly {nA} entities agree: {len(candA)}", flush=True)
|
||||
# WHO a candidate groups is a discriminator available without waiting for a
|
||||
# transition: an OB flag should mark a subset of the hostiles, not a mix that
|
||||
# includes the player and its wingmen. Printed for every candidate rather
|
||||
# than filtered on, because "objectives are always hostile" is an assumption
|
||||
# about the mission, not a measurement -- an escort objective would be
|
||||
# friendly, and Stage 02 has one (the ACROPOLIS).
|
||||
for (d, val), mem in sorted(candA.items()):
|
||||
who = Counter(nm.replace("UN_", "") for nm in mem)
|
||||
print(f" pos{d:+#07x} = {val.hex()} {dict(who)}", flush=True)
|
||||
|
||||
stuck = 0
|
||||
while time.time() < deadline:
|
||||
|
||||
@@ -101,8 +101,13 @@ def main():
|
||||
payload = {"scan_value": v0, "transitions": results,
|
||||
"survivors": [{"off": o, "va": gmem.primary_va(o)} for o in sorted(cands)]}
|
||||
json.dump(payload, open(f"{out}/hunt.json", "w"), indent=1)
|
||||
for o in sorted(cands):
|
||||
# Cap the listing. On a clean run this is a handful of addresses; on an
|
||||
# aborted one (frozen guest, no transition) it is the whole scan, and 21 482
|
||||
# lines of noise buried the one line that mattered.
|
||||
for o in sorted(cands)[:40]:
|
||||
log(f" va {gmem.primary_va(o):#x}")
|
||||
if len(cands) > 40:
|
||||
log(f" ... and {len(cands) - 40} more (see hunt.json)")
|
||||
log(f"wrote {out}/hunt.json")
|
||||
return 0
|
||||
|
||||
|
||||
Reference in New Issue
Block a user