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:
31
docs/re/captures/stage02-freeze-gdb-backtraces.txt
Normal file
31
docs/re/captures/stage02-freeze-gdb-backtraces.txt
Normal 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 ??? ()
|
||||
@@ -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
23
tools/re-capture/gdb_bt.sh
Executable 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"
|
||||
Reference in New Issue
Block a user