re: withdraw the 'unrestorable rbx' claim — the misses are WaitMultiple
The 8 threads whose [rbx] did not resolve to a vtable were never in XObject::Wait. The backtrace grep matched WaitMultiple as a substring, and there %rbx is the XObject** array (mov %rsi,%rbx) with the count in %ebp, so [rbx] is objects[0] -- an object pointer, needing a second deref -- not a vtable. The unwind restored rbx correctly for all 18. freeze_waitobj.sh now takes the function and frame index from the backtrace and applies the matching read, and captures twice in one run (healthy and after the ~270s black-screen) so the comparison is within-run. waitobj_report.py tabulates both and diffs them, discarding any value info symbol cannot resolve.
This commit is contained in:
Sylpheed RE agent
@@ -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 <tag>
|
||||
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)) \
|
||||
</dev/null >/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/<pid>/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"
|
||||
|
||||
74
tools/re-capture/waitobj_report.py
Executable file
74
tools/re-capture/waitobj_report.py
Executable file
@@ -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 '<unresolved>'] += 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'))
|
||||
Reference in New Issue
Block a user