#!/usr/bin/env bash # Wait for the in-mission freeze and capture the evidence at the moment it lands. # # Written because catching it by hand costs a tool call every 25 s and the freeze # takes anywhere from ten seconds to never: roughly half the runs that reach # flight freeze, and the other half do not # (docs/re/mission-freeze-resume-spin.md). # # "Frozen" is two screenshots byte-identical (frozen.py); it is checked ONLY # while the flight HUD is still on screen, because the GAME OVER screen animates # and a run that ended there is not a freeze. # # On detection it snapshots what the stuck-wait probe has said, so the comparison # against the healthy-run baseline (one thread polling one Event) is made from # the same instant rather than reconstructed later. set -u export HOME=/sylph-home/re DISP="${DISPLAY:-:98}" SD="$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd)" LOG="${1:-/sylph-home/re/shots/probe-canary.stdout}" OUT="${2:-/sylph-home/re/logs/freeze-evidence.txt}" DEADLINE=$(( SECONDS + ${3:-1800} )) : > "$OUT" # Sample memory every poll, so a run that DIES has a contemporaneous reading # instead of a post-mortem guess. Two runs were SIGKILLed from outside with the # cgroup's oom_kill counter reading 0 both times, and by the time anything was # read the pressure (if that is what it was) had passed. mem_line() { local avail cur avail=$(awk '/MemAvailable/{print int($2/1024)}' /proc/meminfo) cur=$(( $(cat /sys/fs/cgroup/memory.current 2>/dev/null || echo 0) / 1048576 )) local oom oom=$(awk '/^oom_kill /{print $2}' /sys/fs/cgroup/memory.events 2>/dev/null) echo "t=${SECONDS}s host_avail=${avail}MiB cgroup=${cur}MiB oom_kill=${oom}" } while [ $SECONDS -lt $DEADLINE ]; do mem_line >> "${OUT%.txt}-mem.log" if ! pgrep -x xenia_canary >/dev/null; then { echo "EMULATOR GONE at ${SECONDS}s"; echo "last memory samples:"; tail -5 "${OUT%.txt}-mem.log"; } | tee -a "$OUT"; exit 4 fi if python3 "$SD/frozen.py" 5 >/dev/null; 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" echo echo "=== stuck-wait probe: (thread, object) pairs ===" grep -oE 'thread [0-9A-F]+ has timed out [0-9]+ times in a row on object [0-9A-F]+ \(type [0-9]+\)' "$LOG" \ | sed -E 's/has timed out [0-9]+ times in a row //' | sort | uniq -c | sort -rn echo echo "=== last 12 stuck-wait lines ===" grep 'wait-probe' "$LOG" | tail -12 echo echo "=== call-rate probe: per-thread rates in the last 20 windows ===" grep 'wait-rate' "$LOG" | tail -20 \ | sed -E 's/.*thread ([0-9A-F]+) called KeWaitForSingleObject ([0-9]+) times in ([0-9]+) ms over ([0-9]+) distinct.*last result ([0-9A-F]+)/thread \1 \2 calls\/\3ms \4 objects result \5/' echo echo "=== call-rate: highest single window per thread, whole run ===" grep 'wait-rate' "$LOG" \ | sed -E 's/.*thread ([0-9A-F]+) called KeWaitForSingleObject ([0-9]+) times.*/\1 \2/' \ | sort -k1,1 -k2,2nr | awk '!seen[$1]++ {print " thread " $1 " peak " $2 " calls/window"}' } | tee -a "$OUT" exit 0 fi echo "frozen but NOT in flight (mission over) at ${SECONDS}s" | tee -a "$OUT" exit 5 fi sleep 20 done echo "NO FREEZE within ${3:-1800}s" | tee -a "$OUT"; exit 1