From e3b622ff40dff04bf22d9a250d4488926c68b409 Mon Sep 17 00:00:00 2001 From: Nitnek <5654027+Nitnek@users.noreply.github.com> Date: Mon, 9 Nov 2026 19:44:16 +0100 Subject: [PATCH] feat(vk): time a capture's GPU wait for its late pages apart in the log take_capture waits for the GPU (vk_timeline_wait(c->late_value)) before it copies the pages a submission still on the GPU writes back. That wait was counted in "retires and stamps", so the 600-take log line could not tell the replay thread waiting for the GPU from its own bookkeeping. The wait grows as fewer pools have a VRAM mirror: with RX_VK_MIRROR_MB=1024 on an RTX 3070 it was 1.5-1.8 ms of a 1.7-1.9 ms capture, six captures a frame, and Hyrule Field ran at ~41 fps instead of ~52 (issue 995). The line now reads "all; GPU wait for late pages (takes that waited), pools lock, retires and stamps, bytes copied". "Retires and stamps" starts once pools_mu is held. tests/test_capture_wait_log.py checks the timing and the line. Assisted-by: Claude Code (Claude Opus 5.5) Co-Authored-By: Claude Opus 5.5 --- gpu/vk/vk_memory.cpp | 23 +++++++++++---- tests/test_capture_wait_log.py | 52 ++++++++++++++++++++++++++++++++++ 2 files changed, 69 insertions(+), 6 deletions(-) create mode 100644 tests/test_capture_wait_log.py diff --git a/gpu/vk/vk_memory.cpp b/gpu/vk/vk_memory.cpp index aa0aec2c2..09ea8be70 100644 --- a/gpu/vk/vk_memory.cpp +++ b/gpu/vk/vk_memory.cpp @@ -937,7 +937,8 @@ bool capture_on() { std::atomic captures_seen{false}; std::atomic cap_view_gen{1}; // (bumped when a capture is published or a page is stamped: cached reads go stale) void cap_view_bump() { cap_view_gen.fetch_add(1, std::memory_order_release); } -double st_tk_all, st_tk_stamp, st_tk_copy; // (memory_take_capture's parts, ms) // (a capture was ever made: the replay thread's; without it nothing owns pages) +double st_tk_all, st_tk_stamp, st_tk_copy, st_tk_late, st_tk_lock; // (memory_take_capture's parts, ms) +int64_t st_tk_late_n; // (the takes that waited for the GPU for their late pages) // (a capture was ever made: the replay thread's; without it nothing owns pages) // ---- texture storage in the capture ---- // The textures' storage the replay uploads from joins the capture, and what the capture took of it is kept (the @@ -1498,13 +1499,22 @@ void memory_recording_value(uint64_t value, uint64_t completed) { bool take_capture(std::unique_ptr c, uint64_t value, uint64_t completed) { const auto tk0 = std::chrono::steady_clock::now(); if (c->late_value && c->map) { // (the pages a submission still on the GPU writes back: see capture_make) + // (timed apart: the replay thread waits here for the GPU, the more often the fewer pools have a mirror. With + // RX_VK_MIRROR_MB=1024 on an 8 GB card it was most of a capture's 2.4-3 ms, six submits a frame: Hyrule Field at + // 35-45 fps instead of 55, issue 995) + const auto tw = std::chrono::steady_clock::now(); vk_timeline_wait(c->late_value); + st_tk_late += std::chrono::duration(std::chrono::steady_clock::now() - tw).count(); + st_tk_late_n++; uint8_t* const base = (uint8_t*)host->guest_base(); for (uint32_t i : c->late) guarded_copy((uint8_t*)c->map + (uint64_t)i * 4096, base + ((uint64_t)c->pages[i] << kPageShift), 4096); flush_mapped(c->alloc, c->nbytes); } + const auto tl = std::chrono::steady_clock::now(); std::lock_guard lk(pools_mu); + const auto tk_locked = std::chrono::steady_clock::now(); + st_tk_lock += std::chrono::duration(tk_locked - tl).count(); cur_cap_value = value; cur_cap_gen = 0; // (captures past the last kKeep, or past the byte budget, retired once the work that read them is done) @@ -1583,14 +1593,15 @@ bool take_capture(std::unique_ptr c, uint64_t value, uint64_t completed { // (every 600 takes: where a take's time went) const auto tk2 = std::chrono::steady_clock::now(); static int64_t n; - st_tk_stamp += std::chrono::duration(tk1 - tk0).count(); + st_tk_stamp += std::chrono::duration(tk1 - tk_locked).count(); st_tk_all += std::chrono::duration(tk2 - tk0).count(); if (++n % 600 == 0) { - logf("vk: a capture taken (ms): all %.3f; retires and stamps %.3f, bytes copied %.3f; %zu kept (%llu MB), %zu " - "spare buffers, %zu texture pages copied (%llu MB)", st_tk_all / 600, st_tk_stamp / 600, st_tk_copy / 600, cap_bufs.size(), - (unsigned long long)(cap_bytes >> 20), cap_free.size(), shadow_n.load(std::memory_order_relaxed), + logf("vk: a capture taken (ms): all %.3f; GPU wait for late pages %.3f (%lld of 600 takes), pools lock %.3f, retires " + "and stamps %.3f, bytes copied %.3f; %zu kept (%llu MB), %zu spare buffers, %zu texture pages copied (%llu MB)", + st_tk_all / 600, st_tk_late / 600, (long long)st_tk_late_n, st_tk_lock / 600, st_tk_stamp / 600, st_tk_copy / 600, + cap_bufs.size(), (unsigned long long)(cap_bytes >> 20), cap_free.size(), shadow_n.load(std::memory_order_relaxed), (unsigned long long)(shadow_n.load(std::memory_order_relaxed) >> 8)); - st_tk_all = st_tk_stamp = st_tk_copy = 0; + st_tk_all = st_tk_stamp = st_tk_copy = st_tk_late = st_tk_lock = 0, st_tk_late_n = 0; } } return true; diff --git a/tests/test_capture_wait_log.py b/tests/test_capture_wait_log.py new file mode 100644 index 000000000..e315302bd --- /dev/null +++ b/tests/test_capture_wait_log.py @@ -0,0 +1,52 @@ +"""A capture's GPU wait for its late pages is timed apart from its other work, and the 600-take log line names it. + +Before, the wait sat inside "retires and stamps": with a small mirror budget (RX_VK_MIRROR_MB=1024 on an 8 GB card) that +part read 2.4-3 ms a capture, six captures a frame, and nothing said it was the replay thread waiting for the GPU (issue 995). + +python -I -B tests/test_capture_wait_log.py +""" +from pathlib import Path +import re +import unittest + +ROOT = Path(__file__).resolve().parents[1] + + +def block(text, marker): + start = text.index(marker) + end = text.index("{", start) + 1 + depth = 1 + while depth: + depth += (text[end] == "{") - (text[end] == "}") + end += 1 + return text[start:end] + + +class CaptureWaitLogTests(unittest.TestCase): + @classmethod + def setUpClass(cls): + mem = (ROOT / "gpu" / "vk" / "vk_memory.cpp").read_text(encoding="utf-8") + cls.take = block(mem, "bool take_capture(") + + def test_the_late_page_wait_is_timed_on_its_own(self): + late = block(self.take, "if (c->late_value && c->map)") + wait = late.index("vk_timeline_wait(c->late_value);") + self.assertRegex(late[:wait], r"const auto (\w+) = std::chrono::steady_clock::now\(\);") + self.assertIn("st_tk_late +=", late[wait:]) + self.assertIn("st_tk_late_n++", late[wait:]) + + def test_retires_and_stamps_start_after_the_lock(self): + lock = self.take.index("std::lock_guard lk(pools_mu);") + self.assertIn("st_tk_lock +=", self.take[lock:lock + 300]) + self.assertRegex(self.take, r"st_tk_stamp \+= std::chrono::duration\(tk1 - tk_locked\)") + + def test_the_log_line_names_the_wait_and_resets_it(self): + line = re.search(r'logf\("vk: a capture taken \(ms\):.*?\);', self.take, re.S).group(0) + self.assertIn("GPU wait for late pages", line) + self.assertIn("pools lock", line) + self.assertIn("st_tk_late / 600", line) + self.assertRegex(self.take, r"st_tk_late = st_tk_lock = 0, st_tk_late_n = 0;") + + +if __name__ == "__main__": + unittest.main()