d8e9874984
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
84 lines
3.7 KiB
Python
Executable File
84 lines
3.7 KiB
Python
Executable File
#!/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())
|