Gather the log lines of a quarter of a second and write them at once.

The log thread wrote as soon as it woke, which outside a burst is once for every line: each line woke it and was a write of its own to the log file and the console. It now waits a quarter of a second from the first line it finds, or until the queue is half full, and writes what was queued by then at once, so the log is up to that much behind the game. What is being gathered stays in the queue, so a fatal error, a crash report and an exit write it out before their own lines as before; a game ended from outside loses those last lines. The queue's test checks the gathering, the half-full write and that a process which ends at once, by an exit or as a fatal error does, leaves every line in its file.

Co-Authored-By: Claude Fable 5.2 <noreply@anthropic.com>

docs/architecture.md

@@ -41,10 +41,11 @@ from other projects, with its license, is listed in [THIRD_PARTY_NOTICES.md](../
   variables and written back when the in-game menu changes it. The menu and the performance overlay are Dear ImGui,
   drawn into the swapchain image (`runtime/ui/`); their text is in `ui_text.c`.
 - Log: in a game run the lines go through a queue to a thread that writes them (`runtime/logq.c`), so a stalled
-  write to the log file or the console does not hold the thread that logged. A thread's lines reach the log in the
-  order it logged them: a line waits for the queue's lock, and one that finds the queue full is written after
-  everything queued before it. A fatal error, the crash report and the end of the process write the queue out first
-  (`rt_log_sync`). `NX2NAVI_LOG_ASYNC=0` writes each line where it is logged.
+  write to the log file or the console does not hold the thread that logged. The log thread gathers the lines of
+  a quarter of a second, or half a queue, into one write, so the log is up to that much behind the game. A thread's
+  lines reach the log in the order it logged them: a line waits for the queue's lock, and one that finds the queue
+  full is written after everything queued before it. A fatal error, the crash report and the end of the process write
+  the queue out first (`rt_log_sync`). `NX2NAVI_LOG_ASYNC=0` writes each line where it is logged.
 - Co-op (`coop.c`, `coop_proto.c`, [coop.md](coop.md)): a host thread with a UDP socket to a relay (`tools/coop_relay.py`),
   rooms of up to 8 players and a channel for messages between them; it never holds a virtual core.
 - OS calls the host makes go through `runtime/platform/` (`platform.h`, `win32.c`).

docs/building.md

@@ -373,9 +373,14 @@ A change to the log queue (`runtime/logq.c`) passes `python tests\logq_check.py`
 layer and a destination of its own: 160,000 lines from eight threads arrive whole and in each thread's order, a line
 logged while the queue's lock is taken waits and does not pass the lines queued before it, a destination that takes
 30 ms a write does not hold the threads that log, the line about slow writes comes once in ten seconds, a destination
-that stops while four times the queue's size is logged loses nothing, and `logq_sync` returns with everything written.
-The test passes on a busy machine too: it waits for the queue to empty instead of for a time, and counts slow lines
-instead of timing one. No game files.
+that stops while four times the queue's size is logged loses nothing, lines logged together are written in one write
+a quarter of a second after the first and not before, a queue that is half full is written at once, and `logq_sync`
+returns with everything written, the lines the log thread was still gathering included. The program then runs twice
+more as a process that logs 200 lines to a file and ends at once, by an exit and as a fatal error does: each file
+holds every line, and the fatal line last.
+The test passes on a busy machine too: it waits for the queue to empty instead of for a time, counts slow lines
+instead of timing one, leaves out a check its own thread was too late for, and tries the half-full write three times.
+No game files.
 
 A change to the button prompts (`tools/make_romfs_patches.py --prompts`, `tools/button_icons.py`) passes
 `.venv-py314\Scripts\python tests\romfs_prompts_test.py`, which runs the tool on a RomFS it makes itself (no game

nx2navi.ini.example

@@ -874,9 +874,11 @@
 # sync_wake_all = 0
 # 1 (default): a thread of its own writes the log lines, to the log file and the console, so a write that stalls (a
 # busy disk, a virus scanner, a console that scrolls) no longer holds the thread that logged, which is often the one
-# that draws the frame. A crash, a fatal error and the end of the game write out what is still queued first. 0: each
-# line is written by the thread that logs it, as before. Either way a "log: ... writes of the log took over 2 ms" line
-# counts the slow writes and says whose time they took.
+# that draws the frame. It writes the lines of a quarter of a second together, sooner when many are waiting, so the
+# log file and the console are up to that much behind the game. A crash, a fatal error and the end of the game write
+# out what is still queued first; a game that is ended from outside (Task Manager) loses those last lines. 0: each
+# line is written at once by the thread that logs it, as before. Either way a "log: ... writes of the log took over
+# 2 ms" line counts the slow writes and says whose time they took.
 # log_async = 1
 # 1: the frame-time summary also splits the replay by op kind (draw, bind, transfer), which says where a stalled frame
 # went. The clock reads cost a fraction of a millisecond a frame, so it is off by default.

runtime/logq.c

@@ -11,6 +11,15 @@
 // and turns the queue off for the rest of the run: a fatal error, the crash report and the end of the process call it
 // (rt_log_sync), so no line is lost to an exit and their own lines are written as they are made.
 //
+// The log thread gathers before it writes (log_main): from the first line it finds it waits LOGQ_GATHER_NS, or until
+// the queue is half full (LOGQ_GATHER_BYTES), and then writes everything queued by then in one write. It used to
+// write as soon as it woke, which outside a burst is once for every line: the thread that logged woke the log thread
+// for each, and each was a write of its own to every destination. The price is that the log file and the console are
+// up to LOGQ_GATHER_NS behind the game. The lines being gathered are in the queue like any others, so logq_sync
+// writes them too, and a fatal error, a crash report and an exit still lose none. A process that is ended from
+// outside runs no code of ours and loses what was gathered at that moment; it used to lose only the lines the log
+// thread had not reached yet.
+//
 // Every write is timed. One that took LOGQ_SLOW_NS or longer is counted, and a line says so at most every ten
 // seconds: with the queue that time was the log thread's, without it (NX2NAVI_LOG_ASYNC=0) the logging thread's.
 #include <stdlib.h>
@@ -21,6 +30,8 @@
 #include "platform/platform.h"
 
 #define LOGQ_CAP (1u << 20)
+#define LOGQ_GATHER_NS 250000000ull        // log_main: a batch is written this long after its first line was found ...
+#define LOGQ_GATHER_BYTES (LOGQ_CAP / 2)   // ... or as soon as this much is queued
 #define LOGQ_SLOW_NS 2000000ll
 #define LOGQ_SAY_NS 10000000000ull
 
@@ -97,11 +108,12 @@ static int put(const char *p, size_t n) {
         }
         return 0;
     }
-    int first = !Q.n;
+    // the log thread sleeps until the first line of a batch, and then until the batch fills half the queue (log_main)
+    int wake = !Q.n || (Q.n < LOGQ_GATHER_BYTES && Q.n + n >= LOGQ_GATHER_BYTES);
     memcpy(Q.buf + Q.n, p, n);
     Q.n += n;
     plat_mutex_unlock(&Q.q);
-    if (first) plat_cond_signal(&Q.more);
+    if (wake) plat_cond_signal(&Q.more);
     return 1;
 }
 
@@ -111,11 +123,18 @@ void logq_write(const char *p, size_t n) {
     say_slow();
 }
 
+// The log thread: it sleeps until a line is queued, gathers, and writes the batch (drain). While it gathers it holds
+// no lock, so neither the threads that log nor logq_sync wait for it. The gathering ends when its time is up, when
+// the queue is half full (put signals that), and when the queue is empty again because another thread wrote it: a
+// line that found no room (put), or logq_sync, after which nothing is queued any more and this thread sleeps for good.
 static void log_main(void *arg) {
     (void)arg;
     for (;;) {
         plat_mutex_lock(&Q.q);
         while (!Q.n) plat_cond_wait(&Q.more, &Q.q);
+        for (uint64_t t0 = plat_now_ns(), spent = 0; Q.n && Q.n < LOGQ_GATHER_BYTES && spent < LOGQ_GATHER_NS;
+             spent = plat_now_ns() - t0)
+            plat_cond_wait_ns(&Q.more, &Q.q, LOGQ_GATHER_NS - spent);
         plat_mutex_unlock(&Q.q);
         drain();
         say_slow();

tests/logq_check.c

@@ -115,7 +115,33 @@ static size_t run(Prod *pr, int n, int lines, int pad) {
     return bytes + (size_t)n * (size_t)lines * (size_t)pad;
 }
 
-int main(void) {
+// ---- the end of a process: `logq_check exit <file>` and `logq_check fatal <file>`, which tests/logq_check.py runs
+// after the checks and whose file it reads. The process logs END_LINES lines together, through the queue and into the
+// file, and ends at once, while the log thread is still gathering them: "exit" as a run ends (plat_exit, whose hook is
+// logq_sync, as main.c log_open sets it), "fatal" as a fatal error ends one (dispatch.c fatal_end: logq_sync, then its
+// own line, then _Exit). Every line has to be in the file, and the fatal line after them.
+#define END_LINES 200
+static PlatAppend *end_file;
+static void end_sink(const char *p, size_t n) { plat_append_write(end_file, p, n); }
+static int end_run(const char *how, const char *path) {
+    end_file = plat_append_open(path);
+    if (!end_file) return 3;
+    logq_init(end_sink);
+    plat_exit_hook = logq_sync;
+    if (!logq_async()) return 3;
+    for (int i = 0; i < END_LINES; i++) {
+        char line[64];
+        int n = snprintf(line, sizeof line, "t 0 %d \n", i);
+        logq_write(line, (size_t)n);
+    }
+    if (!strcmp(how, "exit")) plat_exit(0);
+    logq_sync();
+    logq_write("FATAL: the end\n", 15);
+    _Exit(70);
+}
+
+int main(int argc, char **argv) {
+    if (argc == 3) return end_run(argv[1], argv[2]);
     setvbuf(stdout, NULL, _IONBF, 0);
     out = malloc(OUT_CAP);
     if (!out) return 3;
@@ -227,18 +253,67 @@ int main(void) {
     at = out_n;
     for (int i = 0; i < THREADS; i++) next[i] = 0;
 
-    // 7. logq_sync: what is queued is written before it returns, and later lines are written by their own thread.
+    // 7. The log thread gathers: lines logged together are written together, LOGQ_GATHER_NS after the first of them
+    //    and not before. The clock says whether this thread logged its lines and looked at the output within half that
+    //    time; on a machine too busy for that, the two checks that need it are left out.
+    int calls = sink_calls;
+    uint64_t g0 = plat_now_ns();
+    for (int i = 0; i < 20; i++) {
+        char line[64];
+        int n = snprintf(line, sizeof line, "t 0 %d \n", i);
+        logq_write(line, (size_t)n);
+    }
+    size_t early = out_n - at;
+    int in_time = plat_now_ns() - g0 < LOGQ_GATHER_NS / 2;
+    if (in_time) CHECK(!early, "%zu bytes were written before the gathering time was up", early);
+    for (int i = 0; i < 60000 && out_n == at; i++) plat_sleep_ms(1);
+    uint64_t gathered = plat_now_ns() - g0;
+    settle();
+    CHECK(gathered >= LOGQ_GATHER_NS, "a batch was written %.1f ms after its first line, before the gathering time was up",
+          gathered / 1e6);
+    CHECK(check_lines(at, next, &notes) == 20, "lines lost from a gathered batch");
+    if (in_time) CHECK(sink_calls == calls + 1, "%d writes for 20 lines logged together", (int)sink_calls - calls);
+    at = out_n;
+    for (int i = 0; i < THREADS; i++) next[i] = 0;
+
+    // 8. A queue that is half full is written at once, not when the gathering time is up, so a burst that filled one
+    //    half has the other for what it logs next. Each try logs over half the queue's size together and sees how soon
+    //    a write came; on a busy machine the log thread may get its processor late, so one try in three has to show it.
+    int prompt = 0, burst = 0;
+    for (int tries = 0; tries < 3 && !prompt; tries++) {
+        settle();
+        size_t b0 = out_n;
+        uint64_t h0 = plat_now_ns();
+        pr[0] = (Prod){.id = 0, .lines = 2100, .pad = 250, .first = burst};   // 2100 x 260 bytes: 546,000 of 1,048,576
+        producer(&pr[0]);
+        burst += 2100;
+        for (int i = 0; i < 60000 && out_n == b0; i++) plat_sleep_ms(1);
+        prompt = plat_now_ns() - h0 < LOGQ_GATHER_NS / 2;
+    }
+    settle();
+    CHECK(prompt, "a half-full queue was written only when the gathering time was up, three times in a row");
+    CHECK(check_lines(at, next, &notes) == burst, "lines lost at a half-full queue");
+    at = out_n;
+    for (int i = 0; i < THREADS; i++) next[i] = 0;
+
+    // 9. logq_sync: what is queued is written before it returns, and later lines are written by their own thread. The
+    //    lines are logged together just before it, so the log thread is still gathering them (the clock says whether
+    //    this thread was in time for that): the batch a fatal error, a crash or the end of the process finds queued.
     __atomic_store_n(&sink_ms, 20, __ATOMIC_RELEASE);
+    uint64_t s0 = plat_now_ns();
     for (int i = 0; i < 50; i++) {
         char line[64];
         int n = snprintf(line, sizeof line, "t 1 %d \n", i);
         logq_write(line, (size_t)n);
     }
+    early = out_n - at;
+    in_time = plat_now_ns() - s0 < LOGQ_GATHER_NS / 2;
     logq_sync();
     __atomic_store_n(&sink_ms, 0, __ATOMIC_RELEASE);
+    if (in_time) CHECK(!early, "%zu bytes were written before logq_sync, inside the gathering time", early);
     CHECK(check_lines(at, next, &notes) == 50, "logq_sync returned before the queued lines were written");
     at = out_n;
-    int calls = sink_calls;
+    calls = sink_calls;
     logq_write("t 2 0 \n", 7);
     CHECK(out_n == at + 7 && sink_calls == calls + 1, "a line after logq_sync was not written at once");
     logq_sync();   // a second call does nothing

tests/logq_check.py

@@ -2,6 +2,9 @@
 platform layer linked and a destination of the test's own. No game files: the module layout the runtime includes is a
 stand-in written to the test's build folder.
 
+After its checks the program is run twice more as a process that logs to a file and ends at once, by an exit and as
+a fatal error does, while the log thread is still gathering its lines (ends): each file has to hold every line.
+
 Usage: logq_check.py
 """
 import os
@@ -45,7 +48,29 @@ def main():
                            '-march=x86-64-v3', '-I', str(rt), '-I', str(work),
                            str(ROOT / 'tests' / 'logq_check.c'), *map(str, plat), '-o', str(exe), '-lm', *libs],
                           env=env)
-    return subprocess.run([str(exe)], env=env, timeout=300).returncode
+    failed = subprocess.run([str(exe)], env=env, timeout=300).returncode
+    return ends(exe, work, env) or failed
+
+
+END_LINES = 200   # tests/logq_check.c END_LINES
+
+
+def ends(exe, work, env):
+    """The end of a process whose lines the log thread is still gathering (tests/logq_check.c end_run): the exit code
+    is the one the process ended with, and its file holds every line it logged, the fatal line last."""
+    bad = 0
+    for how, code in (('exit', 0), ('fatal', 70)):
+        path = work / f'end_{how}.log'
+        path.unlink(missing_ok=True)
+        rc = subprocess.run([str(exe), how, path.name], cwd=work, env=env, timeout=60).returncode
+        want = ''.join(f't 0 {i} \n' for i in range(END_LINES)) + ('FATAL: the end\n' if how == 'fatal' else '')
+        got = path.read_bytes() if path.exists() else b''
+        if rc != code or got != want.encode():
+            print(f'FAIL: a process ended by "{how}": exit code {rc}, want {code}; its log holds {len(got)} bytes, '
+                  f'{"the" if got == want.encode() else "not the"} {len(want)} it logged')
+            bad = 1
+    print(f'logq_check: the end of a process: {"FAILED" if bad else "ok"}')
+    return bad
 
 
 if __name__ == '__main__':