From 8b290d701238a1f4c9c55dadd5a18ade3c1191cf Mon Sep 17 00:00:00 2001 From: Sylpheed RE agent Date: Wed, 19 Aug 2026 10:19:06 +0000 Subject: [PATCH] tools+docs: the title's loader thread is created and never runs Two findings, the second only visible because of the first. 1. The harness has always had kernel logging switched off. log_mask DISABLES categories (Kernel=1, Apu=2, Cpu=4, Gpu=8), so the long-standing --log_mask=13 meant Kernel+Cpu+Gpu off; kernel calls also log at Debug while log_level defaults to Info. Seeing one needs BOTH LOG_MASK=12 and LOG_LEVEL=3, and no boot log this project has taken ever contained a kernel call. boot_menu.sh now takes LOG_MASK / LOG_LEVEL / EXTRA_FLAGS. A whole boot at Debug with Kernel on is 23 MB, so the default was costing far more than it saved. 2. With that on, a captured failure shows the (A) handler doing everything right: XamUserGetXUID(0, 7, ...) NtCreateEvent(...) ExCreateThread(..., entry=821748F0, ..., 00000001) ExCreateThread Active: Thread Initially Suspended, XThreadF80000CC (1F) Stack: 70880000-70900000 NtResumeThread(F80000CC, ...) and the thread then never executing. Measured two independent ways: it makes ZERO kernel calls - it appears 13 times in the log and every one is as an ARGUMENT, never as the calling thread, while five other threads make 31905 calls after the resume - and its host thread has 00:00:00 CPU time while the process sits at 546% and has burned 37 minutes of CPU in 6:46 wall. A spinning thread burns CPU. This one has not run at all. So the chain is: press delivered -> handler runs -> thread created suspended -> resumed -> never scheduled. Input, the cache-flush crash and the game's own logic are all excluded. A lost resume is a race, which is the first explanation that fits the ~1-in-3 success rate. Not settled: where the resume is lost, and no successful boot has been captured with kernel logging to compare against. --- docs/re/BACKLOG.md | 15 +++- docs/re/canary-scripted-input-traps.md | 76 +++++++++++++++++++ .../title-loader-thread-never-runs.log | 33 ++++++++ tools/re-capture/boot_menu.sh | 8 +- 4 files changed, 129 insertions(+), 3 deletions(-) create mode 100644 docs/re/captures/title-loader-thread-never-runs.log diff --git a/docs/re/BACKLOG.md b/docs/re/BACKLOG.md index 9f79d8dd..90e8a0be 100644 --- a/docs/re/BACKLOG.md +++ b/docs/re/BACKLOG.md @@ -151,8 +151,19 @@ See [`structures/ui-composable-bundles.md`](structures/ui-composable-bundles.md) ever**. So "the title ignores Ⓐ" is **withdrawn** — the loader stalls. 🔴 Refuted as the cause: the cache-flush crash. All four of today's runs have **zero** `GUEST-THROW`, `CRASH DUMP` and `Access Violation`; the guest stays - alive and polling. **Next probe:** what the `(1F)` thread waits on — an event - or file-system trace on that thread, not input, not the crash. + alive and polling. + ✅ **And now measured to the bottom:** with kernel logging finally on + (`LOG_MASK=12 LOG_LEVEL=3` — the scripts' `log_mask=13` had Kernel *disabled*, + which is why no boot log ever held a kernel call), a captured failure shows the + handler doing everything right — `XamUserGetXUID`, `NtCreateEvent`, + `ExCreateThread(entry=0x821748F0, CREATE_SUSPENDED)`, `NtResumeThread` — and + the thread then **never executing**: zero kernel calls of its own, and + **`00:00:00` host CPU time** while the process runs at 546 %. A spinning thread + burns CPU; this one never ran. A lost resume is a race, which is the first + explanation that fits the ~1-in-3 success rate. + **Next probe:** Xenia's `XThread` create/resume pair — can a resume land before + the host thread starts waiting? And capture one *successful* boot with kernel + logging, to say whether the guest sequence differs at all. See [`canary-scripted-input-traps.md`](canary-scripted-input-traps.md). * ❔ **Blend mode.** Everything is straight alpha-over. The near-white flash quads (`0xf0ffffff`) and coloured ones (`0x60ff0000`) may be additive. The diff --git a/docs/re/canary-scripted-input-traps.md b/docs/re/canary-scripted-input-traps.md index 5c2e25a6..e51c9a8c 100644 --- a/docs/re/canary-scripted-input-traps.md +++ b/docs/re/canary-scripted-input-traps.md @@ -444,3 +444,79 @@ Worth noting for anyone scripting boots meanwhile: **retry whole boots**. Nothin about the failed state recovers — four further presses over four minutes changed nothing, which is consistent with a loader that is stuck rather than a screen that is not listening. + + +## ✅ The loader thread is created and never runs (2026-08-19) + +**Status:** ✅ `CONFIRMED` on a captured failure, two independent ways (zero +kernel calls, zero host CPU time). 🔴 Where the resume is lost is not identified. + +### First: the harness had kernel logging switched off + +`log_mask` **disables** categories — Kernel=1, Apu=2, Cpu=4, Gpu=8 — so the +long-standing `--log_mask=13` in every boot script meant *Kernel + Cpu + Gpu +off*. Kernel calls also log at **Debug**, and `log_level` defaults to Info. So +seeing a single kernel call needs **both** `LOG_MASK=12 LOG_LEVEL=3`, and no boot +log this project has ever taken contained one. `boot_menu.sh` now accepts +`LOG_MASK` / `LOG_LEVEL` / `EXTRA_FLAGS`. The cost is small: a whole boot at +Debug with Kernel on is **23 MB**. + +### What the press actually does + +With that on, one boot reproduced the failure and the handler is fully visible: + +``` +XamUserGetXUID(00000000, 00000007, …) +NtCreateEvent(701CED80(701CEDE0), 0, 0, 0) +ExCreateThread(701CEDC0(701CEE50), 0, 0, 824AFF88, 821748F0, BC369B20, 00000001) +ExCreateThread Active: Thread Initially Suspended, +XThreadF80000CC (1F) Stack: 70880000-70900000 +NtResumeThread(F80000CC, 701CEE40(00000000)) +``` + +The game checks the signed-in user, creates an event, creates a thread **with +`CREATE_SUSPENDED`** at guest entry **`0x821748F0`**, and resumes it. Nothing is +wrong on the guest side. + +### And then the thread never executes + +Two independent measurements, on the stalled process: + +* **Zero kernel calls.** `F80000CC` appears in the log 13 times and **every one + is as an argument** — `Added handle`, `NtDuplicateObject`, `NtResumeThread`. + Not one line has it as the *calling* thread. Meanwhile 31 905 kernel calls are + made after the resume by five other threads + (`KeReleaseSemaphore` ×15 991, `XamInputGetKeystrokeEx` ×2 500, …). +* **Zero host CPU time.** `ps -L` on the emulator shows 71 threads; the only one + created after the press, `XThread47FFF6C0`, has **`00:00:00`** — while the + process as a whole is at **546 % CPU** and has burned 37 minutes of CPU in 6:46 + of wall time. + +A thread that is spinning burns CPU. This one has not run at all. + +([evidence](captures/title-loader-thread-never-runs.log)) + +### What that settles + +The chain is now: press delivered → handler runs → thread created suspended → +resumed → **never scheduled**. Every earlier suspect is excluded — input delivery +(logged as delivered, three ways), the cache-flush crash (zero `GUEST-THROW` / +`CRASH DUMP` / `Access Violation` in four runs), and the game's own logic (the +handler does everything it should). + +It also fits the intermittency, which nothing else did: a lost resume is a race, +and this boot path succeeds about **1 time in 3**. + +### What is not settled + +* 🔴 **Where the resume is lost.** `ExCreateThread` with + `ThreadInitiallySuspended` and `NtResumeThread` are both in + `xboxkrnl_threading.cc`; the next step is Xenia's `XThread` create/resume pair + and whether a resume can land before the host thread has started waiting. +* ❔ **No successful boot has been captured with kernel logging on.** The + comparison would say whether the difference is in the guest (a different call + sequence) or purely in the host (the same sequence, a resume that took). One + more boot at `LOG_MASK=12 LOG_LEVEL=3` is all it needs — the failure rate makes + that cheap. +* ❔ Guest entry `0x821748F0` is now a named RE target: whatever the menu loader + is. diff --git a/docs/re/captures/title-loader-thread-never-runs.log b/docs/re/captures/title-loader-thread-never-runs.log new file mode 100644 index 00000000..a29e340c --- /dev/null +++ b/docs/re/captures/title-loader-thread-never-runs.log @@ -0,0 +1,33 @@ +d> F8000008 XamInputGetKeystrokeEx(701CF854(00000000), 00000003, 701CF898) +d> F8000008 XamInputGetCapabilities(00000001, 00000001, 828F38E8) +d> F8000008 XamInputGetCapabilities(00000002, 00000001, 828F3938) +d> F8000008 XamInputGetCapabilities(00000003, 00000001, 828F3988) +d> F8000070 KeReleaseSemaphore(828A3230, 00000001, 00000001, 00000000) +d> F8000008 XamUserGetXUID(00000000, 00000007, 828F40B8(0000000000000000)) +d> F8000008 XamUserGetXUID(00000000, 00000007, 701CECF0(000000003F800000)) +d> F8000008 NtCreateEvent(701CED80(701CEDE0), 00000000, 00000000, 00000000) +d> F8000008 Added handle:F80000B4 for N2xe6kernel7XObjectE +d> F8000008 ExCreateThread(701CEDC0(701CEE50), 00000000, 00000000, 824AFF88, 821748F0, BC369B20, 00000001) +d> F8000008 ExCreateThread Active: Thread Initially Suspended, +d> F8000008 Added handle:F80000CC for N2xe6kernel7XObjectE +i> F8000008 XThreadF80000CC (1F) Stack: 70880000-70900000 +d> F8000008 NtResumeThread(F80000CC, 701CEE40(00000000)) +d> F8000084 MmGetPhysicalAddress(BE07BE00) +d> F8000084 MmGetPhysicalAddress(BE07DD00) +d> F8000084 MmGetPhysicalAddress(FFCA9080) +A> F8000084 XmaContext: reset context 2 +d> F8000070 KeReleaseSemaphore(828A3230, 00000001, 00000001, 00000000) +... +d> F8000090 Added handle:F80000CC for N2xe6kernel7XObjectE +d> F8000090 NtDuplicateObject(F80000CC, BC65D2C0(00000000), 00000002) +d> F8000008 NtClose(F80000CC) +d> F8000008 Removed handle:F80000CC for N2xe6kernel6XEventE +d> F8000084 Added handle:F80000CC for N2xe6kernel6XEventE +d> F8000084 NtClose(F80000CC) +d> F8000084 Removed handle:F80000CC for N2xe6kernel6XEventE +d> F8000084 Added handle:F80000CC for N2xe6kernel6XEventE +d> F8000084 NtClose(F80000CC) +d> F8000084 Removed handle:F80000CC for N2xe6kernel6XEventE +d> F8000008 Added handle:F80000CC for N2xe6kernel7XObjectE +i> F8000008 XThreadF80000CC (1F) Stack: 70880000-70900000 +d> F8000008 NtResumeThread(F80000CC, 701CEE40(00000000)) diff --git a/tools/re-capture/boot_menu.sh b/tools/re-capture/boot_menu.sh index c4df3ed6..ae34177a 100755 --- a/tools/re-capture/boot_menu.sh +++ b/tools/re-capture/boot_menu.sh @@ -52,7 +52,13 @@ LOG="${BOOT_MENU_LOG:-$SHOTS/$TAG-canary.stdout}" XUID="${SYLPH_XUID:-$(ls "${XENIA_CONTENT:-$HOME/.local/share/Xenia/content}" 2>/dev/null | head -1)}" [ -n "$XUID" ] || { echo "NO PROFILE — run once with --create_profile_if_none=Tag"; exit 2; } echo "signing in profile $XUID" -nohup run-canary --apu=sdl --log_mask=13 \ +# $LOG_MASK / $LOG_LEVEL / $EXTRA_FLAGS are overridable because the defaults +# hide most of the emulator. `log_mask` DISABLES categories (Kernel=1, Apu=2, +# Cpu=4, Gpu=8), so the long-standing 13 = Kernel+Cpu+Gpu off — which is why no +# kernel call has ever appeared in a boot log from this harness. Kernel calls +# also log at Debug, so seeing them needs BOTH `LOG_MASK=12 LOG_LEVEL=3`. +nohup run-canary --apu=sdl --log_mask="${LOG_MASK:-13}" \ + --log_level="${LOG_LEVEL:-2}" ${EXTRA_FLAGS:-} \ --logged_profile_slot_0_xuid="$XUID" "$LOG" 2>&1 & sleep 5 "$SD/skip_intro.sh" 600 || { echo "BOOT FAILED (skip_intro exit $?)"; exit 1; }