diff --git a/docs/re/mission-freeze-resume-spin.md b/docs/re/mission-freeze-resume-spin.md index 7ccdcfd..7a5c526 100644 --- a/docs/re/mission-freeze-resume-spin.md +++ b/docs/re/mission-freeze-resume-spin.md @@ -866,3 +866,50 @@ the preceding gdb session — the gdb wrapper leaves a differently-parented proc tree and the usual cleanup did not catch it. **So the map classification and the multi-word object dump are still unrun**, and the frozen-state capture still has not been taken. + +## ✅ 2026-08-25 — WITHDRAWN: the 8 "unrestorable rbx" readings are a second function + +The entry above is wrong where it matters, and the disassembly says so plainly. +`rbx` was restored perfectly for all 18 threads. **Eight of them are not in +`XObject::Wait` at all — they are in `XObject::WaitMultiple`**, and `%rbx` does +not mean the same thing in the two functions. The grep that produced the table +matched `XObject::Wait` as a *substring*, so `WaitMultiple` frames were pooled in +with `Wait` frames and read with the wrong rule. + +Reading the two prologues settles it (baseline `c1b57f93b`, no run needed): + +``` +8fbc90 XObject::Wait(this, ...) 8fbfc0 XObject::WaitMultiple(count, objects, ...) + push %rbp/%r15/%r14/%rbx/%rax push %rbp/%r15/%r14/%r13/%r12/%rbx + mov %r8,%r15 sub $0x218,%rsp + mov %ecx,%ebp mov %rsi,%rbx <-- rbx = XObject** objects + mov %rdi,%rbx <-- rbx = this mov %edi,%ebp <-- ebp = count +``` + +and the loop just below `WaitMultiple`'s prologue confirms what `rbx` points at +by using it: + +``` +8fbff0: mov (%rbx,%r15,8),%rdi ; rdi = objects[i] +8fbff4: mov (%rdi),%rax ; rax = objects[i]->vtable +8fbff7: call *0x20(%rax) ; a virtual call on it +``` + +So for a `WaitMultiple` frame `[rbx]` is `objects[0]` — **an `XObject*`, not a +vtable** — which is exactly the shape of the eight "misses": pointers into the +mmap region where the kernel objects live. They needed **two** derefs, not one. +The correct read is `[[rbx + 8i]]` for `i < ebp`. + +Predicted values from the healthy capture, to be checked against the next run: +`objects[0]` was `0x7ffd08bcdeb0` for threads 79 and 80 and `0x7ffcfc0911f0` +for thread 78 — two threads sharing one object is itself consistent with a +group of workers waiting on the same handle. + +**What survives from the previous entry:** the two confirmed object types +(`XEvent` ×8, `XSemaphore` ×2) and the self-validating read — a value counts only +if it resolves to a `vtable for …` symbol. **What is withdrawn:** "`rbx` could +not be restored for eight threads", and with it the claim that the reading is +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. diff --git a/tools/re-capture/freeze_waitobj.sh b/tools/re-capture/freeze_waitobj.sh index 90652f8..3d81b2d 100755 --- a/tools/re-capture/freeze_waitobj.sh +++ b/tools/re-capture/freeze_waitobj.sh @@ -1,69 +1,95 @@ #!/usr/bin/env bash -# Read WHICH object the frozen guest threads are waiting on. +# Read WHICH object the guest threads are waiting on, HEALTHY vs FROZEN. # -# Groundwork (mission-freeze-resume-spin.md): XObject::Wait keeps `this` in %rbx, -# and .eh_frame lets gdb restore callee-saved registers during the unwind, so no -# DWARF and no rebuild are needed -- select the Wait frame, read rbx, then read -# the vtable pointer at [rbx] and resolve it in the symtab. +# Groundwork (mission-freeze-resume-spin.md): the waiting functions keep their +# interesting argument in %rbx, and .eh_frame lets gdb restore callee-saved +# registers during the unwind, so no DWARF and no rebuild are needed. +# +# TWO functions end up in these backtraces and %rbx does NOT mean the same +# thing in each -- reading them as one set is what produced the earlier +# "8 of 18 threads have an unreadable rbx" claim (waitobj-two-functions.md): +# +# XObject::Wait(this, ...) 8fbc90: mov %rdi,%rbx -> rbx = this +# XObject::WaitMultiple(count, objects, .) 8fbfc0: mov %rsi,%rbx -> rbx = objects[] +# mov %edi,%ebp -> ebp = count +# +# So a Wait frame is read with one deref and a WaitMultiple frame with two, and +# every reading is checked by `info symbol`: a polymorphic object's first word +# 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. set -u export HOME=/sylph-home/re SDL_AUDIODRIVER=dummy DISPLAY=:98 export PYTHONPATH=/sylph-home/.local/lib/python3.12/site-packages export XENIA_BIN=/sylph-home/re/bin/gdb-wrap/xenia_canary SD="$(cd "$(dirname "$0")" && pwd)" -FLY="${1:-240}" +FLY1="${1:-200}" # healthy checkpoint +FLY2="${2:-140}" # extra seconds -> lands past the ~270s black-screen CMD=/tmp/gdb-cmd; OUT=/tmp/gdb-out.log + +sleepfor(){ python3 -c "import time,sys; time.sleep(float(sys.argv[1]))" "$1"; } + +capture(){ # capture + local tag="$1" pid before + pid=$(pgrep -x gdb | head -1) + [ -n "$pid" ] || { echo "[$tag] no gdb"; return 2; } + before=$(wc -c < "$OUT") + screenshot "/tmp/fz-$tag.png" >/dev/null 2>&1 + echo "[$tag] screen: $(python3 "$SD/screen_id.py" "/tmp/fz-$tag.png" 2>/dev/null | head -1)" + kill -INT "$pid"; sleepfor 3 + { echo 'echo === BT '"$tag"' ===\n'; echo 'thread apply all bt 6' + echo 'echo === END BT ===\n'; } >> "$CMD" + sleepfor 10 + tail -c +$((before + 1)) "$OUT" > "/tmp/fz-bt-$tag.txt" + # emit per-thread reads, with the frame index and the function taken from the + # backtrace itself rather than assumed + TAG="$tag" python3 - "/tmp/fz-bt-$tag.txt" <<'PY' >> "$CMD" +import os,re,sys +txt=open(sys.argv[1],errors='replace').read(); tag=os.environ['TAG'] +cur=None; n=0 +for line in txt.splitlines(): + m=re.match(r'Thread (\d+) ',line) + if m: cur=m.group(1); continue + if not cur: continue + f=re.search(r'#(\d+)\s+0x[0-9a-f]+ in xe::kernel::XObject::(WaitMultiple|Wait)\(',line) + if not f: continue + fr,kind=f.group(1),f.group(2) + print(r'echo === %s T%s %s f%s ===\n'%(tag,cur,kind,fr)) + print('thread %s'%cur); print('frame %s'%fr) + if kind=='Wait': + print('info registers rbx') + print('info symbol *(unsigned long*)$rbx') + else: + print('info registers rbx rbp') + for i in range(4): + print('info symbol *(unsigned long*)*(unsigned long*)($rbx+%d)'%(8*i)) + cur=None; n+=1 +print(r'echo === END OBJ %s ===\n'%tag); print('continue') +sys.stderr.write('[%s] %d wait frames\n'%(tag,n)) +PY + sleepfor 14 + tail -c +$((before + 1)) "$OUT" > "/tmp/fz-obj-$tag.txt" + local epid; epid=$(pgrep -x xenia_canary | head -1) + [ -n "$epid" ] && cp "/proc/$epid/maps" "/tmp/fz-maps-$tag.txt" 2>/dev/null + echo "[$tag] captured" +} + "$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; sleep 3 + 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" "$FLY" \ + SYLPH_HUNT=1 SYLPH_KEEPOUT=1400 nohup python3 "$SD/pilot.py" "$CFG" $((FLY1+FLY2+60)) \ /tmp/fz-pilot.log 2>&1 & P=$!; echo "--- pilot flying"; break fi done -echo "--- flying ${FLY}s (boot under gdb costs ~300s, so this must leave room" -echo "--- for the gdb step inside one call: timeout kills the whole group)" -python3 -c "import time,sys; time.sleep(int(sys.argv[1]))" "$FLY" +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 -pid=$(pgrep -x gdb | head -1) -[ -n "$pid" ] || { echo "no gdb"; exit 2; } -before=$(wc -c < "$OUT") -kill -INT "$pid"; sleep 3 -{ - echo 'echo === HOT THREAD WAIT OBJECTS ===\n' - echo 'thread apply all bt 6' - echo 'echo === END BT ===\n' -} >> "$CMD" -sleep 10 -tail -c +$((before + 1)) "$OUT" > /tmp/fz-bt.txt -# find threads whose frame 3 is XObject::Wait, then read rbx there -python3 - <<'PY' >> "$CMD" -import re -txt=open('/tmp/fz-bt.txt').read() -cur=None -for line in txt.splitlines(): - m=re.match(r'Thread (\d+) ', line) - if m: cur=m.group(1) - if cur and 'XObject::Wait' in line: - print(r'echo === T%s ===\n' % cur) - print('thread %s' % cur) - print('frame 3') - print('info registers rbx') - print('x/8gx $rbx') # vtable, KernelState*, fields -- or saved regs - cur=None -print(r'echo === END OBJ ===\n') -print('continue') -PY -sleep 12 -# Is $rbx in a STACK mapping or an anonymous/heap one? 0x7ffc.. is the shared -# mmap region on x86-64: thread stacks live there, but so do large allocations, -# so the address range alone cannot tell them apart. /proc//maps can. -epid=$(pgrep -x xenia_canary | head -1) -[ -n "$epid" ] && cp "/proc/$epid/maps" /tmp/fz-maps.txt 2>/dev/null && \ - echo "--- saved /proc/$epid/maps ($(wc -l < /tmp/fz-maps.txt) mappings)" -screenshot /tmp/fz-screen.png >/dev/null 2>&1 -echo "--- screen at capture time:" -python3 "$SD/screen_id.py" /tmp/fz-screen.png 2>/dev/null | head -2 -tail -c +$((before + 1)) "$OUT" | sed -n '/HOT THREAD WAIT OBJECTS/,$p' | grep -vE "^\s*$" | tail -70 +python3 "$SD/waitobj_report.py" healthy frozen echo "FREEZE WAITOBJ DONE" diff --git a/tools/re-capture/waitobj_report.py b/tools/re-capture/waitobj_report.py new file mode 100755 index 0000000..d244e99 --- /dev/null +++ b/tools/re-capture/waitobj_report.py @@ -0,0 +1,74 @@ +#!/usr/bin/env python3 +"""Turn the gdb wait-object dumps into a table, discarding what does not check out. + +The two waiting functions do not put the same thing in %rbx (see +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 + +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 +anything else is a misread and is COUNTED but not interpreted. That check is +what the reading is worth -- without it a stale register looks like a result. +""" +import re, sys, collections + +VT = re.compile(r'vtable for ([\w:]+) \+ (\d+)') +HDR = re.compile(r'=== (\w+) T(\d+) (Wait|WaitMultiple) f(\d+) ===') + +def parse(tag): + """-> list of (thread, kind, count, [vtable-or-None per slot])""" + try: + txt = open('/tmp/fz-obj-%s.txt' % tag, errors='replace').read() + except FileNotFoundError: + return [] + out, cur = [], None + for line in txt.splitlines(): + line = line.replace('(gdb) ', '') + h = HDR.search(line) + if h: + if cur: out.append(cur) + cur = dict(th=h.group(2), kind=h.group(3), count=None, slots=[], bad=0) + continue + if not cur: continue + m = re.search(r'rbp\s+0x[0-9a-f]+\s+(\d+)', line) + if m: cur['count'] = int(m.group(1)) & 0xffffffff + if 'info symbol' in line or line.startswith('$'): continue + v = VT.search(line) + if v: + cur['slots'].append(v.group(1)) + elif 'No symbol matches' in line: + cur['slots'].append(None); cur['bad'] += 1 + if cur: out.append(cur) + return out + +def report(tag): + recs = parse(tag) + print('=== %s: %d wait frames ===' % (tag, len(recs))) + 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] + 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(' --- objects waited on:') + for k, c in tally.most_common(): + print(' %-45s %d' % (k, c)) + return tally + +if __name__ == '__main__': + tallies = {t: report(t) for t in (sys.argv[1:] or ['healthy'])} + if len(tallies) > 1: + a, b = list(tallies) + print('=== %s -> %s ===' % (a, b)) + keys = set(tallies[a]) | set(tallies[b]) + 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'))