feat(vk): time a capture's GPU wait for its late pages apart in the log

gpu/vk/vk_memory.cpp

@@ -937,7 +937,8 @@ bool capture_on() {
 std::atomic<bool> captures_seen{false};
 std::atomic<uint64_t> 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<Capture> 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<double, std::milli>(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<double, std::milli>(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<Capture> 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<double, std::milli>(tk1 - tk0).count();
+        st_tk_stamp += std::chrono::duration<double, std::milli>(tk1 - tk_locked).count();
         st_tk_all += std::chrono::duration<double, std::milli>(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;

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<double, std::milli>\(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()