From 6900ebe5ca8667793e6cd1d5bfed48e14c215d88 Mon Sep 17 00:00:00 2001 From: Sylpheed RE agent Date: Tue, 25 Aug 2026 09:02:48 +0000 Subject: [PATCH] re: the frozen wait-object capture, and screen_id was never a freeze test Caught the freeze by waiting for the event (frozen.py + in_flight) instead of sleeping a guessed interval; freeze_waitobj.sh splits into boot/watch so the wait is not capped by one Bash call. Verified hard: a frame minutes later is byte-identical to the capture. Healthy vs frozen, same run: 20 -> 24 wait frames, XEvent 19 -> 23, XSemaphore 8 -> 7. The signature is per-thread -- 17 of 24 threads sit on the exact object they were on, four previously-running threads park, and T74/T75 move off a semaphore onto an event. So the freeze is not a whole-emulator stall. Also corrects the previous entry's test: screen_id reads 'flight' during a freeze by design, which is why frozen.py exists. Re-testing the saved frames says that run was genuinely healthy, but it was right by luck. heavy_read.py added to test whether the instrument provokes the freeze: I/O is free (371 MB in 0.1s, page cache), the cost is Python-level CPU. One data point -- 670s clean, then frozen 54s after the inducer started -- recorded as n=1, not as causation. --- docs/re/data/waitobj-s02.txt | 91 +++++++++++++++++---------- docs/re/mission-freeze-resume-spin.md | 74 ++++++++++++++++++++++ tools/re-capture/freeze_waitobj.sh | 56 +++++++++++++---- tools/re-capture/heavy_read.py | 85 +++++++++++++++++++++++++ tools/re-capture/waitobj_report.py | 22 +++++++ 5 files changed, 285 insertions(+), 43 deletions(-) create mode 100755 tools/re-capture/heavy_read.py diff --git a/docs/re/data/waitobj-s02.txt b/docs/re/data/waitobj-s02.txt index 8e2c752..809f450 100644 --- a/docs/re/data/waitobj-s02.txt +++ b/docs/re/data/waitobj-s02.txt @@ -1,4 +1,29 @@ -=== healthy: 23 wait frames === +=== healthy: 20 wait frames === + T106 Wait n=1 xe::kernel::XEvent + T104 Wait n=1 xe::kernel::XEvent + T97 Wait n=1 xe::kernel::XEvent + T96 Wait n=1 xe::kernel::XEvent + T80 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XSemaphore + T79 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XSemaphore + T78 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XSemaphore + T77 Wait n=1 xe::kernel::XEvent + T76 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XTimer + T75 Wait n=1 xe::kernel::XSemaphore + T74 Wait n=1 xe::kernel::XSemaphore + T71 Wait n=1 xe::kernel::XEvent + T66 Wait n=1 xe::kernel::XEvent + T65 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XSemaphore + T64 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XSemaphore + T63 Wait n=1 xe::kernel::XSemaphore + T62 Wait n=1 xe::kernel::XEvent + T61 Wait n=1 xe::kernel::XEvent + T50 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XEvent + T36 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XEvent + --- objects waited on: + xe::kernel::XEvent 19 + xe::kernel::XSemaphore 8 + xe::kernel::XTimer 1 +=== frozen: 24 wait frames === T106 Wait n=1 xe::kernel::XEvent T105 Wait n=1 xe::kernel::XEvent T104 Wait n=1 xe::kernel::XEvent @@ -9,11 +34,12 @@ T78 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XSemaphore T77 Wait n=1 xe::kernel::XEvent T76 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XTimer - T75 Wait n=1 xe::kernel::XSemaphore - T74 Wait n=1 xe::kernel::XSemaphore + T75 Wait n=1 xe::kernel::XEvent + T74 Wait n=1 xe::kernel::XEvent T71 Wait n=1 xe::kernel::XEvent T69 Wait n=1 xe::kernel::XSemaphore T68 Wait n=1 xe::kernel::XEvent + T67 Wait n=1 xe::kernel::XEvent T66 Wait n=1 xe::kernel::XEvent T65 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XSemaphore T64 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XSemaphore @@ -23,35 +49,36 @@ T50 Wait n=1 xe::kernel::XEvent T36 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XEvent --- objects waited on: - xe::kernel::XEvent 20 - xe::kernel::XSemaphore 9 - xe::kernel::XTimer 1 -=== frozen: 20 wait frames === - T106 Wait n=1 xe::kernel::XEvent - T104 Wait n=1 xe::kernel::XEvent - T97 Wait n=1 xe::kernel::XEvent - T96 Wait n=1 xe::kernel::XEvent - T80 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XSemaphore - T79 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XSemaphore - T78 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XSemaphore - T77 Wait n=1 xe::kernel::XEvent - T76 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XTimer - T75 Wait n=1 xe::kernel::XSemaphore - T74 Wait n=1 xe::kernel::XSemaphore - T71 Wait n=1 xe::kernel::XEvent - T66 Wait n=1 xe::kernel::XEvent - T65 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XSemaphore - T64 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XSemaphore - T63 Wait n=1 xe::kernel::XSemaphore - T62 Wait n=1 xe::kernel::XEvent - T61 Wait n=1 xe::kernel::XEvent - T50 Wait n=1 xe::kernel::XEvent - T36 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XEvent - --- objects waited on: - xe::kernel::XEvent 18 - xe::kernel::XSemaphore 8 + xe::kernel::XEvent 23 + xe::kernel::XSemaphore 7 xe::kernel::XTimer 1 === healthy -> frozen === - xe::kernel::XEvent 20 -> 18 CHANGED - xe::kernel::XSemaphore 9 -> 8 CHANGED + xe::kernel::XEvent 19 -> 23 CHANGED + xe::kernel::XSemaphore 8 -> 7 CHANGED xe::kernel::XTimer 1 -> 1 +=== per-thread healthy -> frozen === + thread healthy frozen + T106 Wait(XEvent) Wait(XEvent) + T105 -- Wait(XEvent) <-- CHANGED + T104 Wait(XEvent) Wait(XEvent) + T97 Wait(XEvent) Wait(XEvent) + T96 Wait(XEvent) Wait(XEvent) + T80 WaitMultiple(XEvent,XSemaphore) WaitMultiple(XEvent,XSemaphore) + T79 WaitMultiple(XEvent,XSemaphore) WaitMultiple(XEvent,XSemaphore) + T78 WaitMultiple(XEvent,XSemaphore) WaitMultiple(XEvent,XSemaphore) + T77 Wait(XEvent) Wait(XEvent) + T76 WaitMultiple(XEvent,XTimer) WaitMultiple(XEvent,XTimer) + T75 Wait(XSemaphore) Wait(XEvent) <-- CHANGED + T74 Wait(XSemaphore) Wait(XEvent) <-- CHANGED + T71 Wait(XEvent) Wait(XEvent) + T69 -- Wait(XSemaphore) <-- CHANGED + T68 -- Wait(XEvent) <-- CHANGED + T67 -- Wait(XEvent) <-- CHANGED + T66 Wait(XEvent) Wait(XEvent) + T65 WaitMultiple(XEvent,XSemaphore) WaitMultiple(XEvent,XSemaphore) + T64 WaitMultiple(XEvent,XSemaphore) WaitMultiple(XEvent,XSemaphore) + T63 Wait(XSemaphore) Wait(XSemaphore) + T62 Wait(XEvent) Wait(XEvent) + T61 Wait(XEvent) Wait(XEvent) + T50 WaitMultiple(XEvent,XEvent) Wait(XEvent) <-- CHANGED + T36 WaitMultiple(XEvent,XEvent) WaitMultiple(XEvent,XEvent) diff --git a/docs/re/mission-freeze-resume-spin.md b/docs/re/mission-freeze-resume-spin.md index 3bc3eaf..4ff5a01 100644 --- a/docs/re/mission-freeze-resume-spin.md +++ b/docs/re/mission-freeze-resume-spin.md @@ -968,3 +968,77 @@ and does not reproduce under gdb, not that it is wrong. **Next:** get a freeze under gdb at all — either drive the mission to the end condition that produces it instead of waiting on a clock, or measure guest time under gdb so the wait can be set in the units the freeze actually follows. + +## ✅ 2026-08-25 — THE FROZEN CAPTURE, and `screen_id` was the wrong test all along + +### First, a correction to the entry above + +The previous entry ruled out a freeze because `screen_id` read `flight`. **That +is not a freeze test**, and `frozen.py`'s own docstring says why: a Stage 02 run +froze with `screen_id` still saying `flight`, the emulator still burning 212 % +CPU, and 724 s of identical state. The right test is two **byte-identical** +frames while the flight HUD is up. + +Re-running that test on the saved frames says the conclusion was right anyway — +`fz-late1/2/3` and `fz-healthy/frozen` all come back `animating`, +`max_pixel_delta=254`. So the previous run really was healthy throughout. But it +was right by luck, and the "~270 s black-screen" it was planned around is not a +thing: the freeze does not black the screen and does not keep a clock. Measured +onsets in `BACKLOG.md` are **27/45/83/183/255 s**. + +### The capture + +`freeze_waitobj.sh` now splits into `boot` and `watch`, and `watch` waits for the +**event** (`frozen.py` + `in_flight`) instead of sleeping a guessed interval. +That got the capture on the first attempt. It is a hard stop, not a hitch: the +frame taken minutes after the capture is still `max_pixel_delta=0` against it. + +Both captures, same run, same mission (`data/waitobj-s02.txt`): + +| waited on | healthy | frozen | +|---|---|---| +| `XEvent` | 19 | **23** | +| `XSemaphore` | 8 | **7** | +| `XTimer` | 1 | 1 | +| wait frames | 20 | **24** | + +**The signature is in which threads moved, not in the totals:** + +| thread | healthy | frozen | +|---|---|---| +| T105, T67, T68 | *not waiting* | `Wait(XEvent)` | +| T69 | *not waiting* | `Wait(XSemaphore)` | +| T74, T75 | `Wait(XSemaphore)` | `Wait(XEvent)` | +| T50 | `WaitMultiple(XEvent,XEvent)` | `Wait(XEvent)` | + +Every other thread — 17 of them — is on exactly the object it was on before. So +the freeze is **not** the whole emulator stalling: the established waiters are +untouched, and what changes is that **four threads that were running are now +parked**, and **two threads move off a semaphore onto an event**. T74/T75 are the +pair to chase — they are the only ones that changed *what kind* of thing they +wait for. + +⚠️ "Not waiting" means not in a wait frame **at that instant**; those threads +existed and were running, they were not created by the freeze. + +## 🟡 One data point that our own instrument provokes it — not proof + +Worth stating because it changes what the freeze *is*. This run flew **~670 s +clean** with only the pilot attached. A heavy-CPU inducer (`heavy_read.py cpu`, +full-region Python word scan of guest memory) was then started at 08:59:54, and +the freeze landed at **09:00:48 — 54 s later**, inside the 27–255 s band the old +heavy-probe runs froze in. + +That is consistent with the tally already in `BACKLOG.md` (heavy probe froze at +27/45/83/183/255 s; cheap probe with the rescan removed was clean past 200 s on 3 +of 4 runs), and it is still **n=1 and not causal**. The obvious confounder is +simply elapsed mission time. + +**Refuted along the way:** the I/O was never the cost. A full uncapped walk of +every allocated extent moves **371 MB in 0.1 s** — all page cache — so "32 MB +reads" was the wrong description of what the old probes spent. The cost is CPU: +unpacking and comparing every word in Python takes **~4.2 s per pass**. + +**The experiment that would settle it:** alternate inducer-on and inducer-off +windows within one run, several runs, and compare freeze rate per unit of +*mission* time. Cheap now that `watch` is event-driven. diff --git a/tools/re-capture/freeze_waitobj.sh b/tools/re-capture/freeze_waitobj.sh index 3d81b2d..6ab218c 100755 --- a/tools/re-capture/freeze_waitobj.sh +++ b/tools/re-capture/freeze_waitobj.sh @@ -18,8 +18,20 @@ # is a vtable, so a value that does not resolve to a `vtable for ...` symbol is # discarded rather than interpreted. # -# Captures TWICE in one run so the comparison is within-run: once while the -# mission is healthy, once after the ~270s black-screen. +# Captures TWICE so the comparison is within-run: once while the mission is +# healthy, once frozen. The frozen one is reached by WAITING FOR THE EVENT, not +# by a clock -- measured onsets are 27/45/83/183/255s (median ~83), only about +# half of runs freeze at all, and the "~270s" figure this script used to sleep +# for was never a real bound. +# +# "Frozen" is frozen.py's test -- two byte-identical frames while the flight HUD +# is still up. It is NOT `screen_id == flight` being false: a frozen mission +# still classifies as `flight`, which is the whole reason frozen.py exists. +# +# Subcommands, because the boot and the wait do not fit one Bash call but the +# emulator survives BETWEEN calls in a turn: +# freeze_waitobj.sh boot [fly_s] boot, fly, capture `healthy`, leave running +# freeze_waitobj.sh watch [secs] poll for the freeze, capture `frozen` set -u export HOME=/sylph-home/re SDL_AUDIODRIVER=dummy DISPLAY=:98 export PYTHONPATH=/sylph-home/.local/lib/python3.12/site-packages @@ -76,20 +88,42 @@ PY echo "[$tag] captured" } +MODE="${1:-boot}" +FLY="${2:-}" + +if [ "$MODE" = watch ]; then + SECS="${FLY:-500}" + pgrep -x xenia_canary >/dev/null || { echo "NO EMULATOR"; exit 1; } + end=$((SECONDS + SECS)) + while [ $SECONDS -lt $end ]; do + pgrep -x xenia_canary >/dev/null || { echo "EMULATOR GONE at ${SECONDS}s"; exit 4; } + if python3 "$SD/frozen.py" 5 >/dev/null 2>&1; then + if python3 -c "import sys;sys.path.insert(0,'$SD');import frozen;sys.exit(0 if frozen.in_flight() else 1)"; then + echo "FROZEN IN FLIGHT at ${SECONDS}s of this watch" + capture frozen + python3 "$SD/waitobj_report.py" healthy frozen + echo "FREEZE WAITOBJ DONE"; exit 0 + fi + echo "frozen but NOT in flight (mission over) at ${SECONDS}s"; exit 5 + fi + sleepfor 12 + done + echo "NO FREEZE within ${SECS}s (still animating)"; exit 1 +fi + +# ---- boot mode ---- +FLY="${FLY:-150}" "$SD/launch_mission.sh" fly || { echo "BOOT FAILED"; exit 1; } CFG=/tmp/nav-fz.json for t in 1 2 3; do python3 "$SD/pad.py" set "rt=1" >/dev/null 2>&1 || true; sleepfor 3 python3 "$SD/pad.py" clear >/dev/null 2>&1 || true if python3 "$SD/entities2.py" self 0x130 "$CFG" >/dev/null 2>&1; then - SYLPH_HUNT=1 SYLPH_KEEPOUT=1400 nohup python3 "$SD/pilot.py" "$CFG" $((FLY1+FLY2+60)) \ - /tmp/fz-pilot.log 2>&1 & P=$!; echo "--- pilot flying"; break + SYLPH_HUNT=1 SYLPH_KEEPOUT=1400 nohup python3 "$SD/pilot.py" "$CFG" 3000 \ + /tmp/fz-pilot.log 2>&1 & echo "--- pilot flying"; break fi done -echo "--- flying ${FLY1}s to the healthy checkpoint" -sleepfor "$FLY1"; capture healthy -echo "--- flying ${FLY2}s more, past the ~270s black-screen" -sleepfor "$FLY2"; capture frozen -[ -n "${P:-}" ] && kill "$P" 2>/dev/null -python3 "$SD/waitobj_report.py" healthy frozen -echo "FREEZE WAITOBJ DONE" +echo "--- flying ${FLY}s to the healthy control capture" +sleepfor "$FLY"; capture healthy +python3 "$SD/waitobj_report.py" healthy +echo "BOOT PHASE DONE -- emulator left running; now: freeze_waitobj.sh watch" diff --git a/tools/re-capture/heavy_read.py b/tools/re-capture/heavy_read.py new file mode 100755 index 0000000..c425871 --- /dev/null +++ b/tools/re-capture/heavy_read.py @@ -0,0 +1,85 @@ +#!/usr/bin/env python3 +"""Reproduce the EXPENSIVE part of the old probes: full-region guest scans. + +Not a probe -- it computes nothing. It exists to test whether the in-mission +freeze is caused by the instrument rather than by the game. The tally in +BACKLOG.md is suggestive but only correlational: the heavy probe (32 MB at +startup + 32 MB every 90 s + two more for calibration) froze at 27/45/83/183/255 +s, while the cheap probe with the periodic rescan removed was clean past 200 s +on 3 of 4 runs. This makes the comparison causal by adding the reads BACK to a +run that is otherwise identical and demonstrably clean. + +MEASURED FIRST: the reads themselves are not the cost. A full uncapped walk of +every allocated extent moves 371 MB in 0.1 s -- it is all page cache. What the +old probes actually spent was CPU, unpacking and comparing every 4-byte word of +that region in Python to build the witness candidate list. So `cpu` mode does +that, and it is the mode that tests the hypothesis; `read` mode is kept only as +the control that shows I/O is free. + +Usage: heavy_read.py [secs] [period_s] [read|cpu] +""" +import os, sys, time + +def shm(): + d = [f for f in os.listdir('/dev/shm') if f.startswith('xenia_memory_')] + return '/dev/shm/' + d[0] if d else None + +def scan(path, cap=(1 << 62)): + """Walk EVERY allocated extent with SEEK_DATA. A 32 MB cap is page-cache cheap + (0.0 s measured), so the cap is off: the expensive thing the old probes did was + the FULL-region search, not a fixed-size read.""" + got = 0 + with open(path, 'rb', buffering=0) as f: + end = os.fstat(f.fileno()).st_size + off = 0 + while off < end and got < cap: + try: + off = os.lseek(f.fileno(), off, os.SEEK_DATA) + except OSError: + break + n = min(1 << 20, cap - got) + b = f.read(n) + if not b: + break + got += len(b); off += len(b) + return got + +def cpu_scan(path): + """The expensive thing: touch every word in Python, as the witness search did.""" + import struct + words = 0 + with open(path, 'rb', buffering=0) as f: + end = os.fstat(f.fileno()).st_size + off = 0 + while off < end: + try: + off = os.lseek(f.fileno(), off, os.SEEK_DATA) + except OSError: + break + b = f.read(1 << 20) + if not b: + break + n = len(b) // 4 + for v in struct.unpack('>%dI' % n, b[:n * 4]): + if 0 < v < 1000: + words += 1 + off += len(b) + return words + +secs = float(sys.argv[1]) if len(sys.argv) > 1 else 600 +period = float(sys.argv[2]) if len(sys.argv) > 2 else 20 +mode = sys.argv[3] if len(sys.argv) > 3 else 'read' +p = shm() +if not p: + print('no guest memory'); sys.exit(1) +print('heavy reads on %s every %gs for %gs' % (p, period, secs), flush=True) +t0 = time.time(); n = 0 +while time.time() - t0 < secs: + a = time.time(); n += 1 + if mode == 'cpu': + got = cpu_scan(p) + print(' cpu-scan %d: %d hits in %.1fs' % (n, got, time.time() - a), flush=True) + else: + got = scan(p) + print(' scan %d: %.1f MB in %.1fs' % (n, got / 1048576, time.time() - a), flush=True) + time.sleep(period) diff --git a/tools/re-capture/waitobj_report.py b/tools/re-capture/waitobj_report.py index a0b9304..c65f79a 100755 --- a/tools/re-capture/waitobj_report.py +++ b/tools/re-capture/waitobj_report.py @@ -70,6 +70,27 @@ def report(tag): print(' %-45s %d' % (k, c)) return tally +def per_thread(tag): + d = {} + for r in parse(tag): + live = [] + for s_ in r['slots']: + if s_ is None: break + live.append(s_.replace('xe::kernel::', '')) + d[int(r['th'])] = '%s(%s)' % (r['kind'], ','.join(live)) + return d + + +def diff_threads(a, b): + """The tally alone hides the signature -- WHICH thread moved is the result.""" + x, y = per_thread(a), per_thread(b) + print('=== per-thread %s -> %s ===' % (a, b)) + print(' %-6s %-32s %-32s' % ('thread', a, b)) + for t in sorted(set(x) | set(y), reverse=True): + fa, fb = x.get(t, '--'), y.get(t, '--') + print(' T%-5d %-32s %-32s %s' % (t, fa, fb, '' if fa == fb else ' <-- CHANGED')) + + if __name__ == '__main__': tallies = {t: report(t) for t in (sys.argv[1:] or ['healthy'])} if len(tallies) > 1: @@ -79,3 +100,4 @@ if __name__ == '__main__': for k in sorted(keys): x, y = tallies[a][k], tallies[b][k] print(' %-45s %3d -> %-3d %s' % (k, x, y, '' if x == y else ' CHANGED')) + diff_threads(a, b)