From 9813c9b9b6d9fa7e56fe0e77ccd4589fd9e90902 Mon Sep 17 00:00:00 2001 From: Arthur Hanson Rasmusson Date: Sun, 25 Oct 2026 05:57:04 -0400 Subject: wall-2 session 74: the client's 11s stalls are userspace completion-slot spins; the next wall is the polled RM control 0x2080a097 Root-caused the vk_frame client's exact 11.00s gaps: a pure sched_yield + clock_gettime userspace spin inside libnvidia-eglcore's EGL/GL init, waiting for completion slots (u16 at slot+0xe == 0xffff) in /dev/nvidiactl mappings. Guest-side filling of the slot flags lets the client proceed immediately, but vkCreateDevice still fails -4: with the slots filled the client settles into an NVOS54 poll of RM control 0x2080a097 (paramsSize=1168) which our emulation answers with the generic all-zero reply, so the poll never completes. Also captured: sema_push_raw dumps proving the GR channel-init push contains NO release (entry0 decodes 2 methods then zeros; entry2 SET_OBJECT 0xc597 then zeros), and the negative result that neither channelFillGpFifo nor nvWriteGpEntry runs for this channel's kick. New probes: gdbpoll6/gdbu16/gdbfill/gdbwatch/gdbparam/gdbgap3/gdbspin (slot check, flag fill, NVOS54 param dump, backtraces), slotfill{,2}.sh (guest slot watcher), stracevk/fastrun{,2}.sh (strace+perf recipes), find_ring_va.py and vmap_watch2.py (vmap/kcore watchers), README-session74.md. --- tools/guest-diag/wall2/README-session74.md | 66 +++++++++++++++++++++++++++ tools/guest-diag/wall2/fastrun.sh | 10 ++++ tools/guest-diag/wall2/fastrun2.sh | 12 +++++ tools/guest-diag/wall2/find_ring_va.py | 45 ++++++++++++++++++ tools/guest-diag/wall2/gdbfill.gdb | 13 ++++++ tools/guest-diag/wall2/gdbgap3.sh | 28 ++++++++++++ tools/guest-diag/wall2/gdbparam.sh | 16 +++++++ tools/guest-diag/wall2/gdbpoll6.gdb | 9 ++++ tools/guest-diag/wall2/gdbspin.sh | 19 ++++++++ tools/guest-diag/wall2/gdbu16.gdb | 9 ++++ tools/guest-diag/wall2/gdbwatch.gdb | 18 ++++++++ tools/guest-diag/wall2/perfstall5.sh | 9 ++++ tools/guest-diag/wall2/slotfill.sh | 30 ++++++++++++ tools/guest-diag/wall2/slotfill2.sh | 19 ++++++++ tools/guest-diag/wall2/stracevk.sh | 7 +++ tools/guest-diag/wall2/vmap_watch2.py | 73 ++++++++++++++++++++++++++++++ 16 files changed, 383 insertions(+) create mode 100644 tools/guest-diag/wall2/README-session74.md create mode 100644 tools/guest-diag/wall2/fastrun.sh create mode 100644 tools/guest-diag/wall2/fastrun2.sh create mode 100644 tools/guest-diag/wall2/find_ring_va.py create mode 100644 tools/guest-diag/wall2/gdbfill.gdb create mode 100644 tools/guest-diag/wall2/gdbgap3.sh create mode 100644 tools/guest-diag/wall2/gdbparam.sh create mode 100644 tools/guest-diag/wall2/gdbpoll6.gdb create mode 100644 tools/guest-diag/wall2/gdbspin.sh create mode 100644 tools/guest-diag/wall2/gdbu16.gdb create mode 100644 tools/guest-diag/wall2/gdbwatch.gdb create mode 100644 tools/guest-diag/wall2/perfstall5.sh create mode 100644 tools/guest-diag/wall2/slotfill.sh create mode 100644 tools/guest-diag/wall2/slotfill2.sh create mode 100644 tools/guest-diag/wall2/stracevk.sh create mode 100644 tools/guest-diag/wall2/vmap_watch2.py (limited to 'tools/guest-diag') diff --git a/tools/guest-diag/wall2/README-session74.md b/tools/guest-diag/wall2/README-session74.md new file mode 100644 index 0000000..58587eb --- /dev/null +++ b/tools/guest-diag/wall2/README-session74.md @@ -0,0 +1,66 @@ +# WALL #2 / device-init completion — session 74 findings (r675) + +## The client's "11 s stalls" fully root-caused (this is NOT the channel-init release) +strace (ioctl-only) shows THREE exact 11.00 s gaps with NO ioctl in flight; a +full strace shows the client doing a pure `sched_yield` spin (~57K/s) + +`clock_gettime` (perf) inside **libnvidia-eglcore.so.570.144** — i.e. a +userspace timeout loop. gdb backtraces place the spin inside the Vulkan ICD's +EGL/GL init (`vkCreateInstance` -> libGLX_nvidia vk_icdNegotiate... -> +libEGL -> eglcore wait loop). + +## The wait target: completion slots in /dev/nvidiactl mappings +- The wait loop (eglcore file offsets ~0xb284b0 delay, ~0xb33d00 wait loop, + ~0xb1c750 slot check) polls a slot table on the client's heap object: + table at object+0x1428, count at object+0x22efc. +- Slot check: `esi` is offset by 0x43; for esi-0x43 > 4 it reads a **u16 at + slot+0xe** and treats `0xffff` as "empty/not complete". +- gdb sampling during the stall: 13164 checks with `u16@slot+0xe = 0xffff`, + 1 with `0` — the client spins until the flag changes. +- The slot pointer = a **/dev/nvidiactl rw-s mapping** (page-sized; base+0x20 + = slot). These are the client's mappings of RM memory (the channel + notifier pages: service logs `notif=0x11627f060` per channel). + +## Filling the slots (guest-side) WORKS mechanically but is not the -4 cause +- `slotfill.sh` / `slotfill2.sh`: while vk_frame runs, write 0 to + `base+0x2e` of every small /dev/nvidiactl rw-s mapping when it reads 0xffff. +- Result: the 11 s gaps vanish (5 fills within ~2 s; the client proceeds + immediately) — **but vkCreateDevice still fails -4**. So the 11 s waits are + not the failure; they are an init-side slowdown the client tolerates. + +## The next wall: the polled RM control 0x2080a097 +- With the slots filled, the client settles into **NVOS54 (ioctl nr=0x2a) + polling every ~1.25 s** (strace), and the host dmesg shows + `GSP_RM_CONTROL cmd=0x2080a097 hClient=0xc1d000bb hObject=0xbeef0004 + paramsSize=1168 flags=0x0` -> `unknown cmd=0x2080a097 -> generic SUCCESS` + (all-zero reply), 36 polls in 45 s. +- The NVOS54 struct (gdb dump): {hClient=0xc1d000c0, hObject=0xbeef0004, + cmd=0x2080a097, flags=0, params=ptr, paramsSize=0x490, status=ptr, ...}. +- The params buffer = 1168 bytes of 32-byte records with a `0x25` field at + +0x10 (dump in /tmp/opencode evidence; gdbparam.sh captures it live). +- The client polls until the control's status/reply signals completion; our + generic all-zero reply never does. **This is the wall that must be solved to + get vkCreateDevice past -4** (either a real reply for 0x2080a097 or making + the polled status field change). + +## Other session-74 results +- The GR ring-entry writer was NOT found by disassembly-guessing: nvidia.ko + `channelFillGpFifo` and nvidia-modeset `nvWriteGpEntry` never fire for this + channel's kick (gdb hbreaks); nvidia/modeset kprobes are `notrace`; QEMU gdb + hbreak works. +- `sema_push_raw` dumps (module param) captured the service's reads of the + push: entry0 decodes only 2 methods then zeros (`consumed=0x288/1432`), + entry2 starts `SET_OBJECT 0xc597` then zeros; **no release in the push** + (`have_rel=0` for all three entries) — the channel-init release theory for + these waits is dead. +- `find_ring_va.py` / `vmap_watch2.py`: the ring entries are NOT in any + vmallocinfo area during the run; the nv_vm_map_pages areas hold the CE + pushes; the GR push content is not found by content searches. + +## Files +- gdbpoll6.gdb, gdbu16.gdb, gdbfill.gdb, gdbwatch.gdb, gdbparam.sh, + gdbgap3.sh, gdbspin.sh — the gdb probes (slot check, u16 flag, fill, + NVOS54 param dump, backtraces). +- slotfill.sh / slotfill2.sh — the guest-side slot-fill watcher. +- stracevk.sh, fastrun.sh, fastrun2.sh — the strace/perf recipes. +- perfstall5.sh — perf sampling with map-relative offsets. +- find_ring_va.py, vmap_watch2.py — the vmap/kcore watchers. diff --git a/tools/guest-diag/wall2/fastrun.sh b/tools/guest-diag/wall2/fastrun.sh new file mode 100644 index 0000000..73b9d80 --- /dev/null +++ b/tools/guest-diag/wall2/fastrun.sh @@ -0,0 +1,10 @@ +#!/bin/bash +cd /tmp +sudo dmesg -C +( sudo bash /tmp/slotfill2.sh > /tmp/slotfill2.log 2>&1 & ) +sleep 0.5 +sudo timeout 60 strace -f -T -tt -e trace=ioctl -o /tmp/vk_strace3.out /tmp/vk_frame 1 64 64 5 /tmp 0 > /tmp/vk77.out 2>&1 +echo "=== client ===" +cat /tmp/vk77.out +echo "=== last ioctls ===" +tail -12 /tmp/vk_strace3.out diff --git a/tools/guest-diag/wall2/fastrun2.sh b/tools/guest-diag/wall2/fastrun2.sh new file mode 100644 index 0000000..3c7b943 --- /dev/null +++ b/tools/guest-diag/wall2/fastrun2.sh @@ -0,0 +1,12 @@ +#!/bin/bash +cd /tmp +sudo dmesg -C +( sudo bash /tmp/slotfill2.sh > /dev/null 2>&1 & ) +sleep 0.5 +sudo timeout 45 /tmp/vk_frame 1 64 64 5 /tmp 0 > /tmp/vk78.out 2>&1 +echo "=== client ===" +cat /tmp/vk78.out +echo "=== repeated controls (top) ===" +sudo dmesg -T | grep -oE "GSP_RM_CONTROL cmd=0x[0-9a-f]+" | sort | uniq -c | sort -rn | head -12 +echo "=== last controls ===" +sudo dmesg -T | grep "GSP_RM_CONTROL cmd" | tail -8 diff --git a/tools/guest-diag/wall2/find_ring_va.py b/tools/guest-diag/wall2/find_ring_va.py new file mode 100644 index 0000000..c02ea40 --- /dev/null +++ b/tools/guest-diag/wall2/find_ring_va.py @@ -0,0 +1,45 @@ +#!/usr/bin/env python3 +# Guest-side: read the nv_vm_map_pages vmap areas via /proc/kcore and find the +# GPFIFO entry pattern (entry0 raw 0x0005980004480000 for va=0x4480000 len=1432). +import struct, sys +pat = bytes.fromhex("0000480400980500") # 0x0005980004480000 LE +class Kcore: + def __init__(self): + self.fd = open("/proc/kcore", "rb") + hdr = self.fd.read(64) + e_phoff = struct.unpack_from(" VA 0x%x" % (idx, lo + idx)) if idx >= 0 else "no")) + if idx >= 0: + # dump the page around the hit + base = lo + (idx & ~0xfff) + page = kc.read(base, 0x100) + print(" page head: %s" % page.hex()) diff --git a/tools/guest-diag/wall2/gdbfill.gdb b/tools/guest-diag/wall2/gdbfill.gdb new file mode 100644 index 0000000..41d1ea3 --- /dev/null +++ b/tools/guest-diag/wall2/gdbfill.gdb @@ -0,0 +1,13 @@ +set pagination off +set confirm off +break *POLLADDR +commands 1 +silent +set $e = *(unsigned long*)($rdi+0x1428) +if *(unsigned short*)($e+0x2e) == 0xffff + set {unsigned short}($e+0x2e) = 0 + printf "FILLED slot at %p+0x2e -> 0\n", $e +end +continue +end +continue diff --git a/tools/guest-diag/wall2/gdbgap3.sh b/tools/guest-diag/wall2/gdbgap3.sh new file mode 100644 index 0000000..bf19370 --- /dev/null +++ b/tools/guest-diag/wall2/gdbgap3.sh @@ -0,0 +1,28 @@ +#!/bin/bash +cd /tmp +(timeout 120 /tmp/vk_frame 1 64 64 5 /tmp 0 > /tmp/vk65.out 2>&1 &) +sleep 5 +PID=$(pgrep -x vk_frame | head -1) +cp /proc/$PID/maps /tmp/maps_d.txt +gdb -p $PID -batch -ex "set pagination off" -ex "bt 12" 2>&1 | grep -E "^#" > /tmp/bt_gap3.txt +python3 - <<'PY' +import re +maps=open('/tmp/maps_d.txt').read().splitlines() +segs=[] +for m in maps: + p=m.split() + if len(p)<6: continue + lo,hi=[int(x,16) for x in p[0].split('-')] + off=int(p[2],16) + segs.append((lo,hi,off,p[5])) +for line in open('/tmp/bt_gap3.txt'): + m=re.match(r'#(\d+)\s+0x([0-9a-f]+)', line) + if not m: continue + a=int(m.group(2),16) + for lo,hi,off,name in segs: + if lo<=a /dev/null 2>&1 & ) +sleep 0.5 +(timeout 60 /tmp/vk_frame 1 64 64 5 /tmp 0 > /tmp/vk79.out 2>&1 &) +sleep 5 +PID=$(pgrep -x vk_frame | head -1) +gdb -p $PID -batch \ + -ex "set pagination off" \ + -ex "catch syscall ioctl" \ + -ex "condition 1 \$rsi == 0xc020462a" \ + -ex "continue" \ + -ex "printf \"ioctl nr=0x2a arg=%p\n\", \$rdx" \ + -ex "x/40wx \$rdx" \ + -ex "detach" 2>/dev/null | tail -45 diff --git a/tools/guest-diag/wall2/gdbpoll6.gdb b/tools/guest-diag/wall2/gdbpoll6.gdb new file mode 100644 index 0000000..d7fccfd --- /dev/null +++ b/tools/guest-diag/wall2/gdbpoll6.gdb @@ -0,0 +1,9 @@ +set pagination off +set confirm off +break *POLLADDR +commands 1 +silent +printf "CHK rsi=%d cnt=%d e0=%p v=%x\n", $rsi, *(int*)($rdi+0x22efc), *(unsigned long*)($rdi+0x1428), *(unsigned int*)(*(unsigned long*)($rdi+0x1428)+($rsi<<4)) +continue +end +continue diff --git a/tools/guest-diag/wall2/gdbspin.sh b/tools/guest-diag/wall2/gdbspin.sh new file mode 100644 index 0000000..989e584 --- /dev/null +++ b/tools/guest-diag/wall2/gdbspin.sh @@ -0,0 +1,19 @@ +#!/bin/bash +cd /tmp +(timeout 120 /tmp/vk_frame 1 64 64 5 /tmp 0 > /tmp/vk57.out 2>&1 &) +sleep 25 +PID=$(pgrep -x vk_frame | head -1) +echo "pid=$PID" +BASE=$(grep 'eglcore' /proc/$PID/maps | head -1 | cut -d- -f1) +echo "base=$BASE" +SPIN=$(printf '0x%x' $((0x$BASE + 0xa10e90))) +echo "spin=$SPIN" +gdb -p $PID -batch \ + -ex "set pagination off" \ + -ex "break *$SPIN" \ + -ex "continue" \ + -ex "printf \"HIT rip=%p rdi=%p rsi=%p rdx=%p rbx=%p rbp=%p\n\", \$rip, \$rdi, \$rsi, \$rdx, \$rbx, \$rbp" \ + -ex "bt" \ + -ex "info registers r12 r13 r14 r15" \ + -ex "x/12i \$rip-24" \ + -ex "detach" 2>&1 | tail -40 diff --git a/tools/guest-diag/wall2/gdbu16.gdb b/tools/guest-diag/wall2/gdbu16.gdb new file mode 100644 index 0000000..61f335b --- /dev/null +++ b/tools/guest-diag/wall2/gdbu16.gdb @@ -0,0 +1,9 @@ +set pagination off +set confirm off +break *POLLADDR +commands 1 +silent +printf "CHK rsi=%d cnt=%d e0=%p u16@2e=%x u32@20=%x u32@0=%x\n", $rsi, *(int*)($rdi+0x22efc), *(unsigned long*)($rdi+0x1428), *(unsigned short*)(*(unsigned long*)($rdi+0x1428)+0x2e), *(unsigned int*)(*(unsigned long*)($rdi+0x1428)+0x20), *(unsigned int*)(*(unsigned long*)($rdi+0x1428)) +continue +end +continue diff --git a/tools/guest-diag/wall2/gdbwatch.gdb b/tools/guest-diag/wall2/gdbwatch.gdb new file mode 100644 index 0000000..36b3339 --- /dev/null +++ b/tools/guest-diag/wall2/gdbwatch.gdb @@ -0,0 +1,18 @@ +set pagination off +set confirm off +break *POLLADDR +commands 1 +silent +set $e = *(unsigned long*)($rdi+0x1428) +watch *(unsigned short*)($e+0x2e) +printf "WATCH set at %p+0x2e\n", $e +disable 1 +continue +end +commands 2 +silent +printf "WRITE to slot+0x2e: old=%x new=%x by pc=%p\n", *(unsigned short*)($e+0x2e), $eax, $pc +bt 3 +continue +end +continue diff --git a/tools/guest-diag/wall2/perfstall5.sh b/tools/guest-diag/wall2/perfstall5.sh new file mode 100644 index 0000000..ae1c161 --- /dev/null +++ b/tools/guest-diag/wall2/perfstall5.sh @@ -0,0 +1,9 @@ +#!/bin/sh +cd /tmp +(timeout 120 /tmp/vk_frame 1 64 64 5 /tmp 0 > /tmp/vk55.out 2>&1 &) +sleep 25 +PID=$(pgrep -x vk_frame | head -1) +cp /proc/$PID/maps /tmp/vk_maps2.txt +sudo perf record -p $PID -g -o /tmp/perf6.data -- sleep 3 2>/dev/null +sudo perf script -i /tmp/perf6.data -F ip,dso 2>/dev/null | grep eglcore | awk '{print $1}' | sort | uniq -c | sort -rn | head -8 > /tmp/spin_addrs.txt +cat /tmp/spin_addrs.txt diff --git a/tools/guest-diag/wall2/slotfill.sh b/tools/guest-diag/wall2/slotfill.sh new file mode 100644 index 0000000..a3416a9 --- /dev/null +++ b/tools/guest-diag/wall2/slotfill.sh @@ -0,0 +1,30 @@ +#!/bin/bash +# Watch the vk_frame client and fill the completion-slot u16 (base+0x2e) in +# every small /dev/nvidiactl rw-s mapping while it waits. +cd /tmp +rm -f /tmp/slotfill.log +(timeout 120 /tmp/vk_frame 1 64 64 5 /tmp 0 > /tmp/vk76.out 2>&1 &) +PID="" +for i in $(seq 1 100); do PID=$(pgrep -x vk_frame | head -1); [ -n "$PID" ] && break; sleep 0.1; done +echo "pid=$PID" >> /tmp/slotfill.log +END=$((SECONDS+60)) +while [ $SECONDS -lt $END ]; do + [ -d /proc/$PID ] || break + for m in $(grep 'nvidiactl' /proc/$PID/maps | awk '$2 ~ /rw-s/ {print $1}'); do + lo=${m%-*}; hi=${m#*-} + size=$((0x$hi - 0x$lo)) + [ $size -gt 65536 ] && continue + off=$((0x$lo + 0x2e)) + v=$(dd if=/proc/$PID/mem bs=1 skip=$off count=2 2>/dev/null | xxd -p) + if [ "$v" = "ffff" ]; then + printf '\x00\x00' | dd of=/proc/$PID/mem bs=1 seek=$off count=2 conv=notrunc 2>/dev/null + echo "$(date +%s.%N) FILL $m+0x2e was ffff" >> /tmp/slotfill.log + fi + done + sleep 0.2 +done +echo "done" >> /tmp/slotfill.log +echo "=== client ===" +cat /tmp/vk76.out +echo "=== fills ===" +grep -c FILL /tmp/slotfill.log diff --git a/tools/guest-diag/wall2/slotfill2.sh b/tools/guest-diag/wall2/slotfill2.sh new file mode 100644 index 0000000..33ad702 --- /dev/null +++ b/tools/guest-diag/wall2/slotfill2.sh @@ -0,0 +1,19 @@ +#!/bin/bash +cd /tmp +PID="" +for i in $(seq 1 200); do PID=$(pgrep -x vk_frame | head -1); [ -n "$PID" ] && break; sleep 0.05; done +END=$((SECONDS+45)) +while [ $SECONDS -lt $END ]; do + [ -d /proc/$PID ] || break + for m in $(grep 'nvidiactl' /proc/$PID/maps 2>/dev/null | awk '$2 ~ /rw-s/ {print $1}'); do + lo=${m%-*}; hi=${m#*-} + size=$((0x$hi - 0x$lo)) + [ $size -gt 65536 ] && continue + off=$((0x$lo + 0x2e)) + v=$(dd if=/proc/$PID/mem bs=1 skip=$off count=2 2>/dev/null | xxd -p) + if [ "$v" = "ffff" ]; then + printf '\x00\x00' | dd of=/proc/$PID/mem bs=1 seek=$off count=2 conv=notrunc 2>/dev/null + fi + done + sleep 0.1 +done diff --git a/tools/guest-diag/wall2/stracevk.sh b/tools/guest-diag/wall2/stracevk.sh new file mode 100644 index 0000000..b2752c4 --- /dev/null +++ b/tools/guest-diag/wall2/stracevk.sh @@ -0,0 +1,7 @@ +#!/bin/sh +cd /tmp +sudo timeout 90 strace -f -T -tt -e trace=ioctl -o /tmp/vk_strace.out /tmp/vk_frame 1 64 64 5 /tmp 0 > /tmp/vk58.out 2>&1 +echo "=== client out ===" +cat /tmp/vk58.out +echo "=== ioctl tail ===" +tail -30 /tmp/vk_strace.out diff --git a/tools/guest-diag/wall2/vmap_watch2.py b/tools/guest-diag/wall2/vmap_watch2.py new file mode 100644 index 0000000..194b0d6 --- /dev/null +++ b/tools/guest-diag/wall2/vmap_watch2.py @@ -0,0 +1,73 @@ +#!/usr/bin/env python3 +# Guest-side live watcher v2: scan ALL vmallocinfo areas via /proc/kcore for +# (a) GR ring entry patterns, (b) pages starting with a small INC_METHOD header. +import struct, time +ENTRIES = [bytes.fromhex("0000480400980500"), bytes.fromhex("8000040004480598"), bytes.fromhex("0003d0000448059c")] +class Kcore: + def __init__(self): + self.fd = open("/proc/kcore", "rb") + hdr = self.fd.read(64) + e_phoff = struct.unpack_from("> 29) & 7 + cnt = (v >> 16) & 0xfff + return op == 1 and 1 <= cnt <= 8 +print("vmap_watch2 start", flush=True) +found = set() +t0 = time.time() +it = 0 +while time.time() - t0 < 300: + it += 1 + nareas = 0 + for lo, hi, tag in areas(): + size = hi - lo + if size > 8 << 20: continue + nareas += 1 + d = kc.read(lo, size) + if not d: continue + for pat in ENTRIES: + i = d.find(pat) + if i >= 0: + key = (lo, i & ~0xfff, pat.hex()) + if key not in found: + found.add(key) + print("%.2f RING %s VA 0x%x (+0x%x) %s" % (time.time()-t0, pat.hex(), lo+(i&~0xfff), i&~0xfff, tag), flush=True) + for off in range(0, size - 0x1000, 0x1000): + page = d[off:off+0x1000] + if hdr_ok(page): + key = (lo, off, "h") + if key not in found: + found.add(key) + print("%.2f HDR VA 0x%x (+0x%x) %s head=%s" % (time.time()-t0, lo+off, off, tag, page[:0x30].hex()), flush=True) + if it % 10 == 0: + print("%.1f iter %d areas %d" % (time.time()-t0, it, nareas), flush=True) + time.sleep(0.2) +print("vmap_watch2 done", flush=True) -- cgit v1.2.3