Sylpheed/docs/re/capture-harness-status.md

🔴 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:43–18: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 0–44 (the GTK menu bar)	100 %	210.5
y 45–719 (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_canary — the 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.