Name the queue lock's long holders under NX2NAVI_LOCK_TIME, and time each swapchain rebuild's hold of it.

With lock_time = 1 the 0.10.0 session showed flip_locked waiting up to 48.61 ms for the queue lock, and the replay's
queue_submit up to 8.05 ms. Nothing named who held it: only vk_texture.c's lock records its holders. A swapchain
rebuild holds the lock across vkDeviceWaitIdle and the create, and that hold was not timed either.

vk_queue_lock, vk_queue_lock_raw and vk_queue_trylock_raw are no longer inlined. Each takes the lock with
plat_rmutex_lock_at and its own return address, so the wait report keeps naming the caller (before, the inlined call
named a site inside flip_locked). At the outermost take, with lock_time on, the holder's site and the time are noted.
vk_queue_unlock passes a hold of 5 ms or more to perf.c perf_qlock_hold. The frame-time summary then prints "queue lock
held 5 ms or more" beside the texture lock's holds, by site, as the waits are. create_swapchain logs how long a
successful rebuild took: the wait for the lock, the hold, and the part spent waiting for the device to idle. It logs
the first 16 rebuilds and each doubling of their count.

Diagnostics only: the counters are behind NX2NAVI_LOCK_TIME, which is off by default, plus one capped line per
rebuild. Checks that passed: pass_cc_check on every runtime file (host.h changed), no new -Wall -Wextra warnings in
gfx_present.c and perf.c, stutter_hitch_check, pgo_build_test, sync_hw_check.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

runtime/gfx_present.c

@@ -42,14 +42,42 @@
 // ---- queue lock
 // Taking it hands the replay's held submissions to the queue first (vk_sync.c, submit batching), so whatever the
 // holder submits or waits for comes after them in queue order.
+// NX2NAVI_LOCK_TIME also names who holds it: a hold of QL_HOLD_NS or more goes into the frame-time summary under the
+// site that took the lock (perf.c perf_qlock_hold), beside the waits for it. A present had waited 48 ms for the lock
+// with no holder named anywhere. The taking functions are not inlined, so that their return address is the caller's
+// site, which is also the site the waits are reported under (plat_rmutex_lock_at). ql_site and ql_t0 are written by
+// the holder only, at the outermost take and release.
+#define QL_HOLD_NS 5000000ull
 static PlatRMutex g_ql;
-void vk_queue_lock(void) {
-    plat_rmutex_lock(&g_ql);
+static void *ql_site;
+static uint64_t ql_t0;
+static void ql_taken(void *site) {
+    if (g_ql.depth == 1 && perf_lock_holds_on()) ql_t0 = plat_now_ns(), ql_site = site;
+}
+__attribute__((noinline)) void vk_queue_lock(void) {
+    void *site = __builtin_return_address(0);
+    plat_rmutex_lock_at(&g_ql, site);
+    ql_taken(site);
     vk_sync_flush_held();
 }
-void vk_queue_lock_raw(void) { plat_rmutex_lock(&g_ql); }
-int vk_queue_trylock_raw(void) { return plat_rmutex_trylock(&g_ql); }
-void vk_queue_unlock(void) { plat_rmutex_unlock(&g_ql); }
+__attribute__((noinline)) void vk_queue_lock_raw(void) {
+    void *site = __builtin_return_address(0);
+    plat_rmutex_lock_at(&g_ql, site);
+    ql_taken(site);
+}
+__attribute__((noinline)) int vk_queue_trylock_raw(void) {
+    if (!plat_rmutex_trylock(&g_ql)) return 0;
+    ql_taken(__builtin_return_address(0));
+    return 1;
+}
+void vk_queue_unlock(void) {
+    if (g_ql.depth == 1 && ql_t0) {
+        uint64_t d = plat_now_ns() - ql_t0;
+        ql_t0 = 0;
+        if (d >= QL_HOLD_NS) perf_qlock_hold(ql_site, d);
+    }
+    plat_rmutex_unlock(&g_ql);
+}
 
 // ---- window state shared with the back end
 static VkSurfaceKHR g_surface;
@@ -448,8 +476,13 @@ static int create_swapchain(void) {
     if (caps.maxImageCount && count > caps.maxImageCount) count = caps.maxImageCount;
     if (count > most) count = most;
 
+    // A rebuild holds the queue lock across the device's idle wait and the create, and every submission waits behind
+    // it: the made swapchain's line says how long (the first 16 and each doubling of the count).
+    const uint64_t t_ask = plat_now_ns();
     vk_queue_lock();
+    const uint64_t t_held = plat_now_ns();
     vkDeviceWaitIdle(c->device);
+    const uint64_t t_idle = plat_now_ns();
     vk_lowlat_swapchain(VK_NULL_HANDLE, 0);   // NVIDIA's low-latency calls name the swapchain: none while it is replaced
     VkSwapchainKHR old = g_sc;
     VkSwapchainCreateInfoKHR ci = {
@@ -555,6 +588,15 @@ static int create_swapchain(void) {
         if (vkCreateImageView(c->device, &vi, NULL, &g_sc_view[i]) != VK_SUCCESS) g_sc_view[i] = VK_NULL_HANDLE;
     }
     free_capture();
+    {
+        static uint32_t n_made;
+        const uint64_t t_end = plat_now_ns();
+        if (++n_made <= 16 || !(n_made & (n_made - 1)))
+            rt_log("gfx: swapchain %ux%u made in %.1f ms: %.1f ms waiting for the queue lock, then the lock held "
+                   "%.1f ms (%.1f ms of it waiting for the device to idle); %u made so far", ext.width, ext.height,
+                   (t_end - t_ask) / 1e6, (t_held - t_ask) / 1e6, (t_end - t_held) / 1e6, (t_idle - t_held) / 1e6,
+                   n_made);
+    }
     vk_queue_unlock();
     return 1;
 }

runtime/host.h

@@ -102,6 +102,7 @@ void perf_replay_cpu(uint64_t ns);   // the replaying thread's CPU time over one
 void perf_lock_timing_here(void);
 int perf_lock_holds_on(void);                   // NX2NAVI_LOCK_TIME
 void perf_lock_hold(void *site, uint64_t ns);   // a lock held ns from site (vk_texture.c, holds over 1 ms)   // NX2NAVI_LOCK_TIME: this thread's lock waits go into the frame-time summary
+void perf_qlock_hold(void *site, uint64_t ns);  // the queue lock held ns from site (gfx_present.c, 5 ms or more)
 extern void (*perf_rec_waits)(uint64_t *full_ns, uint64_t *drain_ns);   // set by the back end (vk_rec.c totals)
 void perf_present(uint64_t frame);
 void perf_cpu_start(void);   // the process's logical processors (NX2NAVI_CACHE_DIE, NX2NAVI_ONE_PER_CORE), at start

runtime/perf.c

@@ -516,6 +516,7 @@ static uint64_t summary_t0;   // start of the current period (0: not started)
 #define LT_N 512
 static struct { void *site; uint64_t ns, n, max, ns0, n0; } lt[LT_N];
 static struct { void *site; uint64_t ns, n, max, ns0, n0; } lh[LT_N];   // texture lock holds over 1 ms (perf_lock_hold)
+static struct { void *site; uint64_t ns, n, max, ns0, n0; } lq[LT_N];   // queue lock holds of 5 ms or more (perf_qlock_hold)
 static uint64_t lt_lost_ns, lt_rec0[2];
 static volatile int64_t fr_hold_ns;   // the texture lock's holds over 1 ms since the last present (ft_frame)
 void (*perf_rec_waits)(uint64_t *full_ns, uint64_t *drain_ns);
@@ -541,6 +542,7 @@ void perf_lock_hold(void *site, uint64_t ns) {
     lt_add((typeof(lt[0]) *)lh, site, ns);
     plat_add64(&fr_hold_ns, (int64_t)ns);
 }
+void perf_qlock_hold(void *site, uint64_t ns) { lt_add((typeof(lt[0]) *)lq, site, ns); }
 
 static int lt_on = -1;
 int perf_lock_holds_on(void) {
@@ -582,7 +584,8 @@ static uint64_t lt_top(typeof(lt[0]) *tab, char *line, int *n, size_t cap, uint6
     return all;
 }
 
-// The lock lines of a summary: the replay threads' waits with the recorder's, then the texture lock's long holds.
+// The lock lines of a summary: the replay threads' waits with the recorder's, then the texture lock's and the queue
+// lock's long holds.
 static void lt_report(void) {
     uint64_t rec[2] = {0, 0}, waits, holds;
     if (perf_rec_waits) perf_rec_waits(&rec[0], &rec[1]);
@@ -598,6 +601,11 @@ static void lt_report(void) {
     snprintf(line, sizeof line, "frametime:   texture lock held over 1 ms: %.0f ms (%llu holds):%s", all / 1e6,
              (unsigned long long)holds, top);
     rt_log("%s", line);
+    n = 0, top[0] = 0;
+    all = lt_top((typeof(lt[0]) *)lq, top, &n, sizeof top, &holds);
+    snprintf(line, sizeof line, "frametime:   queue lock held 5 ms or more: %.0f ms (%llu holds):%s", all / 1e6,
+             (unsigned long long)holds, top);
+    rt_log("%s", line);
     lt_rec0[0] = rec[0], lt_rec0[1] = rec[1], lt_lost_ns = 0;
 }