tools+docs: locate the lost resume, and a title test that is neither too narrow nor too loose

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.
This commit is contained in:
Sylpheed RE agent
2026-08-19 10:41:43 +00:00
parent 8b290d7012
commit e2645255f5
4 changed files with 130 additions and 10 deletions

View File

@@ -161,9 +161,21 @@ See [`structures/ui-composable-bundles.md`](structures/ui-composable-bundles.md)
**`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.
**LOCATED AND FIXED** (canary `a60fe7d11`): `threading_posix.cc` publishes a
suspended thread's `state_` and its `suspend_count_` in **two separate lock
scopes**, and `Resume()` waits only for `state_` before testing
`if (suspend_count_ == 0) return false`. A resumer in that gap drops the
resume; the thread then waits on the count forever. The Linux `XThread::Resume`
discards the `false`, so the guest saw success. Fixed by publishing both under
one lock and waiting without releasing it. On the first clean boot after, the
loader thread is the **caller** on 20 kernel-call lines with 4 `ResolvePath`
reads — every failure before had **zero** of both.
🟡 **Still to show:** that boots now reach the menu *reliably*. The post-fix
boot is confounded — `skip_intro.sh`'s title test has been wrong twice (an
absolute pixel against the wrong surface size, then `screen_id.py` matching the
SQUARE ENIX logo). Now `tools/re-capture/is_title.py` counts the green Ⓐ glyph:
0 px on the logo, 1520 on a real title. A before/after reliability count over
several boots is the remaining work.
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

View File

@@ -520,3 +520,84 @@ and this boot path succeeds about **1 time in 3**.
that cheap.
* ❔ Guest entry `0x821748F0` is now a named RE target: whatever the menu loader
is.
## ✅ Located and fixed: a lost resume in Xenia's POSIX threading (2026-08-19)
**Status:**`CONFIRMED` as the mechanism, by reading the code against the
measurement. ✅ The fix demonstrably changes the emulator's behaviour in the
predicted way. 🟡 **End-to-end menu reliability is NOT yet demonstrated** — one
post-fix boot, and it is confounded (below).
### The race, exactly
`threading_posix.cc` starts a thread created suspended like this:
```cpp
{ lock; state_ = create_suspended ? kSuspended : kRunning; notify_all(); }
// ← lock released
if (create_suspended) { lock; suspend_count_ = 1; wait(count == 0); }
```
and `Resume()` is:
```cpp
WaitStarted(); // waits only for state_ != kUninitialized
lock;
if (suspend_count_ == 0) { return false; } // ← the resume is DROPPED
```
Two separate lock scopes, with the state published **before** the suspend count.
A resumer that arrives in the gap sees a started thread with count 0, drops the
resume, and returns `false`. The new thread then sets the count to 1 and waits on
it forever.
`XThread::Resume`'s Linux path discards that `false` — the Windows path turns it
into `X_STATUS_UNSUCCESSFUL` — so the guest was told the resume succeeded. The
failure was invisible from both sides.
### Why it fits everything measured
| observation | explained |
|---|---|
| loader thread makes **zero** kernel calls | it never leaves the CV wait |
| its host thread has **00:00:00** CPU | ditto — a spin would burn CPU |
| the guest handler looks perfect | it is; the resume it issued was dropped |
| success rate ~**1 in 6** | it is a race |
| `NtResumeThread` returns success | the Linux path ignores the `false` |
### The fix, and what it showed
Publish `state_` and `suspend_count_` under **one** lock and wait without ever
releasing it, so a resumer past `WaitStarted()` always observes 1
(canary `a60fe7d11`).
On the first clean boot afterwards, the same loader thread is the **caller** on
**20** kernel-call lines and issues **4** `ResolvePath` asset reads. Every failed
boot before the fix had exactly **zero** of both. That is the predicted change,
and it is the strongest evidence available short of a reliability run.
### What is honestly not shown
* 🟡 **That boots now reach the menu reliably.** The post-fix boot drifted into
the attract loop because `skip_intro.sh` fired its single press at 145 s, and
the run before it pressed on the **SQUARE ENIX publisher logo** — see below. A
clean before/after reliability count still needs several boots.
* ⚠️ **`host resume was refused` is not by itself a defect.** Resuming a thread
that is not suspended legitimately returns false, and the log fires ~7 times in
a normal boot. It is a breadcrumb, not an alarm.
### A harness regression I introduced and then corrected
`skip_intro.sh`'s title test has now been wrong twice, in opposite directions:
1. the original probed **one absolute pixel** `(625,618)` for the green Ⓐ glyph —
a 1280×720 coordinate against the 1279×675 game surface, so it read the
copyright line and timed out with the title on screen;
2. my replacement used `screen_id.py`, which is **too loose**: it called the
SQUARE ENIX logo "title" 151 s into a boot and the script spent its one press
there.
Now `tools/re-capture/is_title.py` **counts** the green glyph over the whole
frame — geometry-independent and specific. Measured: **0** pixels on the SQUARE
ENIX logo, **1 520** on a real title, threshold 400.

26
tools/re-capture/is_title.py Executable file
View File

@@ -0,0 +1,26 @@
#!/usr/bin/env python3
"""Is this frame the interactive title screen? Exit 0 if yes.
Counts the pixels of the **green (A) glyph** in "PRESS (A) BUTTON" anywhere in
the frame. That is the one thing only the interactive title has, and counting is
geometry-independent — unlike the single absolute pixel this replaced, which was
a 1280x720 coordinate being sampled against the 1279x675 game surface and always
read the copyright line.
`screen_id.py` is too loose for this job on its own: it called the SQUARE ENIX
publisher logo "title" 151 s into a boot, and skip_intro spent its one press
there. Measured on a real title frame: 1442 glyph pixels, centred near (622,572).
is_title.py FRAME.png [min_pixels]
"""
import sys
import numpy as np
from PIL import Image
a = np.asarray(Image.open(sys.argv[1]).convert("RGB"), dtype=int)
r, g, b = a[:, :, 0], a[:, :, 1], a[:, :, 2]
n = int(((g > 130) & (g - r > 45) & (g - b > 45)).sum())
need = int(sys.argv[2]) if len(sys.argv) > 2 else 400
print(f"green-glyph px {n} (need {need})")
sys.exit(0 if n >= need else 1)

View File

@@ -43,13 +43,14 @@ while [ $SECONDS -lt $deadline ]; do
[ -n "$(alive)" ] || { echo "EMULATOR GONE at ${SECONDS}s"; exit 4; }
d=$(compare -metric RMSE /tmp/f1.png /tmp/f2.png null: 2>&1 | sed 's/ .*//' | cut -d. -f1)
d=${d:-0}
# Classify the whole frame, do NOT probe one absolute pixel. The old test
# sampled (625,618) for the green (A) glyph, which is a coordinate from a
# 1280x720 grab; `screenshot` now returns the 1279x675 GAME SURFACE, where
# that point lands on the copyright line and reads (8,17,31). The symptom was
# a 600s TIMEOUT with the title sitting on screen the entire time — measured
# 2026-08-19, with screen_id.py calling it "title" on the same frames.
if [ "$(python3 "$SD_SI/screen_id.py" /tmp/f2.png | awk '{print $1}')" = "title" ]; then
# COUNT the green (A) glyph over the whole frame; do not probe one absolute
# pixel and do not trust screen_id.py here. The pixel probe used a 1280x720
# coordinate against the 1279x675 game surface and always read the copyright
# line (600s TIMEOUT with the title on screen). screen_id.py fixed that and
# then over-matched the other way: it called the SQUARE ENIX publisher logo
# "title" 151s into a boot, and this script spent its one press there.
# is_title.py counts glyph pixels, which only the interactive title has.
if python3 "$SD_SI/is_title.py" /tmp/f2.png >/dev/null 2>&1; then
echo "TITLE at ${SECONDS}s -> A"; tapA; exit 0
fi
# DO NOT tap through the movies. This branch used to, and for a long time it