diff --git a/docs/re/captures/stage02-freeze-gdb-backtraces.txt b/docs/re/captures/stage02-freeze-gdb-backtraces.txt new file mode 100644 index 0000000..cd019fe --- /dev/null +++ b/docs/re/captures/stage02-freeze-gdb-backtraces.txt @@ -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//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 >) () +#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, 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 >) () +#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, xe::kernel::shim::PointerParam c +#5 0x00000000a000013a in ??? () diff --git a/docs/re/mission-freeze-resume-spin.md b/docs/re/mission-freeze-resume-spin.md index 9bf49b1..f15530d 100644 --- a/docs/re/mission-freeze-resume-spin.md +++ b/docs/re/mission-freeze-resume-spin.md @@ -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 "$@"`) 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//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. diff --git a/tools/re-capture/gdb_bt.sh b/tools/re-capture/gdb_bt.sh new file mode 100755 index 0000000..57a2c10 --- /dev/null +++ b/tools/re-capture/gdb_bt.sh @@ -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"