diff --git a/docs/re/captures/stage02-freeze-resume-spin.log b/docs/re/captures/stage02-freeze-resume-spin.log new file mode 100644 index 00000000..5d8d2440 --- /dev/null +++ b/docs/re/captures/stage02-freeze-resume-spin.log @@ -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 diff --git a/docs/re/captures/stage02-freeze-thread-cpu.txt b/docs/re/captures/stage02-freeze-thread-cpu.txt new file mode 100644 index 00000000..e625e378 --- /dev/null +++ b/docs/re/captures/stage02-freeze-thread-cpu.txt @@ -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 diff --git a/docs/re/mission-freeze-resume-spin.md b/docs/re/mission-freeze-resume-spin.md new file mode 100644 index 00000000..fe8ef0e5 --- /dev/null +++ b/docs/re/mission-freeze-resume-spin.md @@ -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. diff --git a/tools/re-capture/ob_flag.py b/tools/re-capture/ob_flag.py index 125229c8..7ca6c874 100755 --- a/tools/re-capture/ob_flag.py +++ b/tools/re-capture/ob_flag.py @@ -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: diff --git a/tools/re-capture/ob_hunt.py b/tools/re-capture/ob_hunt.py index e6168a4d..d5bde9d6 100755 --- a/tools/re-capture/ob_hunt.py +++ b/tools/re-capture/ob_hunt.py @@ -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