From a9526749dc3f14b396a2f9b372c959ffd94ee88f Mon Sep 17 00:00:00 2001 From: Sylpheed RE agent Date: Tue, 25 Aug 2026 08:34:46 +0000 Subject: [PATCH] re: WaitMultiple read confirmed on a live capture; XTimer is a third type 23 wait frames, 30 objects, nothing unresolved -- the second deref turns every former miss into a resolved object, as predicted. XEvent 20 / XSemaphore 9 / XTimer 1; every WaitMultiple thread waits on a pair, and 78/79/80 and 64/65 are worker groups sharing a handle. %ebp does not survive as the count -- WaitMultiple reuses it at 8fc158 -- so the array is bounded by reading until an entry stops resolving instead. The frozen capture is still not taken: screen_id reads 'flight' at the second capture and out to ~470s, so the mission never black-screened. The diff in the data file is two healthy captures and is recorded as such. --- docs/re/data/waitobj-s02.txt | 57 +++++++++++++++++++++++++++ docs/re/mission-freeze-resume-spin.md | 55 ++++++++++++++++++++++++++ tools/re-capture/waitobj_report.py | 21 ++++++---- 3 files changed, 126 insertions(+), 7 deletions(-) create mode 100644 docs/re/data/waitobj-s02.txt diff --git a/docs/re/data/waitobj-s02.txt b/docs/re/data/waitobj-s02.txt new file mode 100644 index 0000000..8e2c752 --- /dev/null +++ b/docs/re/data/waitobj-s02.txt @@ -0,0 +1,57 @@ +=== healthy: 23 wait frames === + T106 Wait n=1 xe::kernel::XEvent + T105 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 + T69 Wait n=1 xe::kernel::XSemaphore + T68 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 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::XTimer 1 +=== healthy -> frozen === + xe::kernel::XEvent 20 -> 18 CHANGED + xe::kernel::XSemaphore 9 -> 8 CHANGED + xe::kernel::XTimer 1 -> 1 diff --git a/docs/re/mission-freeze-resume-spin.md b/docs/re/mission-freeze-resume-spin.md index 7a5c526..3bc3eaf 100644 --- a/docs/re/mission-freeze-resume-spin.md +++ b/docs/re/mission-freeze-resume-spin.md @@ -913,3 +913,58 @@ only 10/18 reliable. The unwind was never the problem; the parser was. `freeze_waitobj.sh` now parses the function name and frame index out of the backtrace instead of assuming frame 3, and applies the matching rule to each. + +## ✅ 2026-08-25 — the WaitMultiple read confirmed, and a third object type + +Ran it. The prediction from the section above holds: applying the second deref +to `WaitMultiple` frames turns every one of the former "misses" into a resolved +object. Full table in `data/waitobj-s02.txt`; **23 wait frames, 30 objects, and +nothing unresolved.** + +| waited on | count | +|---|---| +| `xe::kernel::XEvent` | 20 | +| `xe::kernel::XSemaphore` | 9 | +| `xe::kernel::XTimer` | 1 | + +`XTimer` is new — it never appeared before because the only thread waiting on +one (T76) is a `WaitMultiple` thread, and those were exactly the frames the old +parser read wrongly. + +Every `WaitMultiple` thread waits on a **pair**, never more: six on +(`XEvent`, `XSemaphore`), one on (`XEvent`, `XTimer`), one on +(`XEvent`, `XEvent`). Threads 78/79/80 share one `objects` array contents and +64/65 another, so these are worker groups on a common handle. + +### 🟡 `%ebp` is not a usable count + +The plan was to bound the array with the count in `%ebp`. It reads `0x0` on +every frame, and the disassembly says why: `WaitMultiple` **reuses `ebp`** at +`8fc158` (`mov 0x10(%rax),%ebp`) once it is past the prologue, so the count is +gone by the time these captures interrupt. The array is bounded instead by +reading until an entry stops resolving — past the last real object the words are +`0x0` and gdb reports `Cannot access memory at address 0x0`. Same self-validating +rule as everywhere else here, and it needs no register. + +## 🔴 The frozen capture STILL has not been taken — the freeze did not happen + +The second capture is labelled `frozen` and is not. `screen_id` reads **`flight`** +at the capture (`green=0.0140 mean=(30.3,31.4,36.4)`), 367 s into the mission, +and three follow-up screenshots out to **~470 s of flight** also read `flight` +with a drifting frame mean, so the picture was still moving. The mission simply +did not black-screen this run. + +So the `healthy -> frozen` diff in the data file is **two healthy captures**, and +its `20 -> 18` / `9 -> 8` is three threads (T105, T68, T69) having exited — normal +churn, not a freeze signature. Recorded as-is rather than presented as a result. + +**This also puts a question against the "black-screens at ~4.5 min" bound** used +to plan these runs. One confound is named and not ruled out: this run is under +gdb, which slows the emulator (boot to title took 207 s), so 470 s of wall-clock +may be well short of 270 s of *guest* time. Until that is measured the honest +statement is that the ~270 s figure is a wall-clock observation from ungated runs +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. diff --git a/tools/re-capture/waitobj_report.py b/tools/re-capture/waitobj_report.py index d244e99..a0b9304 100755 --- a/tools/re-capture/waitobj_report.py +++ b/tools/re-capture/waitobj_report.py @@ -6,7 +6,12 @@ freeze_waitobj.sh), so they are parsed separately: Wait rbx = this -> [rbx] is the vtable WaitMultiple rbx = XObject** -> [[rbx+8i]] is object i's vtable - ebp = count -> entries past the count are garbage + +%ebp holds the count only at the prologue: WaitMultiple reuses it at 8fc158 +(`mov 0x10(%rax),%ebp`), and it reads 0 at the point these captures interrupt. +So the array length is NOT taken from a register -- entries are read until one +stops resolving, which is the same self-validating rule used for everything +else here. Every reading is validated the same way: gdb's `info symbol` must resolve it to a `vtable for ...` symbol. A polymorphic object's first word always is one, so @@ -50,14 +55,16 @@ def report(tag): if not recs: return collections.Counter() tally = collections.Counter() for r in recs: - n = r['count'] if r['kind'] == 'WaitMultiple' and r['count'] else len(r['slots']) - n = min(n, len(r['slots'])) - live = r['slots'][:n] + # take entries up to the first one that did not resolve + live = [] + for s_ in r['slots']: + if s_ is None: break + live.append(s_) for s in live: tally[s if s else ''] += 1 - print(' T%-4s %-13s count=%-4s %s' % ( - r['th'], r['kind'], r['count'] if r['count'] is not None else '-', - ', '.join(s or '?' for s in live) or '(nothing readable)')) + print(' T%-4s %-13s n=%d %s' % ( + r['th'], r['kind'], len(live), + ', '.join(live) or '(nothing readable)')) print(' --- objects waited on:') for k, c in tally.most_common(): print(' %-45s %d' % (k, c))