Give the longest lazy fetch and the longest wait of a fault for the freeze lock on the "mem: lazy write-back" line.

A fetch of lazily written pages runs inside the fault handler under frz_lock (memory.c lazy_gone_locked and lazy_piece_fetch_locked call vk_memory.c lazy_fetch, a GPU copy after everything handed over and a wait for it), so every other fault, thaw, freeze and arm waits for the whole copy. The line gave only the fetches' sum: the 0.10.0 session's 848 fetches took 415.8 ms in all, and how long one took, or how long another thread waited behind it, was not known. Both fetch sites now keep the longest fetch, and lazy_fault keeps the longest time a fault waited to take frz_lock; the report line prints them as "the longest X ms, faults waited up to Y ms for the freeze lock" and starts both over. No tool parses the line.

tests\lazy_fetch_check.py's new report scenario fetches for 30 and 120 ms and has a third fault wait 60 ms for frz_lock: the line reads 120.29 ms and 60.03 ms, and the next one 0.00 for both. arm_race, arm_race_slow, wb_lazy_check and heap_lazy_copy_check passed; memory.c compiles without a warning under -Wall -Wextra.

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

docs/building.md

@@ -691,8 +691,9 @@ its reason by platform, by GPU driver and by what the player set. No game files,
 A change to the lazy write-back's arms, faults and releases (`runtime/memory.c` "Lazy write-back") passes
 `python tests\lazy_fetch_check.py`, which builds memory.c with the Windows fault handler and a fetch that only waits,
 and runs each scenario as its own process, so an access violation fails it: a thread that reads a range over and over
-while it is armed and given back again never reaches the crash handler, also when the arm's clean test takes 100 ms.
-Windows only; no game files, no GPU.
+while it is armed and given back again never reaches the crash handler, also when the arm's clean test takes 100 ms;
+and the "mem: lazy write-back" line gives the longest fetch and the longest wait of a fault for the freeze lock since
+the line before. Windows only; no game files, no GPU.
 
 A change to when the freezing of idle guest regions waits (`runtime/freeze_hold.h`, `runtime/vk_memory.c`
 `freeze_pass`) passes `python tests\freeze_hold_check.py`, which builds the header alone: the backoff after a slow

runtime/memory.c

@@ -236,8 +236,10 @@ static uint64_t lz_foreign;             // frz_lock, since the start: segments o
 #define LZ_NOTES 8
 static struct { uint64_t addr, lo, hi, out; uint32_t tid; uint8_t write, stale, hold; } lz_note[LZ_NOTES];
 static int lz_nnote;
-// frz_lock: since the last report: faults by a read, by a write, other releases, fetches, their bytes and time
-static uint64_t lz_faults[2], lz_other, lz_fetches, lz_fetch_bytes, lz_fetch_ns, lz_gaps;
+// frz_lock: since the last report: faults by a read, by a write, other releases, fetches, their bytes and time, the
+// longest fetch, and the longest wait of a fault for frz_lock (behind other threads' fetches, thaws, freezes and arms)
+static uint64_t lz_faults[2], lz_other, lz_fetches, lz_fetch_bytes, lz_fetch_ns, lz_fetch_max_ns, lz_lock_wait_max_ns;
+static uint64_t lz_gaps;
 static volatile uint32_t lz_win_tid;    // lz_lock: the replay thread's id while its part is between check and hand-over
 // For a fatal error's summary line (mem_lazy_note): written under frz_lock and read without it, since the thread that
 // fails may be the one inside a fetch.
@@ -285,7 +287,9 @@ static void lazy_gone_locked(LzSeg s, int why) {
         __atomic_store_n(&lz_fetch_ms, (uint32_t)plat_now_ms() | 1, __ATOMIC_RELAXED);
         __atomic_store_n(&lz_fetch_total, lz_fetch_total + 1, __ATOMIC_RELAXED);
         __atomic_store_n(&lz_fetch_tid, 0, __ATOMIC_RELEASE);
-        lz_fetches++, lz_fetch_bytes += s.hi - s.lo, lz_fetch_ns += plat_now_ns() - t0;
+        uint64_t ns = plat_now_ns() - t0;
+        lz_fetches++, lz_fetch_bytes += s.hi - s.lo, lz_fetch_ns += ns;
+        if (ns > lz_fetch_max_ns) lz_fetch_max_ns = ns;
     }
     for (uint64_t a = s.lo, b; a < s.hi; a = b)
         if (plat_mem_state(a, s.hi, &b) == PLAT_PROT_NONE && !plat_mem_protect(a, b - a, PLAT_PROT_RW))
@@ -364,7 +368,9 @@ static uint64_t lazy_piece_fetch_locked(LzPiece p, uint64_t a, int write) {
         __atomic_store_n(&lz_fetch_ms, (uint32_t)plat_now_ms() | 1, __ATOMIC_RELAXED);
         __atomic_store_n(&lz_fetch_total, lz_fetch_total + 1, __ATOMIC_RELAXED);
         __atomic_store_n(&lz_fetch_tid, 0, __ATOMIC_RELEASE);
-        lz_fetches++, lz_fetch_bytes += c1 - c0, lz_fetch_ns += plat_now_ns() - t0;
+        uint64_t ns = plat_now_ns() - t0;
+        lz_fetches++, lz_fetch_bytes += c1 - c0, lz_fetch_ns += ns;
+        if (ns > lz_fetch_max_ns) lz_fetch_max_ns = ns;
     }
     for (uint64_t x = c0, y; x < c1; x = y)
         if (plat_mem_state(x, c1, &y) == PLAT_PROT_NONE && !plat_mem_protect(x, y - x, PLAT_PROT_RW))
@@ -653,7 +659,10 @@ static int lazy_fault(uint64_t a, int write) {
     if (a >= RT_ADDRESS_LIMIT || !__atomic_load_n(&lzr[a >> FRZ_SHIFT], __ATOMIC_ACQUIRE)) return 0;
     uint32_t me = plat_thread_id();
     for (int tries = 0;; tries++) {
+        uint64_t w0 = plat_now_ns();
         plat_mutex_lock(&frz_lock);
+        uint64_t waited = plat_now_ns() - w0;
+        if (waited > lz_lock_wait_max_ns) lz_lock_wait_max_ns = waited;
         plat_mutex_lock(&lz_lock);   // the window's test and the segment's leaving the list in one step
         int i = 0;
         while (i < lz_n && !(a >= lzs[i].lo && a < lzs[i].hi)) i++;
@@ -745,10 +754,12 @@ void mem_lazy_report(uint64_t frame, uint64_t skipped) {
     if (!__atomic_load_n(&lz_on, __ATOMIC_RELAXED)) return;
     plat_mutex_lock(&frz_lock);
     uint64_t bytes = 0, fr = lz_faults[0], fw = lz_faults[1], other = lz_other, nf = lz_fetches, fb = lz_fetch_bytes,
-             fns = lz_fetch_ns, gaps = lz_gaps, unclean = lz_unclean, no[LZ_NO_N];
+             fns = lz_fetch_ns, fmax = lz_fetch_max_ns, wmax = lz_lock_wait_max_ns, gaps = lz_gaps, unclean = lz_unclean,
+             no[LZ_NO_N];
     int n = lz_n;
     for (int i = 0; i < lz_n; i++) bytes += lzs[i].hi - lzs[i].lo;
     lz_faults[0] = lz_faults[1] = lz_other = lz_fetches = lz_fetch_bytes = lz_fetch_ns = lz_gaps = lz_unclean = 0;
+    lz_fetch_max_ns = lz_lock_wait_max_ns = 0;
     uint64_t small = lz_no_small, calls = lz_arm_calls;
     int nnote = lz_nnote;
     __typeof__(lz_note) note;
@@ -768,10 +779,10 @@ void mem_lazy_report(uint64_t frame, uint64_t skipped) {
     }
     rt_log("mem: lazy write-back at frame %llu: %d ranges armed, %.1f MiB; since the last line %.1f MiB left in the "
            "mirror, %llu read and %llu write faults (%llu inside a part's window), %llu other releases, %llu fetches of "
-           "%.1f MiB in %.2f ms, %llu arms refused (a CPU write not in the mirror yet)", (unsigned long long)frame, n,
-           bytes / 1048576.0, skipped / 1048576.0, (unsigned long long)fr, (unsigned long long)fw,
-           (unsigned long long)gaps, (unsigned long long)other, (unsigned long long)nf, fb / 1048576.0, fns / 1e6,
-           (unsigned long long)unclean);
+           "%.1f MiB in %.2f ms, the longest %.2f ms, faults waited up to %.2f ms for the freeze lock, %llu arms refused "
+           "(a CPU write not in the mirror yet)", (unsigned long long)frame, n, bytes / 1048576.0, skipped / 1048576.0,
+           (unsigned long long)fr, (unsigned long long)fw, (unsigned long long)gaps, (unsigned long long)other,
+           (unsigned long long)nf, fb / 1048576.0, fns / 1e6, fmax / 1e6, wmax / 1e6, (unsigned long long)unclean);
     for (int i = 0; i < nnote && (rt_trace & RT_TRACE_PERF); i++)
         rt_log("mem: lazy write-back: thread %u %s %#llx, %llu KiB into an armed range of %.2f MiB at %#llx; %llu KiB of "
                "it given back%s and held for %u s", note[i].tid, note[i].write ? "wrote" : "read",

tests/lazy_fetch_check.c

@@ -77,6 +77,34 @@ static int fake_clean(uint64_t lo, uint64_t hi, void *ctx) {
 
 // the range [a, a + n) of the heap, as written back from buffer h0 into the heap's own (h1 = heap, offset a - heap)
 static uint64_t arm_buf(uint64_t a, uint64_t n, uint64_t h0) { return mem_lazy_arm(a, n, h0, heap, a - heap, NULL); }
+// the replay leaves its writes to [a, a + n) in the mirror h0: the armed parts there are stale (a touch fetches them)
+static int stale(uint64_t a, uint64_t n, uint64_t h0) {
+    uint64_t out[16][2];
+    return mem_lazy_skip(a, n, h0, -(int64_t)heap, out, 16);
+}
+static double ms(uint64_t t0) { return (plat_now_ns() - t0) / 1e6; }
+// the number after "what" in the last log line, -1 when it is not there
+static double logged(const char *what) {
+    const char *p = strstr(last_log, what);
+    return p ? strtod(p + strlen(what), NULL) : -1;
+}
+
+// ---- threads that touch guest memory, as the game's CPU code does
+typedef struct { uint64_t at; int write; volatile int done; uint8_t got; uint64_t end_ns; double took; } Touch;
+static void toucher(void *arg) {
+    Touch *t = arg;
+    volatile uint8_t *p = (volatile uint8_t *)(uintptr_t)t->at;
+    uint64_t t0 = plat_now_ns();
+    if (t->write) *p = 0x77;
+    t->got = *p;
+    t->end_ns = plat_now_ns();
+    t->took = (t->end_ns - t0) / 1e6;
+    __atomic_store_n(&t->done, 1, __ATOMIC_SEQ_CST);
+}
+static void *touch(Touch *t, uint64_t a, int write) {
+    t->at = a, t->write = write, t->done = 0;
+    return plat_thread_new(toucher, t, "toucher");
+}
 
 static volatile int spin_stop;
 static volatile uint64_t spin_reads;
@@ -116,6 +144,30 @@ int main(int argc, char **argv) {
         plat_thread_join(th);
         CHECK(armed, "nothing was armed");
         printf("  %llu arms, %llu reads\n", (unsigned long long)armed, (unsigned long long)spin_reads);
+    } else if (!strcmp(what, "report")) {
+        // The report line gives the longest fetch since the last line, and the longest wait of a fault for frz_lock;
+        // the next line starts from nothing.
+        uint64_t s1 = heap + (80ull << 20), s2 = heap + (84ull << 20), s3 = heap + (88ull << 20);
+        CHECK(arm_buf(s1, K64, 1) == K64 && arm_buf(s2, K64, 1) == K64 && arm_buf(s3, K64, 1) == K64, "arms");
+        CHECK(stale(s1, K64, 1) == 1 && stale(s2, K64, 1) == 1 && stale(s3, K64, 1) == 1, "stale marks");
+        Touch a;
+        fetch_ns = 30000000ull;
+        plat_thread_join(touch(&a, s1, 0));
+        fetch_ns = 120000000ull;
+        plat_thread_join(touch(&a, s2, 0));
+        fetch_ns = 10000000ull;
+        plat_mutex_lock(&frz_lock);   // another thread's thaw, freeze or arm, 60 ms long
+        void *th = touch(&a, s3, 1);
+        plat_wait_ns(60000000);
+        plat_mutex_unlock(&frz_lock);
+        plat_thread_join(th);
+        CHECK(fetch_calls == 3 && a.got == 0x77, "%d fetches, the write read back %#x", fetch_calls, a.got);
+        mem_lazy_report(1, 0);
+        double longest = logged("the longest "), waited = logged("faults waited up to ");
+        CHECK(longest >= 119 && longest < 200, "the longest fetch read %.2f ms", longest);
+        CHECK(waited >= 40 && waited < 200, "the longest wait for the lock read %.2f ms", waited);
+        mem_lazy_report(2, 0);
+        CHECK(logged("the longest ") == 0 && logged("faults waited up to ") == 0, "the next line did not start over");
     } else {
         printf("unknown scenario %s\n", what);
         return 2;

tests/lazy_fetch_check.py

@@ -20,6 +20,7 @@ MSYS_BIN = Path(r'C:\msys64\ucrt64\bin')
 SCENARIOS = {
     'arm_race': ('arm_race', {}),
     'arm_race_slow': ('arm_race_slow', {}),
+    'report': ('report', {}),
 }