f2ff24d9f6
Last iteration left two candidates for why trace_gpu_stream produced no
file: the CLI flag not reaching the cvar, or BeginTracing failing
silently. Neither. Following the code instead of guessing:
BeginTracing only sets trace_state_ = kStreaming ("Streaming starts on
the next primary buffer execute"). The file is opened later, in
ExecutePrimaryBuffer, inside
#if XE_ENABLE_TRACE_WRITER_INSTRUMENTATION == 1
and trace_writer.h defines that as 0 under NDEBUG, 1 otherwise -- the
trace writer exists only in debug builds.
Confirmed against the binaries, with a control. The format string
"{:08X}_stream.xtr" lives only inside that guard:
build/bin/Linux/Release/xenia_canary 0 occurrences
build/bin/Linux/Debug/xenia_canary 1 occurrence
/sylph-home/re/canary-build/.../Release/... 0 <- what run-canary uses
The debug binary is the control: it proves the test finds the string when
it is present, so the release zero means something.
So trace_gpu_stream is a no-op in this container's emulator -- the cvar
parses, BeginTracing runs, and nothing can open a file. The kill -9 was
not the cause either, though it would have destroyed a trace had one
existed.
The route exists but is not cheap: a debug build with the writer compiled
in sits at build/bin/Linux/Debug/xenia_canary, 253 MB against Release's
18 MB, so a much slower boot plus a trace of every GPU packet on a disk
at 95%. Recorded as available rather than attempted -- what it would
confirm, the DC_LUT write, is already a well-supported inference, and the
cost is out of proportion to the gain.
METHOD: a cvar existing does not mean the feature is compiled in; and
test a compile-time gate against the binary, with a control.
365 lines
16 KiB
Markdown
365 lines
16 KiB
Markdown
# 🔴 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`](../../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](structures/ui-render-tone-curve.md)) and separating `8AX` from
|
||
`ptbase` ([8AX](structures/ui-8ax-fullres-background.md)) — 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
|
||
|
||
```cpp
|
||
#if XE_ENABLE_TRACE_WRITER_INSTRUMENTATION == 1
|
||
```
|
||
|
||
which `trace_writer.h` defines as:
|
||
|
||
```cpp
|
||
#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.
|