diff --git a/docs/architecture.md b/docs/architecture.md index 23c3f05a..562902cc 100644 --- a/docs/architecture.md +++ b/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`). diff --git a/docs/building.md b/docs/building.md index c6c0e9d8..712165bf 100644 --- a/docs/building.md +++ b/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 diff --git a/nx2navi.ini.example b/nx2navi.ini.example index 79597f85..59ea5c3f 100644 --- a/nx2navi.ini.example +++ b/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. diff --git a/runtime/logq.c b/runtime/logq.c index 055e4139..147fd6f3 100644 --- a/runtime/logq.c +++ b/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 @@ -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(); diff --git a/tests/logq_check.c b/tests/logq_check.c index fdc15405..a11b89f8 100644 --- a/tests/logq_check.c +++ b/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 ` and `logq_check fatal `, 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, ¬es) == 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, ¬es) == 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, ¬es) == 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 diff --git a/tests/logq_check.py b/tests/logq_check.py index c59b36bf..1520f507 100644 --- a/tests/logq_check.py +++ b/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__':