resume_reliability.sh counts, per boot, whether the title's loader thread became
the CALLER of a kernel call. Counting boots where the press reached the title:
before the fix 1 of 5 ran the loader; after it, 5 of 5. Three of the post-fix
boots were driven far enough to classify the screen and all three reached the
MAIN MENU, each with the same shape - title at 216-252s, 40 kernel calls by the
loader, 6 ResolvePath reads. The failing boots before had zero of both, every
time.
Caveat kept in the doc: pre-fix runs were interleaved with compiles and a race is
load-sensitive, so the counts corroborate the mechanism rather than carry it.
Also fixes a self-inflicted confound. Two runs came back 'title_at_s=none' with
the emulator log ending in 'Killed', which I first read as the title detector
being too strict. It was not: an earlier copy of the script was still running
because 'pkill -f resume_reliability.sh' had matched the shell running it rather
than the script, and each of that copy's iterations kills the emulator BY NAME -
outside run-canary's lockfile. The harness now takes its own lockfile and refuses
a second copy, and the note records that pkill -f matches your own shell.
The stalled loader thread is a lost wakeup in Xenia's POSIX threading, fixed on
the canary branch as a60fe7d11 and written up here. A thread created suspended
publishes state_ and suspend_count_ in two separate lock scopes, and Resume()
waits only for state_ before testing suspend_count_ == 0 - so a resumer in the
gap drops the resume and the thread waits forever. The Linux XThread::Resume
discards that false, which is why the guest saw success.
On the first clean boot after the fix the loader thread is the CALLER on 20
kernel-call lines and issues 4 ResolvePath reads. Every failed boot before it had
exactly zero of both.
Stated plainly as not shown: that boots now reach the menu RELIABLY. One post-fix
boot, and it is confounded by the harness.
Which is the second half. skip_intro.sh's title test has now been wrong twice in
opposite directions: originally one absolute pixel (625,618) - a 1280x720
coordinate against the 1279x675 game surface, so it read the copyright line and
timed out with the title on screen - and then my replacement, screen_id.py, which
is too loose and called the SQUARE ENIX publisher logo "title" 151s into a boot,
spending the script's single press there. is_title.py now counts the green (A)
glyph over the whole frame: geometry-independent and specific, measured at 0
pixels on the logo and 1520 on a real title.
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.
"The title screen ignores (A)" is withdrawn. First-divergence across three boots
of the same binary says otherwise.
A slot-(1F) guest thread is spawned BY the press: exactly once per run,
immediately after the keydown, same stack base 70880000-70900000 in both runs
that got one, and never at all in the run that never accepted a press - which
rules out a periodic worker starting around the same time.
prm6, reached the menu: (A) at line 6498, (1F) at 6500, 6 ResolvePath after
opt2, stuck on the title: (A) at line 1287, (1F) at 1288, 0 ResolvePath after
opt, stalled before title: no (A) ever, no (1F) thread at all
In the successful run the loader immediately reads six paths out of the on-disc
cache and the menu appears. In the failed run the same thread starts and performs
no file I/O ever again. Total ResolvePath for the three boots is 90/84/78 - the
successful run's extra six are exactly the ones after the press, so the boots are
otherwise identical in I/O.
Refuted as the cause: the cache-flush std::out_of_range. All four of today's runs
have zero GUEST-THROW, zero CRASH DUMP and zero Access Violation, and the guest
stays alive throughout with its keystroke-poll counter climbing past 15000.
Next probe is neither input nor the crash: what the (1F) thread waits on.
Drove NEW GAME deliberately (the menu's first item, no d-pad, which is what the
run that first hit the crash actually did). Three runs with --eh_dispatch on: no
crash, no throw, black screen before the save-slot screen. It is tempting to read
that as the flag working.
The run with --cache_throw_diag as well disproves it. That cvar logs the throw
BEFORE any dispatch is attempted, so a throw would appear whatever dispatch then
did — and there were zero. No guest exception happened, so neither flag ran any
code, so neither can explain the difference. What took those runs out is the
intermittent content-load hang, before the crash path was reached.
eh_dispatch therefore stays untested, and the entry says so with the reasoning
rather than banking a false pass.
Confirmed on the way: the screen after NEW GAME is DIFFICULTY — its whole-image
signature matches the earlier capture exactly — so the menu path is understood
even though the runs die after it.
The run with --eh_dispatch=true produced zero crashes and zero throws, which is
not the result it looks like: the crash path was never reached, so the flag is
UNTESTED. Recording that rather than banking a false pass.
What the run did establish, with screenshots: TUTORIAL leads to a lesson list
(a fifth screen nobody had captured, committed), and selecting BASIC CONTROLS
puts the guest on a permanent black screen — no crash, no GUEST-THROW, emulator
healthy. That gives the black screen a trigger it did not have before: it follows
a CONTENT LOAD, which also fits the earlier black screens.
So the two blockers on the way to a mission are distinct and both unbeaten: the
SELECT DATA crash when the path goes through save-slot enumeration, and the
black-screen hang on loading content. The eh_dispatch test needs a run that
actually reaches SELECT DATA.
The container runs the emulator, the Canary build and the disc test suite on the
same 12 cores, and Xenia alone takes about 5.5 of them. Several (A) experiments
and most boot-duration numbers in this entry were measured while a cargo test or
a build was running; one boot under that load never reached the title in 400 s,
against 130-290 s unloaded.
It does not explain the (A) result by itself — the interleaved A/B alternated
arms under whatever load was present, and the latest title recorded accepted
while an earlier one refused — but "a starved guest misses the input window" is a
hypothesis the existing data cannot exclude, and it should have been flagged when
the numbers were taken rather than after. The same navigation is now being run on
an idle box.
With the capture cvar gone from the launch line entirely, a fresh run reached the
boot title and (A) still did nothing. The flag is therefore not necessary for the
failure, and 0-of-7-with vs 4-of-6-without does not survive as an explanation.
The conclusion is the plain one: (A) at the title succeeds about half the time
and nothing measurable from outside predicts which. Five candidates are now
eliminated — Xenia UI swallowing the keystroke, the driver filter, a sign-in or
content call on the press, the age of the title, and the capture cvar.
So the guest side was traced instead. XamInputGetKeystrokeEx has exactly one
caller in the title, and that has one caller: entry_point -> main loop
(sub_8216EA68) -> per-frame input update (sub_822F1AA8) -> the pad poll
(sub_82457038). The poller's layout is readable and matches the runtime trace
(keystroke queue at +68/+72 drained with flags=3; current state at +36 compared
field-by-field against the previous at +52), and nothing in it is state-gated.
Whatever ignores (A) is a consumer further up — a real RE job, and that is where
the thread now stands, stated rather than guessed at again.
An interleaved A/B (arms alternating in one series, so cache warming cannot pose
as either variable) breaks the confound the last entry flagged — and not in the
direction the first table suggested. The LATEST title of every run recorded,
268 s, accepted (A); a 232 s title refused. "The title arrived late" is dead.
That leaves --log_ui_draws correlating at 0 of 7 against 4 of 5, with no
mechanism available: the cvar is read only when F10 arms a capture, F10 was never
pressed in those runs, the per-draw hook is one relaxed atomic load, and the two
arms' startup config dumps are byte-identical across 246 settings. A correlation
with no mechanism — and an arm that failed once — is not a finding; it is a
variable to remove. Removed: F10 now arms the capture unconditionally.
Also recorded: three boots this session ended on a permanent black screen, two of
them with no input at all. Not the pad, not the cache-flush crash, about one boot
in five.
Five candidate explanations for the (A) gate are now eliminated or refuted. The
next step is the guest's own state machine in sylpheed.db, not another guess from
outside.
Using last iteration's recipe (first title, one (A)) four more times, it failed
every time. The nine-run table splits perfectly on --log_ui_draws: 3 of 3
successes without it, 0 of 5 with it. That would indict my own instrumentation
cvar, which is the one that captures paint order.
It is also perfectly confounded and the entry says so rather than picking the
exciting reading: every success had its title inside 147 s, every failure at
177 s or later. Flag and boot-time move together across all nine runs. A
mechanism is hard to see for the flag (it is read only when F10 arms a capture;
the per-draw hook is one relaxed atomic load), which argues for the boot-time
story — but "I cannot see how" is not evidence.
The separating experiment is named: ON runs with a fast boot. One that accepts
(A) exonerates the flag.
Also recorded: widening the menu signature last commit made screen_id classify
some boot frames as "menu", twice in one run before any menu existed. A dark-blue
movie frame and this menu are not separable from a single grab — navigation
scripts need the classification to hold across two grabs, which is a caller-side
fix, not a classifier one.
Two results, one of which closes the navigation problem the last three
iterations kept hitting.
**The title states.** The hypothesis was that the attract-loop title is a
non-interactive presentation that omits the PRESS (A) plate. Half right:
* the state distinction is REAL — a single (A) on the title that ends the boot
opens the main menu, 2 of 2 in independent runs, one of which never pressed
F10; the title the attract loop returns to accepts nothing, not (A), START, B,
BACK, X or Y, across dozens of delivered presses;
* the proposed tell is REFUTED — capturing the draws in both states in one run
gives 13 quads at identical rects, ptbtn00 and ptbtn00f included. The two are
identical to the renderer and different only to the guest.
So there is now a reliable route to the menu: first title after boot, one tap.
**The main menu's paint order**, captured with it. Its sprites are GP_TITLE
build 5's, and ptframe1/ptframe2/ptbtn01f land within 4 px of their declared
resting placements — an independent placement check on an untouched bundle.
It does NOT settle the ordering question, and the entry says so: build 5 lists
its background at indices 1-2, so declaration order and "background first"
predict the same sequence here. Same failure mode as GP_READY_ROOM/GP_OPTIONS.
What it does establish is that the title's disagreement is not a decode
artefact — same pak, same engine, one build that follows its table and one that
does not.
The previous entry named the next step: "tap (A) once per second and see whether
the success rate goes to 1". It was run. The answer is no.
40 presses at 1/s on the title change nothing, and neither does one each of
START, B, BACK, X and Y. Every press was delivered (the driver logs down/up for
each) and the new [RE-INPUT] diagnostic never fired, so nothing was swallowed —
the guest received them and ignored them.
Also recorded, because it destroys a run rather than merely wasting it: tapping
(A) through the boot (88 presses over the intro) ends on a permanent black
screen with no crash and no throw.
What is left is a difference in STATE, not in input: the one success came on a
title that appeared ~83 s into a warm boot, the failures on titles that appeared
after a full attract cycle. "The attract-loop title is a non-interactive
presentation" is written down as a hypothesis with the experiment that would
settle it — a log_ui_draws capture in each state, looking for ptbtn00.
The previous entry called the title's Ⓐ a hard blocker. It is not: the main menu
is reached and screenshotted (NEW GAME / LOAD GAME / TUTORIAL / OPTIONS /
EXTRAS). What is true is narrower — Ⓐ advances the title only intermittently,
about one attempt in four, with the press verifiably delivered every time and no
Xenia UI active.
Three candidate causes were eliminated with measurements rather than argument:
* IsUIActive is now observable (Canary logs when it swallows a keystroke) and it
never fires on the failing runs;
* the driver filter is fine — the game polls with flags=3 and the file pad
reports Controller=1, so FilterDrivers keeps it;
* the game makes no content/user/signin call on the press at all — tracing every
Xam call around it shows only input polling.
And two traps in my own measuring rig, which cost more than the bug and are
written down so nobody repeats them: a FIFO trace consumer that exits STALLS the
emulator (the guest stops polling — indistinguishable from a dead pad, and it
produced two runs of false evidence), and phase-A's kernel.return events carry a
placeholder return_value of literally 0, so "every keystroke call returns
SUCCESS" was an artifact of the logger, not a finding.
Chasing the title-screen crash into the emulator's own diagnostics turned it
from a mystery into a controlled experiment, and knocked over two things this
corpus said yesterday.
Withdrawn #1: "the fault address 0x1_0000000C is a pointer with a stale high
word". The crash dump prints r25 = 0x0000000C, clean. Xenia maps the guest's
4 GiB at host 0x1_00000000, so that IS guest address 12. The guest dereferenced
the small integer 12.
Withdrawn #2: "with --mem_watch=false the crash does not happen at all", which
named the crash-oracle handoff's suspect #1 as measured. It was confounded —
every --mem_watch=false run had also had a warm cache. Held cold, the throw
happens with the probe off (2 437 crash dumps). mem_watch is eliminated for this
crash.
What it actually is: the access violation is the guest's own `throw` RETURNING,
because this build logs guest C++ exceptions and continues rather than
unwinding. So the event is the throw, and with --cache_throw_diag=true the guest
names it: std::out_of_range, from the cache-manager flush, with a deque of 38
entries (37 distinct, one duplicated) against a 37-key map, every one of them
absent from the flush's snapshot but present in the live map — the TOCTOU race
the logger's own message describes.
And the new, useful part: the trigger is the on-disc cache. Complete cache, no
throw (2 runs). Directory moved aside or half-rebuilt, throw ~100 s into the boot
(3 runs, including one that threw with NO access violation behind it — which is
why crash dialogs are the wrong thing to count). A suspect in that bisection plan
now costs a `mv` and two minutes instead of a mission.
The crash PC from the previous iteration resolves, and it names itself:
sub_823070B0 references the string 'invalid map/set<T> iterator', builds it with
the string helpers and throws it — which is the guest C++ exception (E06D7363)
Xenia reports one line earlier. Its node offsets are MSVC's red-black tree node
exactly (_Left 0, _Parent 4, _Right 8, _Color 24, _Isnil 25), so this is a
std::map/set erase, and the fault is the first dereference after the iterator
check.
That matters beyond this blocker. The canary handoff's Ready-Room crash is the
same shape — a guest STL exception in a cache/save path — and its bisection plan
is priced at "one build plus one Ready-Room run" per suspect. If it is the same
defect, each suspect now costs 40 seconds, and suspect #1 is already measured:
--mem_watch=false removes it.
Stated as unresolved rather than guessed: the fault address 0x1_0000000C is a
32-bit value with bit 32 set, which fits BOTH a corrupt guest tree and a stale
high word on the emulator side. The measurement that separates them (read the
node from guest memory at the throw) is written down rather than assumed.
The second, unreproduced crash PC is identified too: an unrolled 4x16-bit copy
loop faulting on the STORE, i.e. a bad destination — a different failure.
Each of these presents as "the pad is dead", and each has a different cause.
1. **F10 opens the emulator's menu bar.** It is the RE capture hotkey AND the
toolkit's menu key. With that menu open — or any Xenia UI window, the
Profiles Menu included — `IsUIActive()` is true, so XamInputGetKeystrokeEx
returns SUCCESS with a ZEROED keystroke before the pad driver is asked. The
guest polls, gets nothing, and does nothing, with no error anywhere. Escape
does not close it; a click on the game surface does. This cost most of an
iteration.
2. **The file-pad was never the problem.** It delivers (vk=5800 down/up per tap)
and A skips movies in the same runs.
3. **(A) at the title needs a signed-in profile.** Without one the guest calls
XamShowSigninUI and Xenia's dialog appears — which is also the proof the
guest reads the button. That dialog cannot be completed here: the gamertag is
an ImGui text field and synthetic X key events never reach it. Hence Canary's
new --create_profile_if_none.
And the blocker, stated as measured rather than as a theory: with the profile
signed in, (A) still does not advance the title across four boots. The
reproducible failure is next door — with the default --mem_watch=true the guest
crashes in the boot content path (read of 0x10000000C at 0x82307128, thread 9,
after a guest C++ throw), and with --mem_watch=false it does not. That is a
second, far cheaper reproduction of the Ready-Room crash the canary handoff
blames on the mem_watch probe: 40 s from a cold boot instead of after a mission.
One observation kept because it did not reproduce: a single (A) once crashed the
guest at a DIFFERENT PC (0x824578A0, thread 6). Two attempts to reproduce it
gave neither a crash nor a transition.
Next step named: those two PCs in xenia-rs/sylpheed.db, and the content exports
around the press.
