tools+docs: the freeze from inside - all 79 threads are in a wait, and two of them burn CPU cycling

The gdb route works, and the recipe is written down: run-canary execs $XENIA_BIN,
so a wrapper that execs "gdb --args <real binary>" keeps the lockfile, the flags
and the process name (gdb forks and execs the real binary, so ps -C xenia_canary
still finds the inferior) while satisfying ptrace_scope=1 by being the parent.
The Release binary is not stripped - 26595 symtab entries - so frames have names.
The handle SIGSEGV/SIGBUS/SIG32-35 lines are mandatory: xenia uses SIGSEGV for
guest memory watches and the RT signals for thread suspend.

A run froze after ~4 minutes of flight, screen still "flight" rather than GAME
OVER, and all 79 threads had backtraces. EVERY ONE is in a wait - guest threads
in KeWaitForSingleObject / NtWaitForSingleObjectEx / SelfSuspend, the GPU command
processor parked idle, the main thread in poll().

It is nevertheless burning 1253 ticks per 10 s: 403 in the TimerQueue thread
(nanosleep inside TimerThreadMain) and 290 + 274 in two guest threads that the
backtrace shows blocked in KeWaitForSingleObject. A thread genuinely blocked
cannot burn 28% of a core, so those two are CYCLING - a timed wait that expires
and is re-entered - with the timer thread servicing them hot. Three samples
minutes apart show identical frames.

That refines the earlier "the guest is spinning, not deadlocked": the CPU burn is
real but it is in the WAIT PATH inside the kernel layer, not in guest code. The
shape is an event that never gets signalled.

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
2026-08-24 01:13:01 +00:00
parent b67f8d5c59
commit 63f74c9c84
3 changed files with 109 additions and 0 deletions

View File

@@ -0,0 +1,31 @@
# Backtraces of a FROZEN Stage 02 run, taken with the emulator started
# under gdb (ptrace_scope=1 forbids attaching to a running one).
# 79 threads had backtraces; EVERY ONE was in a wait.
#
# CPU over 10 s while frozen, from /proc/<tid>/stat: 1253 ticks total.
# 403 xenia_canary (the TimerQueue thread)
# 290 XThreadD61F96C0
# 274 XThreadD45FF6C0
# 59 XMA Decoder
Thread 2 (Thread 0x7ffff55326c0 (LWP 103706) "xenia_canary"):
#0 0x00007ffff6699bdf in clock_nanosleep () at /lib/x86_64-linux-gnu/libc.so.6
#1 0x00007ffff66a6b27 in nanosleep () at /lib/x86_64-linux-gnu/libc.so.6
#2 0x0000555555bc07bd in xe::threading::TimerQueue::TimerThreadMain() ()
#3 0x00007ffff69c4db4 in ??? () at /lib/x86_64-linux-gnu/libstdc++.so.6
#4 0x00007ffff6649b84 in ??? () at /lib/x86_64-linux-gnu/libc.so.6
#5 0x00007ffff66d6d6c in ??? () at /lib/x86_64-linux-gnu/libc.so.6
Thread 68 (Thread 0x7ffcd61f96c0 (LWP 103773) "XThreadD61F96C0"):
#0 0x00007ffff6645e51 in ??? () at /lib/x86_64-linux-gnu/libc.so.6
#1 0x00007ffff66488cd in pthread_cond_wait () at /lib/x86_64-linux-gnu/libc.so.6
#2 0x0000555555bbb45b in xe::threading::PosixConditionBase::Wait(std::chrono::duration<long, std::ratio<1l, 1000l> >) ()
#3 0x0000555555e4fd80 in xe::kernel::XObject::Wait(unsigned int, unsigned int, unsigned int, unsigned long*) ()
#4 0x0000555555e313f6 in xe::kernel::shim::ExportRegistrerHelper<(xe::kernel::shim::KernelModuleId)0, (unsigned short)176, xe::kernel::shim::ResultBase<unsigned int>, xe::kernel::shim::PointerParam c
#5 0x00000000a000013a in ??? ()
Thread 69 (Thread 0x7ffcd45ff6c0 (LWP 103774) "XThreadD45FF6C0"):
#0 0x00007ffff6645e51 in ??? () at /lib/x86_64-linux-gnu/libc.so.6
#1 0x00007ffff66488cd in pthread_cond_wait () at /lib/x86_64-linux-gnu/libc.so.6
#2 0x0000555555bbb45b in xe::threading::PosixConditionBase::Wait(std::chrono::duration<long, std::ratio<1l, 1000l> >) ()
#3 0x0000555555e4fd80 in xe::kernel::XObject::Wait(unsigned int, unsigned int, unsigned int, unsigned long*) ()
#4 0x0000555555e313f6 in xe::kernel::shim::ExportRegistrerHelper<(xe::kernel::shim::KernelModuleId)0, (unsigned short)176, xe::kernel::shim::ResultBase<unsigned int>, xe::kernel::shim::PointerParam c
#5 0x00000000a000013a in ??? ()

View File

@@ -246,3 +246,58 @@ frames, but it would immediately separate *"spinning inside guest JIT code"* fro
*"spinning in a xenia loop"* — which is the fork this investigation is stuck on.
Not attempted here; recorded so the next pass starts from the right end.
---
# ✅ 2026-08-24 — the freeze, seen from inside: every thread is in a WAIT
The gdb route works. `run-canary` execs `$XENIA_BIN`, so
[`/sylph-home/re/bin/gdb-wrap/xenia_canary`](../../tools/re-capture/gdb_bt.sh)
(a wrapper that `exec`s `gdb --args <real binary> "$@"`) keeps the lockfile, the
flags and the process name intact — gdb forks and execs the real binary, so
`ps -C xenia_canary` still finds the inferior — and being the *parent* satisfies
`ptrace_scope=1`. The Release binary is **not stripped** (26 595 symtab entries),
so frames carry names. `handle SIGSEGV/SIGBUS/SIG32-35 nostop noprint pass` is
mandatory: xenia uses SIGSEGV for guest memory watches and the real-time signals
for thread suspend, and without those lines gdb stops the world on the first one
and the boot never happens.
A Stage 02 run froze after ~4 minutes of flight (screen still `flight`, not GAME
OVER), and `gdb_bt.sh` took backtraces of all **79** threads
([`captures/stage02-freeze-gdb-backtraces.txt`](../captures/stage02-freeze-gdb-backtraces.txt)).
**Every single one is in a wait.** Not one thread is executing guest code or
sitting in a xenia loop:
* the guest threads are in `KeWaitForSingleObject` / `NtWaitForSingleObjectEx` /
`XThread::SelfSuspend`, i.e. `PosixConditionBase::Wait``pthread_cond_wait`;
* the GPU command processor is parked in its own `Wait`, idle;
* the main thread is in `poll()`.
## But it is still burning CPU — in the wait path
Over 10 s while frozen, `/proc/<tid>/stat` shows **1 253 ticks** spread over the
process:
| ticks / 10 s | thread | where it is |
|---|---|---|
| **403** | `xenia_canary` (the **TimerQueue** thread) | `nanosleep` inside `TimerQueue::TimerThreadMain` |
| **290** | `XThreadD61F96C0` | `KeWaitForSingleObject` |
| **274** | `XThreadD45FF6C0` | `KeWaitForSingleObject` |
| 59 | `XMA Decoder` | — |
A thread genuinely blocked in `pthread_cond_wait` cannot burn 28 % of a core. So
those two guest threads are **cycling**: a timed wait that keeps expiring and
being re-entered, with the TimerQueue thread servicing the timers hot. Three
samples minutes apart show them in exactly the same frames.
🔴 **This refines the earlier reading rather than confirming it.** "The guest is
spinning, not deadlocked" was right that CPU is burned and wrong about where: the
burn is in the **wait path inside the kernel layer**, not in guest code. The
shape is a guest event that never gets signalled, with its waiters looping
through short timed waits.
**Next, and now cheap:** read *which* object those two threads are waiting on —
the handle is an argument to `KeWaitForSingleObject`, one `info args`-equivalent
away now that a debugger can be attached at will — and find who was supposed to
signal it.

23
tools/re-capture/gdb_bt.sh Executable file
View File

@@ -0,0 +1,23 @@
#!/usr/bin/env bash
# Take a backtrace of every thread of an emulator that is running under gdb.
#
# Pair with the wrapper at /sylph-home/re/bin/gdb-wrap/xenia_canary (see
# docs/re/mission-freeze-resume-spin.md): ptrace_scope=1 forbids attaching to a
# running emulator, so it has to be STARTED under gdb.
#
# SIGINT to gdb stops the inferior; commands then go in through the command file
# the wrapper is tailing, and the answer comes back in the gdb log. `continue` at
# the end so the run can carry on.
set -u
CMD="${GDB_CMD_FILE:-/tmp/gdb-cmd}"
OUT="${GDB_OUT_FILE:-/tmp/gdb-out.log}"
DEPTH="${1:-12}"
pid=$(pgrep -x gdb | head -1)
[ -n "$pid" ] || { echo "no gdb process — was the emulator started with XENIA_BIN=/sylph-home/re/bin/gdb-wrap/xenia_canary ?"; exit 1; }
mark="=== BT $(date +%s) ==="
before=$(wc -c < "$OUT")
kill -INT "$pid"
sleep 3
{ echo "echo $mark\\n"; echo "info threads"; echo "thread apply all bt $DEPTH"; echo "echo === END ===\\n"; echo "continue"; } >> "$CMD"
sleep 8
tail -c +$((before + 1)) "$OUT"