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:
@@ -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
|
**`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
|
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.
|
explanation that fits the ~1-in-3 success rate.
|
||||||
**Next probe:** Xenia's `XThread` create/resume pair — can a resume land before
|
✅ **LOCATED AND FIXED** (canary `a60fe7d11`): `threading_posix.cc` publishes a
|
||||||
the host thread starts waiting? And capture one *successful* boot with kernel
|
suspended thread's `state_` and its `suspend_count_` in **two separate lock
|
||||||
logging, to say whether the guest sequence differs at all.
|
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).
|
See [`canary-scripted-input-traps.md`](canary-scripted-input-traps.md).
|
||||||
* ❔ **Blend mode.** Everything is straight alpha-over. The near-white flash
|
* ❔ **Blend mode.** Everything is straight alpha-over. The near-white flash
|
||||||
quads (`0xf0ffffff`) and coloured ones (`0x60ff0000`) may be additive. The
|
quads (`0xf0ffffff`) and coloured ones (`0x60ff0000`) may be additive. The
|
||||||
|
|||||||
@@ -520,3 +520,84 @@ and this boot path succeeds about **1 time in 3**.
|
|||||||
that cheap.
|
that cheap.
|
||||||
* ❔ Guest entry `0x821748F0` is now a named RE target: whatever the menu loader
|
* ❔ Guest entry `0x821748F0` is now a named RE target: whatever the menu loader
|
||||||
is.
|
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
26
tools/re-capture/is_title.py
Executable 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)
|
||||||
@@ -43,13 +43,14 @@ while [ $SECONDS -lt $deadline ]; do
|
|||||||
[ -n "$(alive)" ] || { echo "EMULATOR GONE at ${SECONDS}s"; exit 4; }
|
[ -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=$(compare -metric RMSE /tmp/f1.png /tmp/f2.png null: 2>&1 | sed 's/ .*//' | cut -d. -f1)
|
||||||
d=${d:-0}
|
d=${d:-0}
|
||||||
# Classify the whole frame, do NOT probe one absolute pixel. The old test
|
# COUNT the green (A) glyph over the whole frame; do not probe one absolute
|
||||||
# sampled (625,618) for the green (A) glyph, which is a coordinate from a
|
# pixel and do not trust screen_id.py here. The pixel probe used a 1280x720
|
||||||
# 1280x720 grab; `screenshot` now returns the 1279x675 GAME SURFACE, where
|
# coordinate against the 1279x675 game surface and always read the copyright
|
||||||
# that point lands on the copyright line and reads (8,17,31). The symptom was
|
# line (600s TIMEOUT with the title on screen). screen_id.py fixed that and
|
||||||
# a 600s TIMEOUT with the title sitting on screen the entire time — measured
|
# then over-matched the other way: it called the SQUARE ENIX publisher logo
|
||||||
# 2026-08-19, with screen_id.py calling it "title" on the same frames.
|
# "title" 151s into a boot, and this script spent its one press there.
|
||||||
if [ "$(python3 "$SD_SI/screen_id.py" /tmp/f2.png | awk '{print $1}')" = "title" ]; then
|
# 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
|
echo "TITLE at ${SECONDS}s -> A"; tapA; exit 0
|
||||||
fi
|
fi
|
||||||
# DO NOT tap through the movies. This branch used to, and for a long time it
|
# DO NOT tap through the movies. This branch used to, and for a long time it
|
||||||
|
|||||||
Reference in New Issue
Block a user