diff --git a/docs/re/captures/stage02-freeze-at-time-0337.png b/docs/re/captures/stage02-freeze-at-time-0337.png new file mode 100644 index 00000000..95877640 Binary files /dev/null and b/docs/re/captures/stage02-freeze-at-time-0337.png differ diff --git a/docs/re/captures/stage02-freeze-cpu-while-frozen.txt b/docs/re/captures/stage02-freeze-cpu-while-frozen.txt new file mode 100644 index 00000000..0b45ed8c --- /dev/null +++ b/docs/re/captures/stage02-freeze-cpu-while-frozen.txt @@ -0,0 +1,18 @@ +# CPU gained per host thread over 10 s while the game is FROZEN +# ticks state tid comm + 409 R 47682 xenia_canary + 57 S 47745 XThread7EFFE6C0 + 56 S 47746 XThread7D7FC6C0 + 37 S 47684 Logging Writer + 20 S 47758 XThread63FFF6C0 + 14 S 47762 XThread42FFE6C0 + 14 S 47761 XThread43FFF6C0 + 14 S 47760 XThread51FFD6C0 + 10 S 47714 GPU Commands (0 + 3 S 47752 SDLAudioP2 + 1 S 47747 XThread7C7FB6C0 + 1 S 47715 GPU Frame limit + 0 S 50534 XThreadFFFFF6C0 + 0 S 50533 XThread11FFD6C0 + 0 S 50532 XThread1FFFF6C0 +# total ticks gained: 636 (100 ticks = 1 s of CPU) diff --git a/docs/re/captures/stage02-freeze-kernel-tail.log b/docs/re/captures/stage02-freeze-kernel-tail.log new file mode 100644 index 00000000..e3808b83 --- /dev/null +++ b/docs/re/captures/stage02-freeze-kernel-tail.log @@ -0,0 +1,25 @@ +# Stage 02, frozen at TIME 03:37.83, Canary log with the Kernel channel ON +# (LOG_MASK=12 LOG_LEVEL=3). 50 MB / 690k+ lines; this is the tail. +# +# counts for the self-suspending worker F8000204: +# 'self-suspending' 3116 +# 'resumed' 3115 +# NtResumeThread refusals from F800026C 3115 +# so exactly ONE self-suspend is unmatched - the last one - and no +# further NtResumeThread is ever issued for it. + +d> F8000204 Thread F8000204 resumed +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 +d> F8000204 NtSuspendThread(F8000204, 70AAFE50(00000000), ContextArg) +d> F8000204 Thread F8000204 self-suspending +--- final lines of the file --- +d> F80000A0 ObReferenceObjectByHandle(FFFFFFFE, 30000000, 7071FDC0(00000000)) +d> F80000A0 KeSetBasePriorityThread(30071010, 00000001) +d> F80000A0 ObDereferenceObject(30071010, ContextArg) +d> F8000204 Thread F8000204 resumed +d> F8000204 NtSuspendThread(F8000204, 70AAFE50(00000000), ContextArg) +d> F8000204 Thread F8000204 self-suspending diff --git a/docs/re/mission-freeze-resume-spin.md b/docs/re/mission-freeze-resume-spin.md index fe8ef0e5..7e34a644 100644 --- a/docs/re/mission-freeze-resume-spin.md +++ b/docs/re/mission-freeze-resume-spin.md @@ -1,6 +1,11 @@ -# The in-mission freeze looks like a *second* lost resume +# The in-mission freeze — the resume-spin lead is DEAD, and the freeze is a guest-side spin -**Status: 🟡 a strong lead with one inference in it, not a diagnosis.** +**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`). @@ -90,3 +95,83 @@ combination the earlier work found necessary — and then: 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 `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. diff --git a/tools/re-capture/freeze_report.py b/tools/re-capture/freeze_report.py new file mode 100755 index 00000000..f6af9305 --- /dev/null +++ b/tools/re-capture/freeze_report.py @@ -0,0 +1,83 @@ +#!/usr/bin/env python3 +"""Summarise a Canary log around the in-mission freeze. + +[`mission-freeze-resume-spin.md`](../../docs/re/mission-freeze-resume-spin.md) +found a frozen Stage 02 run whose log ends in 1 171 refused resumes of one guest +thread by one guest thread. This turns that reading into a repeatable one, and +answers the question that separates the two candidate mechanisms: + +* the target thread **never ran** — a lost resume, the same class of bug as + `c1b57f93b`, and the refusals are the *cause*; +* the target thread **ran and then blocked** — the refusals are the game's + reaction to a worker stuck on something else, and the resume path is innocent. + +`XThread::Execute thid N (handle=…)` is logged on the **Kernel** channel when a +thread actually begins executing, so the discriminator is simply whether that +line exists for the target handle. It needs `LOG_MASK=12 LOG_LEVEL=3`: the +scripts' old `log_mask=13` has Kernel DISABLED, which is why no earlier log ever +held a kernel call. + +Usage: freeze_report.py [top_n] +""" +import collections +import re +import sys + +REFUSED = re.compile( + r"^\S+ (\S+) XThread::Resume: host resume was refused for thread (\S+)") +EXECUTE = re.compile(r"XThread::Execute thid (\d+) \(handle=([0-9A-F]{8})") +CREATE = re.compile(r"XThread([0-9A-F]{8}) \(([0-9A-F]+)\) Stack: (\S+)") + + +def main(): + path = sys.argv[1] + lines = open(path, errors="replace").read().splitlines() + pairs = collections.Counter() + first_line = {} + for i, l in enumerate(lines): + m = REFUSED.match(l) + if m: + pairs[m.groups()] += 1 + first_line.setdefault(m.groups(), i + 1) + + print(f"# {len(lines)} log lines, {sum(pairs.values())} refused resumes, " + f"{len(pairs)} distinct (caller -> target) pairs") + for (caller, target), n in pairs.most_common(int(sys.argv[2]) if len(sys.argv) > 2 else 5): + print(f" {caller} -> {target}: {n} (first at line {first_line[(caller, target)]})") + if not pairs: + print(" none — this run did not spin") + return 0 + + (caller, target), n = pairs.most_common(1)[0] + executed = {m.group(2) for l in lines for m in [EXECUTE.search(l)] if m} + # Without the Kernel channel there are NO XThread::Execute lines at all, and + # every thread then looks like it never ran — a false answer to exactly the + # question this tool exists to settle. Refuse instead. + if not executed: + print("\n# NO XThread::Execute lines in this log at all.") + print("# The Kernel channel was disabled, so 'did it ever run' is " + "UNANSWERABLE here — re-run with LOG_MASK=12 LOG_LEVEL=3.") + return 2 + created = {m.group(1): m.group(0) for l in lines for m in [CREATE.search(l)] if m} + print(f"\n# the dominant target, {target}:") + print(f" created: {created.get(target, 'NO CREATION LINE')}") + print(f" executed: {'YES' if target in executed else 'NO — it never began executing'}") + print(f" caller {caller} executed: " + f"{'YES' if caller in executed else 'NO'}") + print(f"# threads created: {len(created)} threads that executed: {len(executed)}") + never = [h for h in created if h not in executed] + print(f"# created but NEVER executed ({len(never)}): {' '.join(sorted(never)[:20])}") + + own = [l for l in lines if l.split(" ")[1:2] == [target] + and "host resume was refused" not in l] + print(f"\n# last lines whose CALLER is {target} ({len(own)} total):") + for l in own[-12:]: + print(" " + l[:160]) + print(f"\n# last non-refusal lines in the file:") + for l in [x for x in lines if "host resume was refused" not in x][-12:]: + print(" " + l[:160]) + return 0 + + +if __name__ == "__main__": + raise SystemExit(main())