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.
This commit is contained in:
@@ -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
|
||||
|
||||
@@ -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.
|
||||
|
||||
33
docs/re/captures/title-loader-thread-never-runs.log
Normal file
33
docs/re/captures/title-loader-thread-never-runs.log
Normal file
@@ -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))
|
||||
@@ -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" </dev/null >"$LOG" 2>&1 &
|
||||
sleep 5
|
||||
"$SD/skip_intro.sh" 600 || { echo "BOOT FAILED (skip_intro exit $?)"; exit 1; }
|
||||
|
||||
Reference in New Issue
Block a user