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
This commit is contained in:
BIN
docs/re/captures/stage02-freeze-at-time-0337.png
Normal file
BIN
docs/re/captures/stage02-freeze-at-time-0337.png
Normal file
Binary file not shown.
|
After Width: | Height: | Size: 1.0 MiB |
18
docs/re/captures/stage02-freeze-cpu-while-frozen.txt
Normal file
18
docs/re/captures/stage02-freeze-cpu-while-frozen.txt
Normal file
@@ -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)
|
||||
25
docs/re/captures/stage02-freeze-kernel-tail.log
Normal file
25
docs/re/captures/stage02-freeze-kernel-tail.log
Normal file
@@ -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
|
||||
@@ -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.
|
||||
|
||||
83
tools/re-capture/freeze_report.py
Executable file
83
tools/re-capture/freeze_report.py
Executable file
@@ -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 <canary.stdout> [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())
|
||||
Reference in New Issue
Block a user