From 2c001647e47455544739fc8f4e841c6b93cbe32f Mon Sep 17 00:00:00 2001 From: Arthur Hanson Rasmusson Date: Wed, 30 Sep 2026 00:06:42 -0400 Subject: gsprm: reply-latency logging + param dump cap; guest-diag: CDT_PAUSE, watcher reaping, wider CE stream window --- tools/guest-diag/bp999v2.py | 89 ++++++++++++++++++++++++++++++ tools/guest-diag/bpwait.py | 74 +++++++++++++++++++++++++ tools/guest-diag/guest_pin_stream.py | 8 ++- tools/guest-diag/push_guest_tools.sh | 2 + tools/guest-diag/run_cycle.sh | 102 +++++++++++++++++++++++++++++++++++ tools/guest-diag/vmrestart.sh | 5 +- tools/test/cuda_drv_test.c | 8 +++ 7 files changed, 284 insertions(+), 4 deletions(-) create mode 100644 tools/guest-diag/bp999v2.py create mode 100644 tools/guest-diag/bpwait.py create mode 100755 tools/guest-diag/run_cycle.sh (limited to 'tools') diff --git a/tools/guest-diag/bp999v2.py b/tools/guest-diag/bp999v2.py new file mode 100644 index 0000000..766bc3b --- /dev/null +++ b/tools/guest-diag/bp999v2.py @@ -0,0 +1,89 @@ +# gdb script: break at the 999/719 RETURN sites of the libcuda scanner +# FUN_0054fa00 and dump the record values the scanner actually read (they are +# still in its stack locals, so the host clearing the notification afterwards +# cannot race this capture). +# +# Scanner layout (disassembly of libcuda+0x44fa00): +# rec = *(*(*(ctx+0x9488)+0x10)+0x10) +# locals: rbp-0x40 rec[+0x00], rbp-0x3c rec[+0x04], rbp-0x38 rec[+0x08], +# rbp-0x34 rec[+0x0c] (s16), rbp-0x32 rec[+0x0e] (s16) +# 0x44fb80 -> return 999 when force != 0 and (rec[+8]|rec[+0xc]|rec[+0xe]) +# 0x44fb6c -> return 0x2cf +# Run: sudo gdb -p -batch -x /tmp/bp999v2.py +import gdb + +out = gdb.execute("info proc mappings", to_string=True) +base = None +for line in out.splitlines(): + if "libcuda" in line and "r-xp" in line: + f = line.split() + base = int(f[0], 16) - int(f[3], 16) + break +print("BASE=0x%x" % (base or 0)) +if base is None: + raise SystemExit + +gdb.execute("set pagination off") +gdb.execute("set confirm off") +gdb.execute("break *0x%x" % (base + 0x44fb80)) +gdb.execute("break *0x%x" % (base + 0x44fb6c)) +try: + gdb.execute("continue") +except gdb.error as e: + print("CONTINUE_ERR %s" % e) +print("STOPPED") + +try: + rip = int(gdb.parse_and_eval("$rip")) & 0xffffffffffffffff + print("RIP=0x%x off=0x%x" % (rip, rip - base)) + rdi = int(gdb.parse_and_eval("$rdi")) & 0xffffffffffffffff + rsi = int(gdb.parse_and_eval("$rsi")) & 0xffffffff + rbp = int(gdb.parse_and_eval("$rbp")) & 0xffffffffffffffff + print("rdi=0x%x rsi(force)=%d rbp=0x%x" % (rdi, rsi, rbp)) + print(gdb.execute("x/5wx 0x%x" % (rbp - 0x40), to_string=True)) + print(gdb.execute("x/2hx 0x%x" % (rbp - 0x34), to_string=True)) +except Exception as e: + print("locals_fail %s" % e) + +try: + print(gdb.execute("bt 14", to_string=True)) +except Exception as e: + print("bt_fail %s" % e) + + +def rd64(a): + try: + return int(gdb.parse_and_eval("*(unsigned long *)0x%x" % a)) & 0xffffffffffffffff + except Exception: + return None + + +def rd32(a): + try: + return int(gdb.parse_and_eval("*(unsigned int *)0x%x" % a)) & 0xffffffff + except Exception: + return None + + +try: + pl = rd64(rdi) + n = 0 + while pl and n < 64: + mgr = rd64(pl + 0x9488) + print("ctx[%d]=0x%x mgr=0x%x" % (n, pl, mgr or 0)) + if mgr: + reg = rd64(mgr + 0x10) + if reg: + rec = rd64(reg + 0x10) + print(" reg=0x%x rec=0x%x" % (reg, rec or 0)) + if rec: + for i in range(0, 0x28, 4): + print(" rec[+0x%02x]=0x%08x" % (i, rd32(rec + i) or 0)) + pl = rd64(pl + 0x9470) + n += 1 +except Exception as e: + print("record_dump_fail %s" % e) +try: + gdb.execute("detach") +except Exception: + pass \ No newline at end of file diff --git a/tools/guest-diag/bpwait.py b/tools/guest-diag/bpwait.py new file mode 100644 index 0000000..9b708c8 --- /dev/null +++ b/tools/guest-diag/bpwait.py @@ -0,0 +1,74 @@ +# gdb script: catch the tracker-gate exit with a NONZERO dispatcher status and +# dump the wait-entry array the gate polls. This names the wait that ends the +# client's context-init spin (the value that becomes the CUDA error). +# +# Site (libcuda+0x23f9e7): the gate loops +# call 0xd50e50 ; wait dispatcher +# 0x23f9ec: mov %eax,%edx +# 0x23f9ee: test %eax,%eax +# 0x23f9f0: je 0x23f9c0 ; still pending -> poll again +# 0x23f9f2: mov %edx,%eax ; <- nonzero status: gate exits with it +# Entry object: { *(void**)rsi; u32 count @+0x10; void *array @+0x18 } +# Array entries are 0x28 bytes: type @+0x0, then type-specific fields. +# Run: sudo gdb -p -batch -x /tmp/bpwait.py +import gdb + +out = gdb.execute("info proc mappings", to_string=True) +base = None +for line in out.splitlines(): + if "libcuda" in line and "r-xp" in line: + f = line.split() + base = int(f[0], 16) - int(f[3], 16) + break +print("BASE=0x%x" % (base or 0)) +if base is None: + raise SystemExit + +gdb.execute("set pagination off") +gdb.execute("set confirm off") +gdb.execute("break *0x%x" % (base + 0x23f9f2)) +try: + gdb.execute("continue") +except gdb.error as e: + print("CONTINUE_ERR %s" % e) +print("STOPPED") + + +def rd64(a): + try: + return int(gdb.parse_and_eval("*(unsigned long *)0x%x" % a)) & 0xffffffffffffffff + except Exception: + return None + + +def rd32(a): + try: + return int(gdb.parse_and_eval("*(unsigned int *)0x%x" % a)) & 0xffffffff + except Exception: + return None + + +try: + rip = int(gdb.parse_and_eval("$rip")) & 0xffffffffffffffff + edx = int(gdb.parse_and_eval("$edx")) & 0xffffffff + rsi = int(gdb.parse_and_eval("$rsi")) & 0xffffffffffffffff + print("RIP=0x%x off=0x%x status(edx)=0x%x" % (rip, rip - base, edx)) + print(gdb.execute("bt 16", to_string=True)) + ent = rd64(rsi) + cnt = rd32(rsi + 0x10) + arr = rd64(rsi + 0x18) + print("entry_obj=0x%x count=0x%x array=0x%x" % (ent or 0, cnt or 0, arr or 0)) + if ent and arr: + print("entity hdr: " + " ".join("+0x%x=0x%x" % (o, rd32(ent + o) or 0) + for o in (0, 4, 8, 0xc, 0x10, 0x14, 0x18, 0x1c))) + if arr and cnt and cnt < 64: + for i in range(cnt): + e = arr + i * 0x28 + words = [rd32(e + o) or 0 for o in (0, 4, 8, 0xc, 0x10, 0x14, 0x18, 0x1c, 0x20, 0x24)] + print("entry[%d] " % i + " ".join("0x%08x" % w for w in words)) +except Exception as e: + print("dump_fail %s" % e) +try: + gdb.execute("detach") +except Exception: + pass \ No newline at end of file diff --git a/tools/guest-diag/guest_pin_stream.py b/tools/guest-diag/guest_pin_stream.py index 2f99bbd..94e4de9 100644 --- a/tools/guest-diag/guest_pin_stream.py +++ b/tools/guest-diag/guest_pin_stream.py @@ -32,9 +32,13 @@ REGION = 0x200000 SPAN = int(os.environ.get("STREAM_SPAN", "0x80000"), 16) # CE push-buffer window: one 1 MB allocation per CE channel at # 0x120000000 + 0x100000*rank; SPAN2 covers the 1 MB boundary inside a -# 2 MB region. +# 2 MB region. Extend HI2 to 0x121400000: the UVM semaphore pool (the +# tracker sems the client's context-init wait polls, pool word at +# 0x121000000 + 4*idx) lives above the push buffers and must reach the host +# through this fast stream - otherwise only the slow QMP chain resolution +# pins it, and the pin lands after the client's RM thread-state deadline. LO2 = int(os.environ.get("STREAM_LO2", "0x120000000"), 16) -HI2 = int(os.environ.get("STREAM_HI2", "0x120600000"), 16) +HI2 = int(os.environ.get("STREAM_HI2", "0x121400000"), 16) SPAN2 = int(os.environ.get("STREAM_SPAN2", "0x180000"), 16) TRACE = ("/sys/kernel/tracing/trace" if os.path.exists("/sys/kernel/tracing/trace") diff --git a/tools/guest-diag/push_guest_tools.sh b/tools/guest-diag/push_guest_tools.sh index 58ebdb3..7114b03 100755 --- a/tools/guest-diag/push_guest_tools.sh +++ b/tools/guest-diag/push_guest_tools.sh @@ -27,6 +27,8 @@ push_b64 "$REPO/tools/test/cuda_drv_test.c" /tmp/cdt.c push_b64 "$HERE/dumpctx.py" /tmp/dumpctx.py push_b64 "$HERE/trkinfo.py" /tmp/trkinfo.py push_b64 "$HERE/bp999.py" /tmp/bp999.py +push_b64 "$HERE/bp999v2.py" /tmp/bp999v2.py +push_b64 "$HERE/bpwait.py" /tmp/bpwait.py push_b64 "$HERE/ctx999.py" /tmp/ctx999.py push_b64 "$HERE/scanerr.py" /tmp/scanerr.py push_b64 "$HERE/sem_counters.py" /tmp/sem_counters.py diff --git a/tools/guest-diag/run_cycle.sh b/tools/guest-diag/run_cycle.sh new file mode 100755 index 0000000..a566469 --- /dev/null +++ b/tools/guest-diag/run_cycle.sh @@ -0,0 +1,102 @@ +#!/bin/bash +# run_cycle.sh - one instrumented CUDA bring-up cycle with full capture. +# +# Recipe (PART 70 + PART 71): restart VM/module, push tools, install kprobes +# (uvmt ON, uvsv/uvsvr OFF, 16 MB ring), start pin_gr_stream + semfix, launch +# cdt (strace -f -e ioctl) holding on failure, snapshot host+guest dmesg. +# +# Usage: tools/guest-diag/run_cycle.sh [hold-seconds] [strace|nostrace] +set -uo pipefail + +HERE="$(cd "$(dirname "$0")" && pwd)" +REPO="$HERE/../.." +VMEXEC="$REPO/scripts/vgpu_vm.py" +OUT=/tmp/opencode +HOLD="${1:-900}" +TRACE="${2:-strace}" + +mkdir -p "$OUT" +echo "[*] vmrestart" +timeout 180 "$HERE/vmrestart.sh" || { echo "vmrestart failed"; exit 1; } + +echo "[*] waiting for guest" +for i in $(seq 1 24); do + if timeout 10 "$VMEXEC" exec "echo UP" 2>/dev/null | grep -q UP; then + echo " guest up" + break + fi + sleep 5 +done + +echo "[*] setting module params" +sudo sh -c 'echo Y > /sys/module/open_iov_vfio/parameters/sema_fake_rel; echo Y > /sys/module/open_iov_vfio/parameters/sema_skip_ops' + +echo "[*] pushing guest tools" +timeout 300 "$HERE/push_guest_tools.sh" >/dev/null 2>&1 || { echo "push failed"; exit 1; } + +echo "[*] loading nvidia modules in guest (kprobe symbols need them)" +timeout 90 "$VMEXEC" exec "nvidia-smi -L >/dev/null 2>&1; lsmod | grep -q nvidia_uvm && echo UVM_LOADED" 2>/dev/null | grep -q UVM_LOADED || echo " WARN: nvidia_uvm not loaded" + +echo "[*] installing guest kprobes (uvmt ON; uvsv/uvsvr OFF; 16 MB ring)" +timeout 60 "$VMEXEC" exec "sh /tmp/kprobes.sh" 2>/dev/null | grep -E "ok|FAIL" | head -8 +timeout 30 "$VMEXEC" exec "TR=/sys/kernel/tracing; [ -d \$TR ] || TR=/sys/kernel/debug/tracing; echo 16384 > \$TR/buffer_size_kb; echo 0 > \$TR/events/kprobes/uvsv/enable; echo 0 > \$TR/events/kprobes/uvsvr/enable; echo 1 > \$TR/events/kprobes/uvmt/enable; echo 1 > \$TR/events/kprobes/uvtw/enable; echo 1 > \$TR/events/kprobes/uvbp/enable; echo 1 > \$TR/events/kprobes/uvch/enable" >/dev/null 2>&1 + +echo "[*] starting host dmesg capture" +sudo dmesg -w > "$OUT/hostdmesg.log" 2>&1 & +DMESG_PID=$! + +echo "[*] starting pin_gr_stream + semfix" +( setsid nohup env SEMFIX_SKIP_PB=1 SEMFIX_COUNTER_RETRY=10 \ + python3 "$HERE/pin_gr_stream.py" > "$OUT/pin_gr_stream.log" 2>&1 & ) +sleep 1 +( setsid nohup env SEMFIX_SKIP_PB=1 SEMFIX_COUNTER_RETRY=10 \ + python3 "$HERE/semfix_uvmt.py" 0.5 > "$OUT/semfix.log" 2>&1 & ) +sleep 2 + +echo "[*] launching cdt (HOLD=$HOLD, $TRACE)" +if [ "$TRACE" = "strace" ]; then + timeout 30 "$VMEXEC" exec \ + "rm -f /tmp/cdt.out /tmp/strace.log; CDT_HOLD=$HOLD nohup strace -f -tt -e trace=ioctl -o /tmp/strace.log /tmp/cdt >/tmp/cdt.out 2>&1 & echo STARTED" \ + >/dev/null 2>&1 +elif [ "$TRACE" = "gdb" ]; then + timeout 30 "$VMEXEC" exec "rm -f /tmp/cdt.out /tmp/bpwait.out; sync; echo CLEARED" >/dev/null 2>&1 + timeout 30 "$VMEXEC" exec \ + "rm -f /tmp/cdt.out /tmp/bpwait.out; CDT_PAUSE=60 CDT_HOLD=$HOLD nohup /tmp/cdt >/tmp/cdt.out 2>&1 & echo STARTED" \ + >/dev/null 2>&1 + PID="" + for i in $(seq 1 12); do + PID=$(timeout 20 "$VMEXEC" exec "pgrep -x cdt" 2>/dev/null | grep -E '^[0-9]+$' | head -1) + [ -n "$PID" ] && break + sleep 2 + done + echo " cdt pid=$PID; arming bpwait (tracker-gate exit, serial+file)" + timeout 40 "$VMEXEC" exec \ + "nohup sh -c \"gdb -p '$PID' -batch -x /tmp/bpwait.py < /dev/null 2>&1 | tee /tmp/bpwait.out > /dev/ttyS0\" >/dev/null 2>&1 & echo ARMED" \ + >/dev/null 2>&1 +else + timeout 30 "$VMEXEC" exec \ + "rm -f /tmp/cdt.out; CDT_HOLD=$HOLD nohup /tmp/cdt >/tmp/cdt.out 2>&1 & echo STARTED" \ + >/dev/null 2>&1 +fi + +echo "[*] waiting for the run to finish (watch cdt.out)" +for i in $(seq 1 90); do + sleep 2 + OUT_TXT=$(timeout 20 "$VMEXEC" exec "cat /tmp/cdt.out 2>/dev/null" 2>/dev/null | tail -6) + if echo "$OUT_TXT" | grep -q "FAILED rc="; then + echo " failure observed after ~$((i*2))s" + break + fi +done + +echo "[*] snapshotting guest dmesg" +timeout 60 "$VMEXEC" exec "dmesg > /tmp/guestdmesg.log; cp /tmp/cdt.out /tmp/cdt.out.snap; [ -f /tmp/strace.log ] && cp /tmp/strace.log /tmp/strace.log.snap; [ -f /tmp/bpwait.out ] && cp /tmp/bpwait.out /tmp/bpwait.out.snap; echo DONE" >/dev/null 2>&1 +sleep 1 +sudo kill "$DMESG_PID" 2>/dev/null + +echo "[*] collecting artifacts to $OUT" +for f in cdt.out.snap strace.log.snap bpwait.out.snap guestdmesg.log; do + timeout 60 "$VMEXEC" exec "cat /tmp/$f" > "$OUT/$f" 2>/dev/null +done +echo "[*] done: $OUT/cdt.out.snap $OUT/strace.log.snap $OUT/guestdmesg.log $OUT/hostdmesg.log" +tail -5 "$OUT/cdt.out.snap" 2>/dev/null \ No newline at end of file diff --git a/tools/guest-diag/vmrestart.sh b/tools/guest-diag/vmrestart.sh index 5d15852..8c15a89 100755 --- a/tools/guest-diag/vmrestart.sh +++ b/tools/guest-diag/vmrestart.sh @@ -9,8 +9,9 @@ sudo pkill -f qemu-system-x86_64 2>/dev/null # Reap host-side watchers too: a pin_gr_stream/semfix pair left over from the # previous boot holds the vsock port and the single QMP socket slot and will # silently corrupt the next run (two QMP clients). -pkill -f "guest-diag/pin_gr_stream.py" 2>/dev/null -pkill -f "guest-diag/semfix_uvmt.py" 2>/dev/null +pkill -f "pin_gr_stream" 2>/dev/null +pkill -f "semfix_uvmt" 2>/dev/null +pkill -f "guest_pin_stream" 2>/dev/null sleep 4 sudo rm -f /tmp/qemu-guest-agent.sock /tmp/qemu-qmp.sock diff --git a/tools/test/cuda_drv_test.c b/tools/test/cuda_drv_test.c index 8995a55..f3ee02f 100644 --- a/tools/test/cuda_drv_test.c +++ b/tools/test/cuda_drv_test.c @@ -99,6 +99,14 @@ int main(void) printf("device 0 = %d\n", dev); MARK("cuCtxCreate"); + { + const char *pause = getenv("CDT_PAUSE"); + if (pause && atoi(pause) > 0) { + printf("CDT_PAUSE: sleeping %d s before cuCtxCreate\n", atoi(pause)); + fflush(stdout); + sleep((unsigned)atoi(pause)); + } + } CHECK(cuCtxCreate(&ctx, 0, dev)); printf("context = %p\n", ctx); -- cgit v1.2.3