From 5fb4da4c43c5ed66ae7ca43f8d03e7224d1200fb Mon Sep 17 00:00:00 2001 From: Sylpheed RE agent Date: Mon, 24 Aug 2026 08:14:11 +0000 Subject: [PATCH] docs+tools: the call-rate probe's baseline already refutes the timeout reading v2 counts every KeWaitForSingleObject call per thread per second, tracks how many distinct objects it saw, and logs the last result. Its HEALTHY baseline is a result on its own: over a full 22-minute run the main thread cleared 500 calls/s in 224 separate windows, peaking at 1235 calls/s over up to THIRTEEN distinct objects, and the last result was X_STATUS_SUCCESS in all 314 windows. Not one timeout. So the game normally does hundreds of successful waits a second across many objects - exactly the blind spot v1 could not see, and the reason a timeout-streak counter reported the same single poller whether the game was frozen or healthy. Stated as a consequence rather than a triumph: 500/s is NOT self-selecting, since the main thread clears it constantly, so the freeze signal has to be a different shape - a thread far above 1235/s, a new thread, or a window whose result is not SUCCESS. That still needs a frozen sample; run 5 ended in GAME OVER at ~22 min without freezing. freeze_watch.sh now summarises the rate probe per thread when it captures. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01PMRJjbxLqZtsb5Vb7KunPE --- docs/re/mission-freeze-resume-spin.md | 33 +++++++++++++++++++++++++++ tools/re-capture/freeze_watch.sh | 11 ++++++++- 2 files changed, 43 insertions(+), 1 deletion(-) diff --git a/docs/re/mission-freeze-resume-spin.md b/docs/re/mission-freeze-resume-spin.md index 0b8a01f4..d9c0f906 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 faf527b4..b9202ee3 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