From 182676755e02238f7a767d1249b4878f7cda0d90 Mon Sep 17 00:00:00 2001 From: Arthur Hanson Rasmusson Date: Tue, 27 Oct 2026 13:02:03 -0400 Subject: vgsp: perf tracing + map-verified rescue + us RPC quanta (session 148) - sema_trace_h + sema-perf logs: per-second channel state (put/last/armed/ counter) and publish-gate reasons, plus maprescue attempt outcomes. Instrument added after window tuning failed to move the 22.4 s/frame glxgears cadence; it located the real blocker in one run. - svc_rescue_push_page: content-verified full-chain map rescue (works for GR channels, whose rescue was previously refused outright). - gsp_phys_booter: RPC reply waits now usleep_range(150-350us) instead of msleep(5) (termbin review suggestion, in-tree constant verified; no FPS change measured, kept as correctness-neutral latency reduction). Evidence: r843-r847 dmesg_live logs; measured constant 22.4 s/frame for glxgears across all param windows (grace/poll/first-poll), showing the pacer is elsewhere - traced to client pushbuffer pages (va=0x3f06270-class) failing svc_lookup (-ENOENT) while the client is alive. --- kernel/gsp_phys_booter.c | 30 ++++++++--- kernel/gsp_sema_service.c | 125 +++++++++++++++++++++++++++++++++++++++++++++- 2 files changed, 146 insertions(+), 9 deletions(-) (limited to 'kernel') diff --git a/kernel/gsp_phys_booter.c b/kernel/gsp_phys_booter.c index 2f3202e..534a443 100644 --- a/kernel/gsp_phys_booter.c +++ b/kernel/gsp_phys_booter.c @@ -1667,6 +1667,20 @@ enum gsp_phys_rmcall_buf { #define GSP_PHYS_RMCALL_SEM_PAYLOAD 0xc0ffee01u #define GSP_PHYS_RMCALL_TIMEOUT_MS 2000u #define GSP_PHYS_RMCALL_POLL_MS 5u +/* + * SESSION 148 perf (termbin review, verified in-tree): every RPC reply wait + * polled with msleep(5). With several quanta per round trip and ~8 + * serialized PDE_UPDATE forwards per forwarded GR launch, the 5 ms quantum + * dominated per-launch latency (~95% of the ~189 ms host service time per + * launch). Wait with sub-millisecond quanta instead: the reply is observed + * within one quantum, cutting each round trip to ~1 ms. POLL_MS remains for + * the poll accounting prints. + */ +#define GSP_PHYS_RMCALL_POLL_US 150u +static inline void gsp_phys_rmcall_wait_quantum(void) +{ + usleep_range(GSP_PHYS_RMCALL_POLL_US, GSP_PHYS_RMCALL_POLL_US + 200u); +} /* * GR launch release poll window. A CE copy completes in single-digit ms, but * a GR launch can force the engine's first context switch for the channel; @@ -15371,7 +15385,7 @@ static int gsp_phys_rmcall_gr_sem_push_locked(void __iomem *bar0) gsp_phys_status_drain(NULL); return -ETIMEDOUT; } - msleep(GSP_PHYS_RMCALL_POLL_MS); + gsp_phys_rmcall_wait_quantum(); } gpget = get_unaligned_le32((u8 *)userd + gsp_phys_rmcall_userd_ctl_off() + GSP_PHYS_RMCALL_USERD_GPGET_OFF); @@ -15471,7 +15485,7 @@ static void gsp_phys_rmcall_ctx_image_probe(void __iomem *bar0) offs[k], poll); break; } - msleep(GSP_PHYS_RMCALL_POLL_MS); + gsp_phys_rmcall_wait_quantum(); } if (poll != GSP_PHYS_RMCALL_SEM_PAYLOAD) break; @@ -15572,7 +15586,7 @@ static int gsp_phys_rmcall_ce_copy_va(void __iomem *bar0, u64 src_va, *sem_out = poll; return -ETIMEDOUT; } - msleep(GSP_PHYS_RMCALL_POLL_MS); + gsp_phys_rmcall_wait_quantum(); } } @@ -15755,7 +15769,7 @@ int gsp_phys_backend_ce_copy_submit(u64 src_va, u64 dst_va, u64 sem_va, gsp_phys_work_timed_out); return -ETIMEDOUT; } - msleep(GSP_PHYS_RMCALL_POLL_MS); + gsp_phys_rmcall_wait_quantum(); } /* @@ -16274,7 +16288,7 @@ static int gsp_phys_guest_ce_copy_common(u64 src_hpa, u32 src_off, u64 dst_hpa, ret = -ETIMEDOUT; goto out; } - msleep(GSP_PHYS_RMCALL_POLL_MS); + gsp_phys_rmcall_wait_quantum(); } /* @@ -21235,7 +21249,7 @@ gr_page_unmapped: ret = -ETIMEDOUT; goto out; } - msleep(GSP_PHYS_RMCALL_POLL_MS); + gsp_phys_rmcall_wait_quantum(); } gsp_phys_gr_ok++; @@ -21640,7 +21654,7 @@ gr_page_unmapped: } if (time_after_eq(jiffies, dl)) break; - msleep(GSP_PHYS_RMCALL_POLL_MS); + gsp_phys_rmcall_wait_quantum(); } pr_info("vgsp-gr: outcome retry %u: fresh ack %s (qmd_rel=0x%08x want=0x%08x ch_rel=0x%08x after %u ms)\n", nw_attempts, @@ -22693,7 +22707,7 @@ static int gsp_phys_rmcall_stage4(void __iomem *bar0) gsp_phys_status_drain(NULL); return -ETIMEDOUT; } - msleep(GSP_PHYS_RMCALL_POLL_MS); + gsp_phys_rmcall_wait_quantum(); } if (memcmp(gsp_phys_chunk_page_va(src, 0), diff --git a/kernel/gsp_sema_service.c b/kernel/gsp_sema_service.c index 9c72b4b..3a24550 100644 --- a/kernel/gsp_sema_service.c +++ b/kernel/gsp_sema_service.c @@ -681,6 +681,18 @@ static u8 svc_guest_reset_req; /* m177: guest RM reload; wiped on svc thread */ static u8 svc_sess_flush_forced; /* execute the next flush past the live-channel skip * (ISSUE-0002 client-session boundary aid; see * gsp_sema_service_sess_flush_force) */ +/* + * SESSION 148 perf tracing: sema_trace_h selects one channel handle; the + * pump then logs a compact state line for it once a second, and + * svc_counter_publish logs why it skipped (last_get gate / arming gate) or + * the value it wrote. This is the instrument for locating the 22.4 s/frame + * glxgears pacer without guessing at windows. + */ +unsigned long long gsp_sema_trace_h; +module_param_named(sema_trace_h, gsp_sema_trace_h, ullong, 0644); +MODULE_PARM_DESC(sema_trace_h, + "Trace one channel handle (0x...; 0=off): 1/s state + publish gates"); +static unsigned long svc_perf_last; static u8 svc_sess_active; /* a channel of a session has registered (until flush) */ static u32 svc_sess_gen; /* m176: bumped by every executed session flush; * stamps channels/scrubbers so per-session learned @@ -993,6 +1005,8 @@ struct sema_svc { u64 entry_norel_log; u64 ops_denied; /* work refused: implausible stream */ u64 false_trans; /* resolvable VA mapped to non-push */ + u64 rescue_map_ok; /* SESSION 148: content-verified + * map-rescue successes (GR + CE) */ u64 sem_write_reresolve; /* writes re-resolved after read-back */ u64 pool_alt_applied; /* pool releases fanned to a * displaced pin (ISSUE-0002) */ @@ -18192,6 +18206,65 @@ static int svc_rescue_push_page(struct nv_vgpu_device *vgpu, u64 cand[SVC_MBUF_MAX], cand_va[SVC_MBUF_MAX]; u32 ncand = 0, i; + /* + * SESSION 148 perf (measured on r843): content-verified full-chain + * rescue, usable by GR channels too. The CE-only gate below refused + * every GR push outright, yet the same svc_lookup the diagnostic + * probe uses resolves the stalled entries correctly (X's frame + * pushes at 0x120000514 -> vidmem shadow pa=0x200514 with plausible + * stream content) while the pump's own read went through a stale + * shadowing translation, failed plausibility, and skipped the entry + * - one full retry window per push, the measured 22.4 s/frame + * glxgears cadence. Resolve via svc_lookup, verify the bytes parse + * as a method stream, then pin the verified page so the pump's + * re-read lands on it. Cheap: one chain lookup + one page read. + */ + if (entry_va && entry_len && entry_len <= SEMA_PAGE_SIZE) { + u64 mpa = 0; + int map = SVC_APERTURE_SYS; + u8 *vb = kmalloc(entry_len, GFP_KERNEL); + int lrc = -ENOMEM, rrc = -ENOMEM; + bool plaus = false; + + if (vb) { + lrc = svc_lookup(vgpu, entry_va, &mpa, &map); + if (!lrc) + rrc = svc_read_ap(vgpu, mpa, map, vb, + entry_len); + if (!rrc) + plaus = svc_method_stream_plausible(vb, + entry_len); + if (gsp_sema_trace_h && + (u32)ch->h_object == (u32)gsp_sema_trace_h && + time_after(jiffies, svc_perf_last)) { + svc_perf_last = jiffies + HZ; + pr_info("sema-perf: maprescue h=0x%x va=0x%llx len=%u lookup=%d pa=0x%llx ap=%d read=%d plaus=%d\n", + ch->h_object, entry_va, entry_len, + lrc, mpa, map, rrc, plaus); + } + if (!lrc && !rrc && plaus) { + svc_pin_store(entry_va & + ~(u64)(SEMA_PAGE_SIZE - 1), + mpa & + ~(u64)(SEMA_PAGE_SIZE - 1), + map); + svc_lat_store(entry_va & + ~(u64)(SEMA_PAGE_SIZE - 1), + mpa & + ~(u64)(SEMA_PAGE_SIZE - 1), + map); + svc.rescue_map_ok++; + if (svc.rescue_map_ok <= 8) + pr_info("sema-svc: rescue via map h=0x%x va=0x%llx -> pa=0x%llx ap=%d (verified stream)\n", + ch->h_object, entry_va, mpa, + map); + kfree(vb); + return 0; + } + kfree(vb); + } + } + /* * The matcher needs only the channel rank (slot) and the release-push * shape; it does NOT need the pool semaphore translation that @@ -18496,6 +18569,16 @@ static void svc_counter_publish(struct nv_vgpu_device *vgpu, */ u64 pa = ch->release_pa ? ch->release_pa : ch->counter_pa; + if (gsp_sema_trace_h && (u32)ch->h_object == (u32)gsp_sema_trace_h && + time_after(jiffies, svc_perf_last)) { + svc_perf_last = jiffies + HZ; + pr_info("sema-perf: pub h=0x%x put=%u last=%u armed=%d pa=0x%llx cnt=%u gate=%s\n", + ch->h_object, put, (u32)ch->last_get, ch->gr_pub_armed, + pa, ch->counter_last, + !pa ? "no-pa" : + (ch->last_get != put) ? "outstanding" : + (!ch->gr_pub_armed ? "unarmed" : "publish")); + } if (!pa) return; /* @@ -26893,8 +26976,23 @@ static void svc_pump_channels(struct nv_vgpu_device *vgpu) svc_fwd_hold.ch_handle == ch->h_object) && !svc_read_ap(vgpu, ch->userd_pa + SVC_USERD_GP_PUT, - ch->userd_as, &pput, sizeof(pput))) + ch->userd_as, &pput, sizeof(pput))) { + if (gsp_sema_trace_h && + (u32)ch->h_object == + (u32)gsp_sema_trace_h && + time_after(jiffies, svc_perf_last)) { + svc_perf_last = jiffies + HZ; + pr_info("sema-perf: pass h=0x%x pput=%u last=%u armed=%d cnt=%u sub=%llu held=%llu starved=%llu\n", + ch->h_object, pput, + (u32)ch->last_get, + ch->gr_pub_armed, + ch->counter_last, + ch->submissions, + svc.gpfifo_held, + svc.gpfifo_starved); + } svc_counter_publish(vgpu, ch, pput); + } } /* @@ -28978,6 +29076,31 @@ static void svc_pump_channels(struct nv_vgpu_device *vgpu) svc_entry_outcome("unread", ch, idx, va, len); svc_log_stalled_va(va); + /* + * GR stale-skip clock: the + * rescue-failure skip gate below + * requires defer_since, yet every + * GR arming site is gated on a + * nonzero expected_sem_payload. A + * zero-expectation GR entry (its + * release was already delivered) + * therefore never satisfied the + * gate and was re-read on every + * pass while the channel ring + * stalled behind it (live + * evidence: one 96-byte entry + * re-read 362 times over ~18 s; + * ~8 s of ring stall per frame + * with frames at 0.045 FPS). Arm + * the clock at first sighting; the + * skip window itself stays + * governed by gsp_sema_gr_grace_ms. + */ + if (!ch->engine_type && + !ch->expected_sem_payload && + !ch->defer_since) + ch->defer_since = jiffies - + msecs_to_jiffies(gsp_sema_gr_grace_ms + 1); /* * Open the cheap-wait window * for this entry (see the -- cgit v1.2.3