Files
Sylpheed/docs/re/capture-harness-status.md
sylph-decoder 5fcc89be55 re: the PRESS-A plate arrives 2.13 s after the title settles, measured twice
The one number the port said decides a structural question on its side: whether
`ScreenView` has to draw two builds at once. It does. The boot title shows
build 4 alone, and 2.13 s after build 4 stops animating it composites build 2
over it. Two independent boots agree to 6 ms (2.138 / 2.132), which is under one
sample interval.

Measure from SETTLED, not from first pixels. "First drawn -> plate" is 3.78 s in
one run and 4.26 s in the other, because the build-in animation itself ran 1.64 s
and 2.13 s -- that spread is the emulator's frame pacing, and it is exactly the
kind of number that looks like a measurement.

Ruled out before believing it: that the plate was pulsing all along, too dim for
a thresholded glyph counter. The counter reads EXACTLY 154 -- the committed
no-plate title's own value -- for every frame of a plateau nearly one full pulse
period long, with zero variation, and the surface mean is flat to +/-0.03 across
it. A cycling overlay moves both.

Also settled, and also not:

  * the black hold between two screens is 0.14-0.30 s, which brackets the port's
    authored 0.17-0.23 s and the file's declared 12 units. Their constant stands.
  * the (A)->menu latency is STILL not available, and now the reason is known.
    Both runs freeze one frame for ~1.4 s at surface mean 26.626 -- agreeing
    between runs to six decimals, and reproduced in run 2 with stream restarts
    disabled, so it is not the capture path. It is a guest load stall: the (B)
    path, which loads nothing, has no freeze at all. Any figure from it would be
    an emulator load time.

Refutation attempt, recorded whether or not it survived: navigation.md's "the
title is not input-ready for about ten seconds, and even then (A) registers
roughly half the time". At 7.29 s and 7.28 s after the title settled, (A) was
accepted first press in both runs, as was (B) on the menu. n=2 only makes "half
the time" unlikely (p ~ 0.25); it contradicts the ten seconds outright.

And the standing red banner is withdrawn: the interactive title IS reachable in
this container, twice, with no pad input, in ~3.5 minutes. Why it changed is NOT
established -- this container came up with no Xenia storage root at all, so run 1
created a profile -- and that is written as a correlation for the next session to
test rather than as a cause.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_014voBspJ6kFncNErZJuZcLw
2026-08-29 12:15:22 +00:00

25 KiB
Raw Blame History

WITHDRAWN 2026-08-29 (later the same day) — the interactive title IS reachable here, twice, with no pad input

This banner supersedes everything below it about the title being unreachable, and it supersedes the 🔴 "Emulator-side questions are blocked" section of MISSION. Everything below is kept because the harness defects it diagnoses were real and the fixes are in use; what it concluded about the game is now refuted by measurement.

Two consecutive boots reached the interactive title, with the PRESS Ⓐ BUTTON plate, without a single pad press before it:

run 1 run 2
plate on screen at 205.4 s into the probe 218.4 s
pad input before that none none
Ⓐ then reached the main menu
Ⓑ then returned to the title

Full per-frame traces, 8 fps, 1783 and 1886 frames: data/plate-timing-run1.tsv · data/plate-timing-run2.tsv. The measurement they were taken for is title-plate-delay-measured.md.

So the standing negative — "three runs, two locales, two launch paths, ~35 minutes of emulator time, no interactive title" — does not hold in this container today. The attract loop is simply passed through in ~3.5 minutes and the title follows.

What changed is NOT established, and I am not going to guess it

What is different about this container, stated as facts rather than as a cause:

  • it came up with no Xenia storage root at all — no ~/.local/share/Xenia, so no profile, no xconfig.settings, and no shader cache. The earlier runs signed in a profile that already existed.
  • run 1 therefore had to create one, with canary's own --create_profile_if_none=Decoder. Run 2 signed in the profile run 1 made (B13EBABEBABEBABE).
  • the launch was otherwise boot_menu.sh's, minus skip_intro.sh — this measurement had to leave the title untouched, so nothing tapped Ⓐ at all.

⚠️ A cold profile is a correlation across two runs, not a cause. It is written down so the next session can test it directly (delete the storage root, boot, compare) instead of re-deriving that the title is reachable.

🔵 What this unblocks

  • the Japanese-locale capture that MISSION parks as "🟡 needs one more run": the mechanism (set_console_language.py ja, user.language at file offset 0x912) is in place, and the reason it was parked — the title never appears — is gone. ⚠️ Note the storage root is new, so xconfig.settings has been recreated and the byte offset should be re-located by its three landmarks rather than assumed.
  • the two items MISSION lists as emulator-blocked: the gamma control behind tone curve, and separating 8AX from ptbase in 8AX.

🔴 Why the boot harness stopped reaching the title — screenshot costs 10.8 s

Status: diagnosed, with a control. Four consecutive runs on 2026-08-28/29 failed to reach the interactive title, across two locales, two launch paths and two display-gamma settings. The cause is none of those.

The measurement

condition one screenshot call
while Xenia Canary is running 10.8 s
immediately after killing it 0.117 s

92×. The 1-minute load average at the slow measurement was 1.80, so this is contention with the emulator (both go through the same X server), not general system load.

Why that breaks the harness

skip_intro.sh takes two grabs 0.6 s apart per iteration, plus an is_title.py numpy load. Its actual sample timestamps in the last run:

57, 95, 177, 218, 238, 298, 333, 380, 426, 471, 515   → intervals
38, 82, 41, 20, 30, 30, 35, 47, 46, 45, 44, 43, 21, 19  median 41 s

A 41-second sampling interval against a title screen that the corpus already documents as lasting "a few seconds" before auto-returning to the attract loop (wait_title.sh's own header). The harness is not seeing a stuck game; it is blinking slower than the thing it is looking for.

That is also why runs at 16:4318:05 the same day succeeded and later ones did not — nothing about the game changed.

🔴 What this retracts

Three earlier conclusions were built on these runs and are withdrawn as causes, though the observations stand:

  • "the Japanese-locale run never reaches the interactive title" — it may well have appeared, unsampled.
  • "neither locale reaches the interactive title without a pad press" — the English control shared the same defect, so it controlled for locale but not for the sampling rate.
  • "the game sat in the attract loop for 604 s" — what was observed is that every one of ~15 samples landed on movie content, which at a 41 s interval is a much weaker statement than it reads as.

⚠️ A confound I introduced

Setting kernel_display_gamma_type = 0 makes the frame substantially brighter (a mid-attract frame measured mean 122.8 against 52.5 and 82.8 on comparable phases at type 2). skip_intro.sh classifies movie-vs-static on an absolute rmse threshold of 1500 between two grabs, so a brighter output inflates that difference and biases every frame toward "movie". The capture harness's tuning is coupled to the display settings — changing gamma and capture behaviour in one run confounds both.

🔴 The fix works — and it REFUTES the diagnosis above

Built and measured (tools/re-capture/fast_title_probe.py): one long-lived ffmpeg x11grab stream, raw RGB frames, glyph counted in numpy. No per-sample process startup, no PNG encode, no convert -crop.

probe seconds per sample, emulator running
the wrapper screenshot 3.98
import -window root → PPM 1.20
long-lived x11grab stream 0.29

13.7× faster, and the counter is control-verified against the committed frames — it returns 753 on live-title-press-a.png and 327 on live-main-menu.png, byte-identical to is_title.py.

Then it was pointed at a running game:

332 frames in  85.3 s = 3.89 fps; max glyph 0
1674 frames in 420.0 s = 3.99 fps; max glyph 0

1 674 consecutive samples over seven unbroken minutes, four per second, and the interactive title never appeared. So the sampling rate was a real defect and not the cause. The hypothesis on this page — that the harness was blinking slower than the event — is mine, and refuted by my own fix.

What that restores

Last iteration I withdrew three conclusions on the strength of that hypothesis. The withdrawal was right at the time (15 samples at 41 s intervals cannot support them) and is now superseded by better evidence: dense sampling says the interactive title genuinely does not appear in a mid-run window. Reinstated as a measurement, with its reach:

  • over 420 continuous seconds, English, gamma_type = 2, ~13 minutes into a run with no pad input, zero frames carried the green Ⓐ glyph.
  • ⚠️ Reach: this covers a mid-run window only. It says nothing about the first minutes of boot.

🟡 The leading hypothesis, not confirmed

The corpus already suspects the answer. title_states_capture.sh exists to test "whether the interactive one draws ptbtn00 (the PRESS Ⓐ plate) and the other does not" — i.e. the title appears twice: once at the end of the boot sequence, and again from the attract loop, and only the first may carry the plate. If so, the plate's window is early and one-shot, and no amount of mid-run sampling will ever find it.

That is consistent with everything measured, and it is not confirmed. The test is to start the fast probe before the boot title — from t=0 rather than attaching to a run already in progress.

The original fix note, kept

Make the probe cheap enough to sample faster than the title window: grab a small region rather than the full surface, drop the ImageMagick convert round trip, or keep the glyph test in one long-lived process instead of re-importing numpy per sample. None of that is done — this page is the diagnosis, and it is what every remaining emulator-side question is waiting on.


🔴 The boot-window hypothesis is refuted too — and the surface is BLACK

2026-08-29, third explanation and third refutation. The named experiment was to attach the fast probe at t = 0 so the boot title could not be missed. Done, on the default config, English:

2391 frames in 600.4 s = 3.98 fps; max glyph 0; hits 0

Ten minutes, sampled four times a second from launch, and the green Ⓐ glyph never appeared. So "the plate only shows in an early boot window I keep missing" is mine, and refuted.

Then the thing I should have checked first. Splitting the raw root grab by band:

band non-black mean
y 044 (the GTK menu bar) 100 % 210.5
y 45719 (the game surface) 0.08 % 0.07

The game is rendering black, reproducibly across back-to-back samples, while the guest is alive and polling input (XamInputGetKeystrokeEx past 1 201 calls) and MEM-WATCH keeps reporting. The crop and every pixel oracle were correct; there was nothing on the surface to detect.

⚠️ What this does and does not explain

It does not retroactively explain the earlier failures, and saying so would be the fourth over-reach in a row. Those runs had content: run 2 sampled frames at mean 33.1 (warm), run 3's classifier measured real frame-to-frame rmse, and the gamma_type = 0 run measured mean 122.8. A black surface is this run's symptom.

So the honest reading is that the failure mode changed over the session, and the black screen is a new and worse one.

🟡 Hypothesis for the regression, untested

Canary's shader/pipeline cache at ~/.local/share/Xenia/cache is 47 MB and was last written 23:49 on 2026-08-28 — during the failed runs. This session has kill -9'd the emulator repeatedly, which can leave a partially written cache. A corrupt pipeline cache is a plausible route to a guest that runs while nothing reaches the screen.

The test is one line and one run: move cache* aside and boot again. Not done — it needs a fresh 10-minute run, and this iteration had spent its emulator budget proving the negative above.


🔴 The fast probe STALLS — and that invalidates its own dense negatives

2026-08-29. The instrument built last iteration is unfit for long runs, found by cross-checking it against an independent grabber while both watched the same screen.

A single long-lived ffmpeg x11grab stream degrades and then freezes:

862 frames in 540.1 s = 1.60 fps          (it starts at 3.98 fps)
t=450s surface mean 5.21 nonblack 10.1%
t=480s surface mean 5.21 nonblack 10.1%
t=510s surface mean 5.21 nonblack 10.1%
t=540s surface mean 5.21 nonblack 10.1%

Four consecutive 30-second marks reporting an identical value. At that same moment an import grab of the same display read surface mean 125.65, and a freshly started ffmpeg stream read 122.43 — agreeing with import to 3 %. So the acquisition, not the analysis, was broken: the stream was replaying a stale frame while the screen was 24× brighter.

🔴 Therefore the previous section's headline is withdrawn. "2 391 frames over 600 s from t=0, max glyph 0" cannot distinguish the title never appeared from the stream froze early and repeated one frame 2 391 times. Its 3.98 fps was measured over the first 20 s, before the degradation.

Fixed in tools/re-capture/fast_title_probe.py: the stream is torn down and restarted every 30 s. Startup costs ~0.3 s, cheap against the title's window, and it buys a guarantee the frames are live.

Clearing the shader cache restored rendering

The cache hypothesis from the previous section was tested: cache, cache0, cache1 and cache_host moved aside (to /tmp/xenia-cache-aside, not deleted), then a fresh boot.

The surface renders again, confirmed with the independent grabber: import reads surface mean 54.8 and 68.6 on successive samples with 100 % non-black warm content, against 0.07 and 0.08 % non-black in the black run. The probe's own summary agrees where it can be trusted — **773 of 862 frames had

2 % non-black**.

🟡 Supported, not proven. One run each side, and the emulator was kill -9'd many times before the black run, so a corrupt pipeline cache is plausible but a single A/B does not exclude run-to-run variation. The old caches are kept in /tmp/xenia-cache-aside if anyone wants to reproduce the failure.

Still no title. Even rendering, max glyph 0 — but that number now comes from a stalling probe, so it establishes nothing either way.


A negative I can finally stand behind — measured with a self-validating probe

2026-08-29. Three earlier "the title never appears" claims came from instruments that were later found broken (a stale pixel oracle, a 41 s sampling interval, a freezing stream). This run used tools/re-capture/title_probe_xchecked.py, which restarts its stream every 30 s and cross-checks itself against an independent import grab every 60 s, printing both numbers.

1851 frames in 560.2 s = 3.30 fps
cross-checks 9, disagreements 1
max glyph 0
t stream import
62 s 6.05 0.07 disagree — a fade, the boot logos are mid-transition
123 s 7.40 7.49 agree
183 s 8.18 8.29 agree
243 s 0.23 0.10 agree
311 s 89.68 89.51 agree
371 s 80.97 81.58 agree
426 s 117.43 117.72 agree
487 s 77.71 76.25 agree
546 s 70.43 70.55 agree

Eight of nine agree to within 2 %, the fps held at 3.30 (no collapse to 1.60), and the surface plainly moved through dark and bright phases. The frames were live and the negative is real:

Measured — over 560 continuous seconds from launch, sampled 3.3 times a second by a cross-validated probe, the interactive title's green Ⓐ plate never appears, while the game renders throughout.

The final frame correlates 0.0145 with our title render, 0.0047 with the main menu and 0.0102 with EXTRAS — it is attract-movie content, not a UI screen at all.

Why, still unknown

live-title-press-a.png is committed and carries 753 glyph pixels, so the title was reachable from this container on 2026-08-28. Nothing found so far explains the change. Clearing the shader cache fixed the black surface but not this.

Where this leaves the emulator-side questions

The two open items that need a running menu — the gamma control (tone curve) and separating 8AX from ptbase (8AX) — remain blocked, now on a well-characterised and instrument-verified failure rather than on a suspicion. Neither blocks the five menu screens. Returning to static work; the probe is committed for whoever picks this up.


The GPU trace route: attempted, produced nothing, characterised

2026-08-29. To turn the gamma-ramp inference into an observation, canary's trace_gpu_stream should work — it records gamma ramps as their own command type (kGammaRamp, index 11 in TraceCommandType). Two bounded runs produced no trace file at all: nothing under the prefix, no .xtr anywhere, no scratch/gpu/.

Bounded deliberately: the container's disk is at 95 % (50 GiB free) and a boot-time trace of all GPU packets includes video decode, so the runner carried a watchdog killing the emulator the moment the trace passed a 2 GiB cap. It never fired — there was nothing to cap. Disk was unchanged at 95 % throughout.

What the attempt did establish:

  • BeginTracing() is called at GPU init when the cvar is set (graphics_system.cc:237), but EndTracing() runs only from GraphicsSystem::Shutdown(). A kill -9 — which this session has used routinely — can never finalise a trace. The second run was therefore stopped with SIGTERM and exited cleanly. Still no file, so that is not the whole story.
  • Two candidates remain and were not separated: the CLI flag not reaching the cvar, or BeginTracing() failing silently.

Explained — and it was neither candidate

The trace writer is compiled out of the build in use. Following the code: BeginTracing() only sets trace_state_ = kStreaming"Streaming starts on the next primary buffer execute" — and the file is opened later, in ExecutePrimaryBuffer, inside

#if XE_ENABLE_TRACE_WRITER_INSTRUMENTATION == 1

which trace_writer.h defines as:

#ifdef NDEBUG
#define XE_ENABLE_TRACE_WRITER_INSTRUMENTATION 0   // release
#else
#define XE_ENABLE_TRACE_WRITER_INSTRUMENTATION 1   // debug
#endif

Confirmed in the binaries themselves, with a control. The format string "{:08X}_stream.xtr" exists only inside that guard:

binary _stream.xtr occurrences
build/bin/Linux/Release/xenia_canary 0
build/bin/Linux/Debug/xenia_canary 1
/sylph-home/re/canary-build/.../Release/xenia_canarythe one run-canary uses 0

So trace_gpu_stream is a no-op in this container's emulator: the cvar parses, BeginTracing runs, and nothing can ever open a file. Neither the CLI flag nor BeginTracing was at fault, and neither was the kill -9 — though that would have destroyed the trace too, had one existed.

🟡 The route exists but is not cheap. A Debug build with the writer compiled in is present at build/bin/Linux/Debug/xenia_canary (253 MB against Release's 18 MB). Running it means a much slower boot and a trace of every GPU packet on a disk at 95 %. Recorded as available rather than attempted — the thing it would confirm (the DC_LUT write) is already a well-supported inference, so the cost is out of proportion to the gain.

⚠️ The config dump in a log is the FILE, not the effective command line

Nearly a wrong conclusion here. The dump printed at startup showed trace_gpu_stream = false after I had passed --trace_gpu_stream=true, which reads as "the flag was ignored". It is not evidence either way:

passed on the CLI shown in the dump actual behaviour
gamma run --log_mask=12 --log_level=3 log_mask = 0, log_level = 2 Kernel Debug logging demonstrably ON

The gamma run's flags plainly took effect — that run is where VdGetCurrentDisplayGamma was captured — while its dump showed the file's values. So the dump reflects the config file and cannot confirm or refute a command-line override.


2026-08-29 (later) — the disc is back, and the section below is withdrawn as CURRENT status

Kept for its history, not as a live claim. The container was replaced: PID 1 here started at 11:07:38 UTC, 25 minutes after commit b9aca6a wrote the section below at 10:42, and the replacement has the disc mounted.

check result
/proc/mounts /dev/sda2 /disc ext4 ro,relatime — a real bind mount
device /disc is device 2050; / is device 92
size 6.2 GB, 74 entries under dat/, default.xex = 3 497 984 B
ISO /iso/game.iso, 7 835 492 352 B
end to end sylpheed-cli screen list /disc/dat/GP_TITLE.pak → 12 builds, element/sprite counts matching the committed build map

⚠️ Two instruments would have said "no disc" either way, and both are still in place. This is the reusable lesson, and it is worth more than the resolved incident:

  • find / -xdev cannot see /disc. -xdev refuses to cross a filesystem boundary; /disc is on a different device from /. The withdrawn section's headline measurement — "no ISO, no default.xex, no GP_TITLE.pak anywhere" — is what that command returns whether or not the disc is mounted. It had no reach over the question it was used to answer.
  • sylph-doctor never checks $SYLPHEED_DISC. Its two disc lines are find /work -maxdepth 2 -iname '*.iso' and [ -d /work/sylph_extract/dat ] (lines 7982). With the disc at /disc it reports "no ISO under /work" and "no extracted disc — Reborn disc tests will SKIP" — as it does right now, against a working disc. "sylph-doctor agrees" was two instruments sharing one blind spot, not corroboration.

To check for the disc, ask the variable that names it: ls "$SYLPHEED_DISC/dat", or sylpheed-cli screen list "$SYLPHEED_DISC/dat/GP_TITLE.pak", which fails loudly and cheaply.

🔴 2026-08-29 — the disc is not in the decoder container at all (WITHDRAWN — see the section immediately above)

Status: diagnosed, root-caused in the launcher. This supersedes every "the emulator did not reach the title" entry above as the current reason the oracle is unavailable: there is no game to run.

The measurement

looked for result
find / -xdev -iname '*.iso' 0
find / -xdev -iname 'default.xex' 0
find / -xdev -iname 'GP_TITLE.pak' 0
$SYLPHEED_DISC empty
/work/sylph_extract does not exist
/exchange/files empty

sylph-doctor agrees and says so in its own words:

── project ──
  ✖ /work/xenia-canary not mounted
  ✖ /work/Syplheed-Reborn not mounted
  ! no ISO under /work — run-canary needs SYLPH_ISO
  ! no extracted disc — Reborn disc tests will SKIP

Everything else is healthy: xenia_canary is built and present, display :98 is up, screenshot works, Vulkan (llvmpipe) enumerates, cargo and the python stack are fine. The emulator has no disc to boot.

The cause — the volume migration, and a mount nobody replaced

Before 06676d3 the launcher bind-mounted the human's working tree:

-v "$PROJECT:$PROJECT"
-v "$PROJECT:/work"

The ISO and sylph_extract/ live in that tree, so the disc arrived incidentally with the repository mount, and run-canary's find "$PROJECT_DIR" -maxdepth 2 -iname '*.iso' found it.

06676d3 replaced that with the agent's own clone in a named volume —

-v "sylpheed-decoder-repo:/work"

— which is the right fix for the collision class it was written for, and it removed the disc along with the working tree. Nothing was added to replace it. The launcher still forwards

[ -n "${SYLPH_ISO:-}" ] && _out+=(-e "SYLPH_ISO=$SYLPH_ISO")

but that is an environment variable with no bind mount behind it — it names a host path that does not exist inside the container, so it cannot help.

The port container does not have this bug. docker/port/sylph-port mounts the disc explicitly:

_out+=(-v "$DISC:/disc:ro" -e "SYLPHEED_DISC=/disc")

So the one container that owns the disc and the oracle is the one container without them.

Reach of the negative

Whole-filesystem, single pass, -xdev per mount, three independent names (the ISO, the executable, a pak the corpus names constantly). The exchange volume is empty, so the disc is not arriving by share either. This is not "I looked in the usual place".

What it blocks — everything disc-side and everything dynamic

  • the oracle — no boot, no capture, no run-canary;
  • every sylpheed-cli invocation that names a pak — screen list, screen info, screen render, pak textures;
  • build-reborn test — the disc-gated tests self-skip, and per MISSION a green run then means almost nothing. (build-reborn is also pointing at /work/Syplheed-Reborn, a path the monorepo no longer has.)
  • static RE of the executable — the XEX is on the disc, so the whole PPC-disassembly route is shut too, not just the dynamic one.

What it does not block

The committed corpus. docs/re/captures/ is 99 MB of oracle frames and docs/re/data/ 2.5 MB of extracted tables, both in git — enough to re-measure against captures, which is what this iteration did instead.

🔵 For the human — the one-line fix

Add a disc mount to docker/decoder/sylph-decoder, the way sylph-port already has one:

[ -d "$DISC" ] && _out+=(-v "$DISC:/disc:ro" -e "SYLPHEED_DISC=/disc")
[ -f "$SYLPH_ISO" ] && _out+=(-v "$SYLPH_ISO:/disc.iso:ro" -e "SYLPH_ISO=/disc.iso")

Recorded rather than worked around, per do not improvise around a blocker — and not attempted, because the launcher runs on the host and this container cannot restart itself.

⚠️ sylph-doctor reports the missing ISO as ! (a warning) rather than . For the decoder that is not a warning: it is the difference between having an oracle and not having one.

A second, smaller consequence of the same migration — no git identity

git commit in a fresh decoder container fails with "Author identity unknown": nothing in the image, the entrypoint or sylph-decoder sets user.name / user.email, and the old bind mount used to bring the human's .git/config along with the tree.

Set locally, per iteration if the volume is recreated:

git config --local user.name  "sylph-decoder"
git config --local user.email "fabian@diekaulbachs.de"

⚠️ push-work's header warns at length against git config --local, because the credential helper it wrote there leaked a container-only path onto the host. That warning no longer applies to identity: /work is a private named volume now, not a shared bind mount, so nothing written to its .git/config can reach a host checkout. The credential helper is still applied per-invocation with -c, and should stay that way.