diff --git a/docs/re/mission-freeze-resume-spin.md b/docs/re/mission-freeze-resume-spin.md index 0b8a01f..d9c0f90 100644 --- a/docs/re/mission-freeze-resume-spin.md +++ b/docs/re/mission-freeze-resume-spin.md @@ -435,3 +435,36 @@ of object or result**, and logs a thread whose rate is absurd along with the object and the return value. That is a small edit to the same hook plus another build — and, as ever, another run of the freeze lottery, which this time paid out on the first attempt. + +## ✅ 2026-08-24 — the call-rate probe, and what its baseline already proves + +[`log_stuck_waits` v2](https://example.invalid) (canary +`auto/re-wait-timeout-probe` `597740046`) counts **every** call to +`KeWaitForSingleObject` per thread in a one-second window, records how many +**distinct objects** it saw, and logs the last object and the last **result** when +the rate passes 500/s. That covers both blind spots the v1 streak counter left. + +**The healthy-run baseline is itself a result.** Over a full ~22-minute Stage 02 +run that ended in GAME OVER rather than a freeze: + +| thread | windows over 500/s | peak | distinct objects | +|---|---|---|---| +| `F8000008` (main) | 224 | **1 235 calls/s** | up to **13** | +| `F8000234` | 47 | 919 | up to 10 | +| `F800025C` | 41 | 819 | up to 7 | +| `F8000204`, `F8000270` | 1 each | 562 / 730 | 2 / 1 | + +and the last result was `00000000` — **`X_STATUS_SUCCESS`** — in **all 314** +windows. Not one timeout. + +So the game's normal mode is exactly what v1 could not see: **hundreds of waits a +second, over up to thirteen different objects, all succeeding.** That confirms +blind spot (b) directly and explains why a timeout-streak counter reported the +same single poller during a freeze as during healthy play — it was measuring a +phenomenon the game barely exhibits. + +🟡 **Consequence for the instrument:** 500/s is *not* self-selecting; the main +thread clears it 224 times in a normal run. The freeze signal has to be a +**different** shape — a thread far above 1 235/s, or a new thread, or a window +whose result is *not* SUCCESS. That comparison needs a frozen sample, which run 5 +did not provide (GAME OVER at ~22 min). diff --git a/tools/re-capture/freeze_watch.sh b/tools/re-capture/freeze_watch.sh index faf527b..b9202ee 100755 --- a/tools/re-capture/freeze_watch.sh +++ b/tools/re-capture/freeze_watch.sh @@ -35,8 +35,17 @@ while [ $SECONDS -lt $DEADLINE ]; do 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 probe lines ===" + 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