re: I cannot measure this emulator's clock -- and that answers the port's 2%

The port put two of my pages against each other: settle->plate 2.135 s and one
focus-ring revolution 2.177 s, both a declared 120 units during a static hold,
2% apart against a 6 ms run-to-run agreement. Fair challenge.

The resolution is that the question assumes a stable wall clock. Same interval,
same container, same day: 2.138, 2.132, and 2.549 s -- a 19% swing, caused by
adding --log_ui_draws=true. The 2% is a fifth of that. The two pages were never
in conflict about the game; they are three readings of one declared quantity
through a clock that moves. What settles the quantity is the disc.

Wall clock cannot separate the hypotheses, so I tried to measure frames instead.
Both instruments are recorded as failures rather than published as numbers:

  * Canary's own [UI-CAP] counter -- the one that produced the corpus's 28.5 fps
    -- costs a third of the frame rate. 300 frames in 16.567 s = 18.11 fps on a
    screen that gives ~28 without it. That reclassifies 28.5 as a load-dependent
    lower bound; it does not overturn it.
  * A distinct-frame counter over the spinning ring FAILED its decisive control:
    15.88 fps against the game's own 17.59 in the same window, 10% low, so the
    ring does not change on every presented frame. Its static control also read
    2.63 instead of ~0. Dead, not tuneable, per METHOD.md.

The rule that follows, and it applies to everything I hand the port: a measured
interval landing near a round number of declared units almost certainly IS that
number of units. Ship the units.

Also recovered here, because the same question needed it: the static PPC route.
Four tools open /work/xenia-rs/sylpheed.db and nothing in this repository builds
it -- no disassembler, no PPC decoder, and default.xex is encrypted (zero
plaintext "GamePart"). Xenia decompresses the image at load, so dump_image.py
reads it out of guest memory and validates it against the corpus's own landmarks:
the 29-entry GamePart id table at 0x820A1630 and the Xbox 360 D3D runtime
strings. String search and table dumps work again; instruction-level work does
not, and the present interval I wanted is an immediate, not a string.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_014voBspJ6kFncNErZJuZcLw
This commit is contained in:
sylph-decoder
2026-08-29 13:16:02 +00:00
parent 5b0a6e6666
commit e07c1de1b5
7 changed files with 9078 additions and 0 deletions

View File

@@ -0,0 +1,234 @@
"""Time the whole boot, and measure the PRESENTATION RATE per screen.
Two jobs, one oracle session, because they need each other.
1. **The boot timeline the port asked for.** Every screen-to-screen transition
from launch to the main menu, wall-clock, with the black holds marked. The
port paces its boot off `ScreenView.settle_time()` = a group's `rest.t`, and
`rest.t` is NOT when a screen settles (docs/re/REFUTED.md) — so every screen's
dwell is currently wrong by an unknown amount.
2. **Frames, not seconds.** Two pages of the corpus measure the same declared
120 keyframe units during a static hold and disagree by 2 %: settle→plate is
2.135 s (28.10 fps implied) and one focus-ring revolution is 2.177 s (27.56
implied). Either the presentation rate differed between those sessions, or one
interval is not 120 units. The two were taken on DIFFERENT SCREENS, so this
measures the rate on each — with the game's own frame counter, not a guess
about what changes between grabs.
`--log_ui_draws=true --ui_draw_capture_frames=N` makes Canary log
`[UI-CAP] capture armed` and then `[UI-CAP] done: D draws over F frames`. Timing
between those two lines in its own stdout gives frames/second directly, and it
re-arms (the log index is `{:02d}`), so one session can measure several screens.
⚠️ The instrument can perturb what it measures — writing a draw log costs the
emulator something. Control built in: the ring period is measured both DURING a
capture and OUTSIDE one, and a rate that is an artefact of logging would move it.
boot_timeline_probe.py --control
boot_timeline_probe.py --run SECONDS OUT.tsv CANARY_STDOUT [shots_dir]
"""
import os
import subprocess
import sys
import time
import numpy as np
from PIL import Image
SD = os.path.dirname(os.path.abspath(__file__))
sys.path.insert(0, SD)
import title_timing_probe as T # noqa: E402 (same crop, same ZNCC, same controls)
REPO = os.path.dirname(os.path.dirname(SD))
CAP = os.path.join(REPO, "docs", "re", "captures")
# The boot shows two splashes before the movie; both are committed captures.
T.REFS["splash_pub"] = "title-builds/live-splash-publisher.png"
T.REFS["splash_dev"] = "title-builds/live-splash-developer.png"
T._R.clear()
RATE = 8
CAPTURE_FRAMES = int(os.environ.get("UICAP_FRAMES", "300"))
def control():
"""Every control title_timing_probe has, plus the two splashes."""
T.CONTROLS.extend([
(os.path.join(CAP, "title-builds/live-splash-publisher.png"), "splash_pub"),
(os.path.join(CAP, "title-builds/live-splash-developer.png"), "splash_dev"),
])
return T.control()
def _tail(path, seen):
"""New lines appended to the emulator's stdout since the last call."""
try:
with open(path, "rb") as f:
f.seek(seen)
b = f.read()
return b.decode("utf-8", "replace"), seen + len(b)
except OSError:
return "", seen
def arm_capture(log_path, seen, timeout=90.0):
"""Press F10, then time the emulator's own armed->done lines.
Timed between the two LOG lines, not from the keypress: the arm latency is
then excluded rather than folded into the rate.
"""
win = subprocess.run(["xdotool", "search", "--name", "Xenia-canary"],
capture_output=True, text=True).stdout.split()
if not win:
return None, seen
w = win[-1]
subprocess.run(["xdotool", "windowactivate", w], capture_output=True)
subprocess.run(["xdotool", "key", "--window", w, "F10"], capture_output=True)
subprocess.run(["xdotool", "key", "F10"], capture_output=True)
t_armed = t_done = None
frames = draws = None
deadline = time.time() + timeout
while time.time() < deadline:
chunk, seen = _tail(log_path, seen)
for line in chunk.splitlines():
if "[UI-CAP] capture armed" in line and t_armed is None:
t_armed = time.time()
elif "[UI-CAP] done" in line and t_armed is not None:
t_done = time.time()
# "[UI-CAP] done: 1526 draws over 300 frames"
parts = line.replace(":", " ").split()
try:
draws = int(parts[parts.index("done") + 1])
frames = int(parts[parts.index("over") + 1])
except (ValueError, IndexError):
pass
if t_done:
break
time.sleep(0.02)
if not (t_armed and t_done and frames):
return None, seen
dt = t_done - t_armed
return {"frames": frames, "draws": draws, "seconds": dt, "fps": frames / dt}, seen
def run(limit, out_path, log_path, shots_dir):
os.makedirs(shots_dir, exist_ok=True)
n = T.W * T.H * 3
p = T.open_stream()
t0 = time.time()
seg = t0
frames = 0
seen = 0
ev = []
rates = {}
state = "boot"
last_label = None
last_gray = None
prev_mean = -1.0
fh = open(out_path, "w")
fh.write("#t\tglyph\tmean\tmotion\t" + "\t".join(T.REFS) + "\tlabel\n")
def mark(name, t=None):
t = time.time() - t0 if t is None else t
ev.append((name, t))
print(f"EVENT {name} t={t:.3f}", flush=True)
return t
while time.time() - t0 < limit and state != "done":
now = time.time()
# Restart only while still waiting; never across a measured interval.
if state == "boot" and now - seg > 30:
p.kill(); p = T.open_stream(); seg = now
fh.write(f"#restart\t{now - t0:.3f}\n")
buf = p.stdout.read(n)
if len(buf) < n:
p.kill(); p = T.open_stream(); seg = time.time(); continue
t = time.time() - t0
rgb = np.frombuffer(buf, np.uint8).reshape(T.H, T.W, 3)
g = T.gray_of(rgb)
gl = T.glyph(rgb)
sc = T.scores(g)
lb = T.label(sc)
surf = T.surface(g)
mn = float(surf.mean())
mo = float(np.abs(surf[::8, ::8] - last_gray).mean()) if last_gray is not None else -1.0
last_gray = surf[::8, ::8].copy()
frames += 1
fh.write(f"{t:.3f}\t{gl}\t{mn:.3f}\t{mo:.3f}\t"
+ "\t".join(f"{sc[k]:+.4f}" for k in T.REFS) + f"\t{lb}\n")
# Every label change and every entry/exit from pure black is a boot event.
blk = "black" if mn < 1.0 else lb
if blk != last_label:
mark(f"screen:{blk}", t)
last_label = blk
if blk in ("splash_pub", "splash_dev", "title_noplate", "menu"):
Image.fromarray(rgb).save(os.path.join(shots_dir, f"boot-{blk}.png"))
if state == "boot":
if lb in ("title_noplate", "title_plate") and 0 <= mo < 2.0 and gl >= 100:
mark("title_settled", t); state = "title"
elif state == "title":
if gl >= T.PLATE_GLYPH:
mark("plate", t); state = "plate_hold"; hold_from = t
elif state == "plate_hold":
if t - ev[-1][1] > 3.0:
fh.flush()
r, seen = arm_capture(log_path, seen)
rates["title"] = r
mark(f"rate_title={r and round(r['fps'], 3)}")
state = "press"
elif state == "press":
tp = T.tap("A") - t0
ev.append(("pressA", tp)); print(f"EVENT pressA t={tp:.3f}", flush=True)
state = "toMenu"
elif state == "toMenu":
if lb == "menu":
mark("menu", t); state = "menuSettle"; menu_at = t
elif state == "menuSettle":
if t - ev[-1][1] > 6.0:
fh.write(f"#ring_free_start\t{t:.3f}\n")
state = "ringFree"; ring_from = t
elif state == "ringFree":
# 12 s of ring with NOTHING else running -- the outside-capture control
if t - ring_from > 12.0:
fh.write(f"#ring_free_end\t{t:.3f}\n")
fh.flush()
r, seen = arm_capture(log_path, seen)
rates["menu"] = r
mark(f"rate_menu={r and round(r['fps'], 3)}")
fh.write(f"#ring_capture_end\t{time.time()-t0:.3f}\n")
state = "ringAfter"; after_from = time.time() - t0
elif state == "ringAfter":
if t - after_from > 12.0:
state = "done"
p.kill()
dt = time.time() - t0
fh.write(f"#summary\tframes={frames}\telapsed={dt:.1f}\tfps={frames/dt:.2f}\trequested={RATE}\n")
for k, r in rates.items():
if r:
fh.write(f"#rate\t{k}\tframes={r['frames']}\tdraws={r['draws']}"
f"\tseconds={r['seconds']:.3f}\tfps={r['fps']:.4f}\n")
else:
fh.write(f"#rate\t{k}\tFAILED\n")
for name, t in ev:
fh.write(f"#event\t{name}\t{t:.3f}\n")
fh.close()
print(f"\n{frames} frames in {dt:.1f}s = {frames/dt:.2f} fps (requested {RATE})")
for k, r in rates.items():
print(f" presentation rate on {k}: "
+ (f"{r['fps']:.4f} fps ({r['frames']} frames in {r['seconds']:.3f} s, "
f"{r['draws']} draws)" if r else "FAILED"))
return 0
if __name__ == "__main__":
if len(sys.argv) > 1 and sys.argv[1] == "--control":
sys.exit(control())
if len(sys.argv) > 4 and sys.argv[1] == "--run":
sys.exit(run(float(sys.argv[2]), sys.argv[3], sys.argv[4],
sys.argv[5] if len(sys.argv) > 5 else "/sylph-home/re/shots/boot-timeline"))
print(__doc__)
sys.exit(2)

81
tools/re-capture/dump_image.py Executable file
View File

@@ -0,0 +1,81 @@
#!/usr/bin/env python3
"""Dump the guest's DECOMPRESSED executable image out of live Xenia memory.
Why this exists: the static PPC route the corpus is built on ran against a
disassembly database at `/work/xenia-rs/sylpheed.db`, and that file is **not in
this container** — the same migration that took the Xenia storage root. Without
it, every finding that cites a `sub_82xxxxxx` is unre-checkable.
`/disc/default.xex` cannot substitute: it is encrypted and LZX-compressed. Its
header is intact (`XEX2`, original PE name `default.pe`) and everything after is
noise — `strings` finds **zero** occurrences of `GamePart` in it.
Xenia decompresses, decrypts and relocates the image at load, so a running guest
holds exactly the flat VA image the corpus calls the `.pe`. Dump it once and the
static route works offline, with no emulator and no disc.
Validated on write, and both checks are the corpus's own, not this tool's:
* `0x820A1630` must hold the **GamePart id table** — 29 pointers into `.rdata`
resolving to `GP_TITLE` … `GP_TEST`, with `GP_CHALLENGE` at id 26
(docs/re/challenge-mission-gate.md);
* the image must contain the Xbox 360 D3D runtime's own error strings, which a
mis-based or partial dump does not.
dump_image.py [OUT.pe] # with Canary running
"""
import os
import struct
import sys
SD = os.path.dirname(os.path.abspath(__file__))
sys.path.insert(0, SD)
import gmem # noqa: E402
LO, HI = 0x82000000, 0x82400000
BASE = LO
EXPECT = {0: "GP_TITLE", 3: "GP_LOAD", 11: "GP_READY_ROOM", 26: "GP_CHALLENGE", 28: "GP_TEST"}
def validate(buf):
def s_at(va):
o = va - BASE
e = buf.find(b"\0", o, o + 64)
return buf[o:e].decode("ascii", "replace")
bad = []
for i, want in EXPECT.items():
p = struct.unpack_from(">I", buf, 0x820A1630 - BASE + 4 * i)[0]
got = s_at(p) if LO <= p < HI else f"<ptr {p:#x} out of range>"
if got != want:
bad.append(f"GamePart id {i}: expected {want!r}, got {got!r}")
if buf.count(b"ERR[D3D]") < 1:
bad.append("no Xbox 360 D3D runtime strings — this is not the game image")
return bad
def main(out):
path = gmem.mem_path()
off = gmem.va_to_off(LO)
with open(path, "rb") as f:
f.seek(off)
buf = f.read(HI - LO)
if len(buf) < HI - LO:
print(f"short read: {len(buf)} of {HI - LO}", file=sys.stderr)
return 1
bad = validate(buf)
for b in bad:
print("FAIL:", b, file=sys.stderr)
if bad:
return 2
open(out, "wb").write(buf)
pages = sum(1 for i in range(0, len(buf), 4096) if any(buf[i:i + 4096]))
print(f"wrote {out} {len(buf)} bytes VA {LO:#x}..{HI:#x}")
print(f"validated: GamePart id table + D3D runtime strings; "
f"{pages}/{len(buf)//4096} non-empty 4K pages")
return 0
if __name__ == "__main__":
sys.exit(main(sys.argv[1] if len(sys.argv) > 1 else "/sylph-home/re/sylpheed-image.pe"))

View File

@@ -0,0 +1,181 @@
"""Measure Canary's PRESENTATION RATE without perturbing it, and time the boot.
Why this exists: two pages of the corpus measure the same declared 120 keyframe
units during a static hold and disagree by 2 % -- settle->plate 2.135 s (28.10
fps implied) and one focus-ring revolution 2.177 s (27.56 implied). The port
challenged it. Either the rate differed between the sessions, or one interval is
not 120 units. Both were WALL-CLOCK, so nothing in either can tell them apart.
The obvious instrument is Canary's own `[UI-CAP]` frame counter, and it is the
one the corpus used for "28.5 fps". 🔴 **It perturbs badly.** Measured here:
armed on the title with a concurrent 8 fps grab, 300 frames took 16.567 s =
**18.11 fps** against the ~28 the same screen gives without it. A frame counter
that costs a third of the frame rate cannot measure the frame rate.
So: count DISTINCT FRAMES in an oversampled crop of something that moves every
frame (the spinning focus ring). Sampling at 60 fps a source presenting at R,
the fraction of consecutive samples that differ is R/60.
Its controls, all in one session and all required to believe a number:
* a STATIC crop must read ~0 -- if it does not, the counter is seeing noise;
* two sampling rates (45 and 60) must agree -- if the estimate tracks the
sampler it is measuring the sampler;
* and the decisive one: while `[UI-CAP]` runs, this counter and the emulator's
own frame count must AGREE. Both are perturbed in that window, but agreeing
there is what licenses using this counter alone outside it.
present_rate_probe.py --run SECONDS OUT.json CANARY_STDOUT
"""
import json
import os
import subprocess
import sys
import time
import numpy as np
SD = os.path.dirname(os.path.abspath(__file__))
sys.path.insert(0, SD)
import title_timing_probe as T # noqa: E402
import boot_timeline_probe as B # noqa: E402
# The button column, from ring_period.py: game coords (480,130)-(570,530), and
# the game surface sits at +1,+45 in the root.
RX, RY, RW, RH = 481, 175, 90, 400
# A crop that must NOT move: the top-left of the menu's background.
SX, SY, SW, SH = 60, 120, 90, 120
def crop_stream(x, y, w, h, rate):
return subprocess.Popen(
["ffmpeg", "-loglevel", "error", "-f", "x11grab", "-draw_mouse", "0",
"-video_size", f"{w}x{h}", "-i", f"{T.DISPLAY}+{x},{y}", "-r", str(rate),
"-f", "rawvideo", "-pix_fmt", "rgb24", "-"],
stdout=subprocess.PIPE, bufsize=w * h * 3 * 4)
def count_distinct(x, y, w, h, rate, secs, thresh=0.02):
"""Sample a crop and count how many frames differ from their predecessor.
Returns (samples, distinct, seconds, implied_fps, frames_list, times_list).
`thresh` is a mean-abs-difference floor; a capture path with no noise makes
an identical frame differ by exactly 0, so this only has to reject dither.
"""
p = crop_stream(x, y, w, h, rate)
n = w * h * 3
t0 = time.time()
prev = None
samples = distinct = 0
prof, ts = [], []
while time.time() - t0 < secs:
b = p.stdout.read(n)
if len(b) < n:
break
a = np.frombuffer(b, np.uint8).reshape(h, w, 3)
g = (0.299 * a[..., 0] + 0.587 * a[..., 1] + 0.114 * a[..., 2]).astype(np.float32)
samples += 1
if prev is not None and float(np.abs(g - prev).mean()) > thresh:
distinct += 1
prev = g
prof.append(float(g.mean()))
ts.append(time.time() - t0)
p.kill()
dt = time.time() - t0
return dict(samples=samples, distinct=distinct, seconds=dt,
sample_fps=samples / dt, implied_fps=distinct / dt), prof, ts
def wait_for(pred, limit, rate=8):
"""Classify a full-frame stream until `pred(label, glyph, mean)` or timeout."""
p = T.open_stream()
n = T.W * T.H * 3
t0 = time.time()
trail = []
while time.time() - t0 < limit:
buf = p.stdout.read(n)
if len(buf) < n:
p.kill(); p = T.open_stream(); continue
rgb = np.frombuffer(buf, np.uint8).reshape(T.H, T.W, 3)
g = T.gray_of(rgb)
lb = T.label(T.scores(g))
gl = T.glyph(rgb)
mn = float(T.surface(g).mean())
trail.append((round(time.time() - t0, 3), lb, gl, round(mn, 2)))
if pred(lb, gl, mn):
p.kill()
return time.time() - t0, trail
p.kill()
return None, trail
def main(limit, out_path, log_path):
res = {}
t0 = time.time()
# --- reach the plate, then press A promptly: the title's idle window is short
hit, trail = wait_for(lambda lb, gl, mn: lb in ("title_plate", "title_noplate")
and gl >= T.PLATE_GLYPH, limit)
res["trail_to_plate"] = trail[-40:]
if hit is None:
res["error"] = "never reached the plate"
json.dump(res, open(out_path, "w"), indent=1)
return 1
res["plate_at"] = round(hit, 3)
print(f"plate at {hit:.1f}s -> A", flush=True)
T.tap("A")
hit, trail = wait_for(lambda lb, gl, mn: lb == "menu", 120)
if hit is None:
res["error"] = "never reached the menu"
res["trail_to_menu"] = trail[-40:]
json.dump(res, open(out_path, "w"), indent=1)
return 1
print(f"menu at +{hit:.1f}s; settling", flush=True)
time.sleep(8)
# --- CONTROL 1: a crop that must not move
st, _, _ = count_distinct(SX, SY, SW, SH, 60, 6)
res["control_static"] = st
print(f"static control: {st['distinct']}/{st['samples']} distinct "
f"({st['implied_fps']:.2f} implied)", flush=True)
# --- CONTROL 2: the same ring at two sampling rates
for r in (45, 60):
d, prof, ts = count_distinct(RX, RY, RW, RH, r, 12)
res[f"ring_free_{r}"] = d
res[f"ring_profile_{r}"] = [round(v, 4) for v in prof]
res[f"ring_times_{r}"] = [round(v, 4) for v in ts]
print(f"ring @{r}fps: {d['distinct']}/{d['samples']} -> "
f"{d['implied_fps']:.2f} fps (sampled {d['sample_fps']:.1f})", flush=True)
# --- CONTROL 3 (the decisive one): agree with the game's own counter
seen = os.path.getsize(log_path) if os.path.exists(log_path) else 0
import threading
box = {}
def _arm():
box["uicap"], box["seen"] = B.arm_capture(log_path, seen, timeout=120)
th = threading.Thread(target=_arm)
th.start()
d, prof, ts = count_distinct(RX, RY, RW, RH, 60, 30)
th.join(timeout=60)
res["ring_during_capture"] = d
res["uicap"] = box.get("uicap")
print(f"during UI-CAP: distinct-frame {d['implied_fps']:.2f} fps; "
f"UI-CAP {box.get('uicap')}", flush=True)
# --- and back to unperturbed
d, prof, ts = count_distinct(RX, RY, RW, RH, 60, 12)
res["ring_after"] = d
res["ring_profile_after"] = [round(v, 4) for v in prof]
res["ring_times_after"] = [round(v, 4) for v in ts]
print(f"after: {d['implied_fps']:.2f} fps", flush=True)
res["elapsed"] = round(time.time() - t0, 2)
json.dump(res, open(out_path, "w"), indent=1)
return 0
if __name__ == "__main__":
if len(sys.argv) > 4 and sys.argv[1] == "--run":
sys.exit(main(float(sys.argv[2]), sys.argv[3], sys.argv[4]))
print(__doc__)
sys.exit(2)