24c1c940e6
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.
69 lines
3.7 KiB
Bash
Executable File
69 lines
3.7 KiB
Bash
Executable File
#!/usr/bin/env bash
|
|
# Boot to the TITLE MENU and stop there — no save is loaded.
|
|
#
|
|
# nav_probe.sh's boot half deliberately loads a save, which is wrong for any
|
|
# experiment that wants to *inspect* save slots rather than enter one: with
|
|
# several probe saves on disc the load picks one of them, and a probe value the
|
|
# game cannot make sense of turns into a long "NOW PROCESSING" (or a mission
|
|
# load, if a d-pad step is dropped and A lands on TAKE OFF).
|
|
#
|
|
# From the main menu, LOAD GAME is one d-pad step away and its slot list renders
|
|
# every slot's Details panel — STAGE, Game Status, Points, Times Cleared — which
|
|
# is read straight out of each save's payload. That makes this the cheap harness
|
|
# for save-field probes: write N slots, boot once, arrow through them.
|
|
#
|
|
# Run as ONE BLOCKING FOREGROUND call. Usage: boot_menu.sh [tag]
|
|
set -u
|
|
export HOME=/sylph-home/re SDL_AUDIODRIVER=dummy DISPLAY=:98
|
|
SD="$(cd "$(dirname "$0")" && pwd)"
|
|
SHOTS=/sylph-home/re/shots
|
|
TAG="${1:-menu}"
|
|
mkdir -p "$SHOTS"
|
|
|
|
alive(){ ps -o pid=,stat= -C xenia_canary 2>/dev/null | awk '$2 !~ /^Z/ {print $1}'; }
|
|
ensure_display(){
|
|
if ! xdpyinfo -display "$DISPLAY" >/dev/null 2>&1; then
|
|
rm -f "/tmp/.X${DISPLAY#:}-lock" 2>/dev/null || true
|
|
nohup bash -c 'Xvfb "$0" -screen 0 1280x720x24 -ac -nolisten tcp \
|
|
+extension GLX +extension RANDR >/tmp/xvfb98.log 2>&1' "$DISPLAY" </dev/null >/dev/null 2>&1 &
|
|
for _ in $(seq 1 50); do xdpyinfo -display "$DISPLAY" >/dev/null 2>&1 && break; sleep 0.2; done
|
|
nohup env DISPLAY="$DISPLAY" HOME=/sylph-home openbox </dev/null >/tmp/openbox98.log 2>&1 &
|
|
sleep 1
|
|
fi
|
|
xdpyinfo -display "$DISPLAY" >/dev/null 2>&1 || { echo "DISPLAY UNAVAILABLE"; exit 1; }
|
|
}
|
|
|
|
[ -n "$(alive)" ] && { kill -9 $(alive) 2>/dev/null; sleep 2; }
|
|
rm -f /dev/shm/xenia_memory_* /dev/shm/xenia_code_cache_* 2>/dev/null
|
|
ensure_display
|
|
cd /sylph-home/re
|
|
# KEEP the emulator's stdout. It used to go to /dev/null, which cost a session:
|
|
# the pad appeared dead at the title and the one log line that would have said
|
|
# why — "[RE-INPUT] XamInputGetKeystrokeEx swallowed by IsUIActive" — was being
|
|
# discarded. A boot harness that throws away the emulator's own account of
|
|
# itself can only ever report symptoms.
|
|
LOG="${BOOT_MENU_LOG:-$SHOTS/$TAG-canary.stdout}"
|
|
# Sign in the profile that EXISTS. Naming a XUID with no profile behind it is
|
|
# not a no-op: the title opens a sign-in dialog, xam_dialogs_shown_ goes to 1,
|
|
# and IsUIActive() then swallows every XamInputGetKeystrokeEx for the rest of
|
|
# the run — a pad that delivers keystrokes to an emulator that discards them.
|
|
# Measured: 8.4 MILLION swallowed calls in one boot, with the pad log showing
|
|
# `vk=5800 down/up` arriving normally the whole time.
|
|
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"
|
|
# $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; }
|
|
sleep 14
|
|
screenshot "$SHOTS/$TAG-menu.png" >/dev/null 2>&1
|
|
echo "AT MAIN MENU (cursor on NEW GAME); LOAD GAME is one d-pad step down"
|
|
echo "emulator log: $LOG"
|