Log the GPU's timed parts of a frame whose render thread waited 20 ms or more for fences.

In the 2026-11-13 session frames of 60-96 ms came 2 to 6 frames after each area load with the render thread waiting 59-86 ms for the GPU, and no line said what the GPU was doing. With trace = perf such a frame now gets a line at the next present: the timed parts that ended in its interval, their GPU time, the longest gap between two, and the longest parts with their kind (draws, copies into VRAM mirrors, pre-passes, uploads, presents) and their time in the queue. The completion thread keeps the last parts in a ring as it reads their timestamps; nothing waits for the GPU. Measurement only.

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

runtime/perf.c

@@ -592,6 +592,9 @@ static void ft_report(uint64_t now, const char *tag) {
 }
 
 __attribute__((weak)) void gfx_exit_log(void) {}
+__attribute__((weak)) void vk_gpu_parts_log(uint64_t frame, uint64_t t0, uint64_t t1, double fence_ms) {
+    (void)frame, (void)t0, (void)t1, (void)fence_ms;
+}
 __attribute__((weak)) void vk_mem_rank_log(const char *when) { (void)when; }
 
 // The session's reports when the window loses the focus in play: the frame-time summary of the period so far (which
@@ -946,6 +949,13 @@ void perf_present(uint64_t frame) {
     MarkSums fm;
     mark_frame(&fm);
     seg_frame(frame, now, last ? d : 0, &fm);
+    // A frame whose render thread waited 20 ms or more for GPU fences: at the next present, the GPU's timed parts that
+    // ended in its interval (vk_sync.c vk_gpu_parts_log), read then, so that the completion thread has read them.
+    static uint64_t parts_frame, parts_t0, parts_t1;
+    static double parts_fence;
+    if (parts_frame) vk_gpu_parts_log(parts_frame, parts_t0, parts_t1, parts_fence), parts_frame = 0;
+    if (last && frame_ns[PERF_FENCE] >= 20000000ull)
+        parts_frame = frame, parts_t0 = plat_now_ns() - d, parts_t1 = plat_now_ns(), parts_fence = frame_ns[PERF_FENCE] / 1e6;
     if (last) {
         sum += d;
         n++;

runtime/vk.h

@@ -948,6 +948,9 @@ VkCommandBuffer vk_sync_cut(void);
 // sub_ns (plat_now_ns), its timestamps start and end (ticks of the graphics queue). vk_gtl_log: the gaps of the pieces
 // noted since the last call, over frames frames, in the log.
 enum { GTL_PART, GTL_MIRROR, GTL_PRE, GTL_UPLOAD, GTL_PRESENT, GTL_KINDS };
+// NX2NAVI_TRACE=perf: the timed GPU parts that ended in [t0, t1] (plat_now_ns), the interval of a frame whose render
+// thread waited fence_ms for fences (perf.c perf_present), in one line (vk_sync.c)
+void vk_gpu_parts_log(uint64_t frame, uint64_t t0, uint64_t t1, double fence_ms);
 void vk_gtl_note(int kind, uint64_t sub_ns, uint64_t start_tick, uint64_t end_tick);
 void vk_gtl_log(uint64_t frame, int frames);
 extern int vk_sub_in_frame;   // replay: the submission being recorded is the frame's n-th (0 the first; vk_backend.c)

runtime/vk_sync.c

@@ -670,6 +670,14 @@ static void ts_submitted(const VkCommandBufferSubmitInfo *cbi, uint32_t ncb) {
     ts_n_unsent = 0;
 }
 
+// The last timed parts, for the line of a frame whose render thread waited long for the GPU (vk_gpu_parts_log): with
+// calibrated timestamps, each part's submit, GPU start and end (plat_now_ns) and its kind (vk.h GTL_*). Written by the
+// completion thread alone, in submission order; a reader takes the newest PART_RING / 2 entries, which the writer does
+// not reach before it has read them unless the GPU ends that many parts meanwhile.
+#define PART_RING 512
+static struct { int64_t sub, sn, en; int kind; } part_ring[PART_RING];
+static volatile uint64_t part_n;
+
 static void ts_read_cb(void *arg) {   // completion thread, in submission order
     TsRead *t = arg;
     VkCtx *c = vk_ctx();
@@ -691,6 +699,10 @@ static void ts_read_cb(void *arg) {   // completion thread, in submission order
                 if (en > ts_last_end_ns) ts_last_end_ns = en;
                 int64_t q = (int64_t)ts_queue_ns[t->pair];
                 vk_gtl_note_ns(t->mirror, sub, q ? q : sub, sn, en);
+                uint64_t pn = __atomic_load_n(&part_n, __ATOMIC_RELAXED);
+                part_ring[pn % PART_RING].sub = sub, part_ring[pn % PART_RING].sn = sn;
+                part_ring[pn % PART_RING].en = en, part_ring[pn % PART_RING].kind = t->mirror;
+                __atomic_store_n(&part_n, pn + 1, __ATOMIC_RELEASE);
             }
             uint64_t from = s > ts_last_end ? s : ts_last_end;
             if (e > from) {
@@ -708,6 +720,46 @@ static void ts_read_cb(void *arg) {   // completion thread, in submission order
     free(t);
 }
 
+// NX2NAVI_TRACE=perf (perf.c): a frame whose render thread waited 20 ms or more for GPU fences gets, at the next
+// present, a line of the timed parts that ended in its interval [t0, t1]: how many, the GPU time they took, the
+// longest ones with their kind and the time they waited in the queue, and the longest gap between two. In a session of
+// 2026-11-13 frames of 60-96 ms followed each area load by 2 to 6 frames, the render thread waiting 59-86 ms for the
+// GPU, and no line said which work the GPU did then. Read from the ring the completion thread fills: nothing here
+// waits for the GPU.
+void vk_gpu_parts_log(uint64_t frame, uint64_t t0, uint64_t t1, double fence_ms) {
+    static uint32_t logged;
+    if (logged >= 400) return;
+    uint64_t n = __atomic_load_n(&part_n, __ATOMIC_ACQUIRE), from = n > PART_RING / 2 ? n - PART_RING / 2 : 0;
+    struct { int64_t ns, q; int kind; } top[6] = {{0}};
+    static const char *const kn[GTL_KINDS] = {"part", "mirror copies", "pre-pass", "uploads", "present"};
+    uint64_t parts = 0, busy = 0, gap = 0;
+    int64_t prev_end = 0;
+    for (uint64_t i = from; i < n; i++) {
+        const typeof(part_ring[0]) *p = &part_ring[i % PART_RING];
+        if (p->en < (int64_t)t0 || p->en > (int64_t)t1 || p->en < p->sn) continue;
+        int64_t ns = p->en - p->sn, q = p->sub && p->sn > p->sub ? p->sn - p->sub : 0;
+        parts++, busy += (uint64_t)ns;
+        if (prev_end && p->sn > prev_end && (uint64_t)(p->sn - prev_end) > gap) gap = (uint64_t)(p->sn - prev_end);
+        if (p->en > prev_end) prev_end = p->en;
+        for (int k = 0; k < 6; k++)
+            if (ns > top[k].ns) {
+                memmove(&top[k + 1], &top[k], sizeof top[0] * (size_t)(5 - k));
+                top[k].ns = ns, top[k].q = q, top[k].kind = p->kind;
+                break;
+            }
+    }
+    if (!parts) return;
+    logged++;
+    char line[700];
+    int o = snprintf(line, sizeof line, "perf: frame %llu: the GPU's timed parts that ended while the render thread waited "
+                     "%.1f ms for fences: %llu parts, %.1f ms of GPU time, the longest gap between two %.1f ms; the longest:",
+                     (unsigned long long)frame, fence_ms, (unsigned long long)parts, busy / 1e6, gap / 1e6);
+    for (int k = 0; k < 6 && top[k].ns && o < (int)sizeof line - 80; k++)
+        o += snprintf(line + o, sizeof line - (size_t)o, "%s %.1f ms (%s, %.1f ms in the queue)", k ? "," : "",
+                      top[k].ns / 1e6, top[k].kind >= 0 && top[k].kind < GTL_KINDS ? kn[top[k].kind] : "?", top[k].q / 1e6);
+    rt_log("%s", line);
+}
+
 // ---- frame timeline
 // NX2NAVI_GPU_TIMELINE=<frame>: from that presented frame on, TL_FRAMES frames of what the CPU and the GPU did go to the
 // log once they are complete, in milliseconds from the first of those presents: each replay's begin and end and its