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

@@ -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)      

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.

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)) \
-      </dev/null >/tmp/fz-pilot.log 2>&1 & P=$!; echo "--- pilot flying"; break
+    SYLPH_HUNT=1 SYLPH_KEEPOUT=1400 nohup python3 "$SD/pilot.py" "$CFG" 3000 \
+      </dev/null >/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"

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)

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)