diff --git a/runtime/gfx_present.c b/runtime/gfx_present.c index a8c1d78d..b4225655 100644 --- a/runtime/gfx_present.c +++ b/runtime/gfx_present.c @@ -118,7 +118,10 @@ static volatile uint32_t exit_tid; // the thread that runs the orderly end, 0 int rt_exit_begin(void) { uint32_t me = plat_thread_id(), was = 0; - if (__atomic_compare_exchange_n(&exit_tid, &was, me, 0, __ATOMIC_ACQ_REL, __ATOMIC_ACQUIRE)) return 1; + if (__atomic_compare_exchange_n(&exit_tid, &was, me, 0, __ATOMIC_ACQ_REL, __ATOMIC_ACQUIRE)) { + rt_log_ending(); // the end's lines reach the log file past its cap (main.c log_sink) + return 1; + } if (was == me) return 0; for (;;) plat_sleep_ms(1000); } diff --git a/runtime/host.h b/runtime/host.h index 0b43c003..06628673 100644 --- a/runtime/host.h +++ b/runtime/host.h @@ -24,6 +24,7 @@ void rt_vlogf(const char *fmt, va_list ap); void rt_log_raw(const char *p, size_t n); const char *rt_log_path(void); // the log file, NULL when this run writes none void rt_log_sync(void); // writes the queued log lines now; later lines are written as they are made +void rt_log_ending(void); // the process is ending: its lines reach the log file past its 64 MiB cap enum { RT_TRACE_SVC = 1, RT_TRACE_HOSTCALL = 2, RT_TRACE_IPC = 4, RT_TRACE_FS = 8, RT_TRACE_GFX = 16, RT_TRACE_PERF = 32, RT_TRACE_SCHED = 64, RT_TRACE_AUDIO = 128, RT_TRACE_PRESENT = 256 }; extern unsigned rt_trace; // from NX2NAVI_TRACE=svc,host,ipc,fs,gfx,perf,sched,audio,present (or all) diff --git a/runtime/main.c b/runtime/main.c index f3567e16..dd8fa6c1 100644 --- a/runtime/main.c +++ b/runtime/main.c @@ -62,8 +62,15 @@ unsigned rt_trace; // `2> file` keep their own file. Each start moves the earlier logs to nx2navi.1.log .. nx2navi.4.log. A file stops at 64 MiB // (NX2NAVI_TRACE can write that much). Lines from before log_open wait in a static buffer: mem_init runs first so that // nothing else lands in the guest address space, and an earlier open would put the CRT's heap there. +// The end of the run still reaches a file past its cap: once the process is ending (rt_log_ending at the start of an +// orderly end, gfx_present.c rt_exit_begin, and of the frame-time summary, perf.c perf_summary_flush; rt_log_sync at a +// fatal error and in the crash report), up to LOG_END_RESERVE more bytes are written, counted on their own. A +// trace = perf session reaches the cap in about 90 minutes, and every line after it, the exit summary, "frametime: +// exit", the stutter map and FATAL lines included, went to stderr only, which a game started from the launcher or +// Explorer does not keep. #define LOG_KEEP 5 #define LOG_CAP (64ull << 20) +#define LOG_END_RESERVE (4ull << 20) enum { LOG_EARLY, LOG_FILE, LOG_OFF }; static int g_log_state; static PlatAppend *g_log_file; @@ -76,6 +83,10 @@ static uint64_t g_log_bytes; // crash report. static PlatMutex g_err_lock = PLAT_MUTEX_INIT; static volatile int32_t g_log_final; +static volatile int32_t g_log_ending; // rt_log_ending ran: the process is ending +static uint64_t g_log_tail; // bytes of the end the file was given past LOG_CAP + +void rt_log_ending(void) { __atomic_store_n(&g_log_ending, 1, __ATOMIC_RELEASE); } // The log's destinations: the file first, then stderr. logq.c calls it: from the log thread in a game run, else from // the thread that logs. A write to stderr can block for as long as its reader likes: a console window holds every write @@ -89,9 +100,21 @@ static void log_sink(const char *p, size_t n) { uint64_t at = __atomic_fetch_add(&g_log_bytes, n, __ATOMIC_RELAXED); if (at + n <= LOG_CAP) { plat_append_write(g_log_file, p, n); - } else if (at <= LOG_CAP) { // the first write past the cap says so, once - static const char cut[] = "[host] log: the file reached 64 MiB, the rest of this run goes to stderr only\n"; - plat_append_write(g_log_file, cut, sizeof cut - 1); + } else { + if (at <= LOG_CAP) { // the first write past the cap says so, once + static const char cut[] = "[host] log: the file reached 64 MiB, the rest of this run goes to stderr only, " + "but for the lines of its end\n"; + plat_append_write(g_log_file, cut, sizeof cut - 1); + } + if (__atomic_load_n(&g_log_ending, __ATOMIC_ACQUIRE) || __atomic_load_n(&g_log_final, __ATOMIC_ACQUIRE)) { + uint64_t t = __atomic_fetch_add(&g_log_tail, n, __ATOMIC_RELAXED); + if (!t) { + static const char end[] = "[host] log: the end of the run follows; the lines between the cap and it " + "were not written to this file\n"; + plat_append_write(g_log_file, end, sizeof end - 1); + } + if (t + n <= LOG_END_RESERVE) plat_append_write(g_log_file, p, n); + } } } // without the file stderr is the log (run_game.py, `2> file`), and it is waited for diff --git a/runtime/perf.c b/runtime/perf.c index c75c9fe9..5b4db880 100644 --- a/runtime/perf.c +++ b/runtime/perf.c @@ -764,6 +764,7 @@ static void session_report(uint64_t now) { __attribute__((weak)) void vk_texstat_frame(uint64_t frame, uint64_t d) { (void)frame, (void)d; } void perf_summary_flush(void) { // at exit (prof_write) + rt_log_ending(); // the summary and the stutter map reach the log file past its cap (main.c log_sink) ft_stop(); if (rt_trace & RT_TRACE_PERF) seg_close(__atomic_load_n(&gfx_counters.frames, __ATOMIC_RELAXED), kern_now_ns(), 1); if (summary_t0) { diff --git a/tests/exit_order_check.py b/tests/exit_order_check.py index f11405ee..434d0a59 100644 --- a/tests/exit_order_check.py +++ b/tests/exit_order_check.py @@ -65,6 +65,8 @@ static char seen[1024]; STEP(fs_save_wait) STEP(rtss_limit_restore) STEP(input_rumble_hd_stop) STEP(vk_pipeline_prewarm_marker_clear) STEP(prof_write) STEP(vk_mem_exit_log) STEP(logq_flush) STEP(vk_pipeline_save_exit) STEP(fs_save_flush) static int cfg_save(void) { strcat(seen, "cfg_save "); return 1; } +static int ending; +static void rt_log_ending(void) { ending++; } ''' MAIN = r''' @@ -95,9 +97,9 @@ int main(int argc, char **argv) { int first = rt_exit_begin(), again = rt_exit_begin(); HANDLE t = CreateThread(NULL, 0, second, NULL, 0, NULL); int parked = WaitForSingleObject(t, 300) == WAIT_TIMEOUT && second_back == -1; - printf("once: first caller %d, its own thread again %d, another thread %s\n", first, again, - parked ? "stays in rt_exit_begin" : "came back"); - if (first != 1 || again != 0 || !parked) printf("FAIL: the end must run once\n"), fails++; + printf("once: first caller %d, its own thread again %d, another thread %s; the log told of the end %d time(s)\n", + first, again, parked ? "stays in rt_exit_begin" : "came back", ending); + if (first != 1 || again != 0 || !parked || ending != 1) printf("FAIL: the end must run once\n"), fails++; // an update under way: ft_stop waits for it; after ft_stop no update starts HANDLE p = CreateThread(NULL, 0, present, (void *)(intptr_t)20, 0, NULL); @@ -156,8 +158,9 @@ def static_checks(): flush = strip_comments(function(perf, 'void perf_summary_flush(void)')) present = strip_comments(function(perf, 'void perf_present(uint64_t frame)')) e, f, s, l = (present.find(x) for x in ('ft_enter()', 'ft_frame(', 'session_report(', 'ft_leave()')) - ok = flush[flush.index('{') + 1:].strip().startswith('ft_stop();') and 0 <= e < f < s < l - print(f'perf.c: perf_summary_flush starts with ft_stop, perf_present updates inside ft_enter/ft_leave: ' + stop, report = flush.find('ft_stop();'), flush.find('ft_report(') + ok = 0 <= stop < report and 0 <= e < f < s < l + print(f'perf.c: perf_summary_flush calls ft_stop before ft_report, perf_present updates inside ft_enter/ft_leave: ' f'{"ok" if ok else "FAIL"}') bad += not ok return bad @@ -188,6 +191,7 @@ def main(): want_all = ' '.join(STEPS) + ' ' want_seconds = ' '.join(s for s in STEPS if s != 'cfg_save') + ' ' rc = subprocess.run([str(exe), want_all, want_seconds], env=env, timeout=60).returncode + print(f'exit_order_check, the static checks and the program: {"FAILED" if bad or rc else "ok"}') return 1 if bad or rc else 0 diff --git a/tests/log_cap_check.py b/tests/log_cap_check.py new file mode 100644 index 00000000..03686636 --- /dev/null +++ b/tests/log_cap_check.py @@ -0,0 +1,127 @@ +"""The log file's cap and the end of the run (runtime/main.c log_sink): past the cap ordinary lines are dropped, with +one line that says so; once the process is ending (rt_log_ending, or rt_log_sync at a fatal error and in the crash +report) its lines are still written, after one line that says the end follows, up to a reserve of their own, however +much was dropped before. Builds log_sink with a small cap and reserve against stand-ins for the file and stderr. No +game files. + +Usage: python tests/log_cap_check.py [path to clang]""" +import os +import re +import shutil +import subprocess +import sys +from pathlib import Path + +ROOT = Path(__file__).resolve().parents[1] +MSYS_BIN = Path(r'C:\msys64\ucrt64\bin') +source = (ROOT / 'runtime' / 'main.c').read_text(encoding='utf-8') + + +def compiler(): + if len(sys.argv) > 1: + return sys.argv[1] + if os.environ.get('CC'): + return os.environ['CC'] + if os.name == 'nt' and (MSYS_BIN / 'clang.exe').exists(): + return str(MSYS_BIN / 'clang.exe') + return shutil.which('clang') or 'clang' + + +def function(signature): + start = source.index(signature) + brace = source.index('{', start) + depth, end = 1, brace + 1 + while depth: + depth += (source[end] == '{') - (source[end] == '}') + end += 1 + return source[start:end] + + +HARNESS = r''' +#include +#include +#include +#include +typedef int PlatMutex; +#define PLAT_MUTEX_INIT 0 +typedef struct PlatAppend PlatAppend; +static void plat_mutex_lock(PlatMutex *m) { (void)m; } +static int plat_mutex_trylock(PlatMutex *m) { (void)m; return 1; } +static void plat_mutex_unlock(PlatMutex *m) { (void)m; } +static char file[1 << 16]; +static size_t file_n; +static int plat_append_write(PlatAppend *f, const void *p, size_t n) { + (void)f; + if (file_n + n <= sizeof file) memcpy(file + file_n, p, n); + file_n += n; + return 1; +} +static int plat_stderr_write(const void *p, size_t n) { (void)p, (void)n; return 1; } +static void logq_sync(void) {} +#define LOG_CAP 4096ull +#define LOG_END_RESERVE 2048ull +enum { LOG_EARLY, LOG_FILE, LOG_OFF }; +static int g_log_state = LOG_FILE; +static PlatAppend *g_log_file; +static uint64_t g_log_bytes; +''' + +MAIN = r''' +static int count(const char *what) { + int n = 0; + for (const char *p = file; (p = strstr(p, what)) != NULL && p < file + file_n; p++) n++; + return n; +} +static int line(const char *tag, int i) { // returns the line's length + char b[64]; + int n = snprintf(b, sizeof b, "%s %04d ........................\n", tag, i); + log_sink(b, (size_t)n); + return n; +} +int main(int argc, char **argv) { + int fails = 0, how = argc > 1 && !strcmp(argv[1], "sync"); + int play_n = 0, end_n = 0; + for (int i = 0; i < 1000; i++) play_n = line("play", i); // 35,000 bytes, many times the cap + size_t before_end = file_n; + int play = count("play "), cut = count("reached 64 MiB"); + if (how) rt_log_sync(); + else rt_log_ending(); + for (int i = 0; i < 100; i++) end_n = line("last", i); // 3,400 bytes, more than the reserve + int end = count("last "), follows = count("the end of the run follows"); + printf("%s: %d play lines in the file, the cut line %d time(s); after %s %d end lines, the line before them %d " + "time(s); the file %zu bytes (cap %llu, reserve %llu)\n", how ? "rt_log_sync" : "rt_log_ending", play, cut, + how ? "rt_log_sync" : "rt_log_ending", end, follows, file_n, LOG_CAP, LOG_END_RESERVE); + if (play != (int)(LOG_CAP / play_n) || cut != 1) printf("FAIL: lines past the cap\n"), fails++; + if (follows != 1 || end != (int)(LOG_END_RESERVE / end_n)) printf("FAIL: the end's lines\n"), fails++; + if (file_n - before_end > LOG_END_RESERVE + 200) printf("FAIL: past the reserve\n"), fails++; + return fails ? 1 : 0; +} +''' + + +def main(): + parts = [HARNESS] + parts.append(re.search(r'static PlatMutex g_err_lock = PLAT_MUTEX_INIT;\n(.*?\n)\nvoid rt_log_ending', source, re.S) + .group(0).rsplit('\n', 1)[0]) + parts.append(function('void rt_log_ending(void)')) + parts.append(function('static void log_sink(const char *p, size_t n)')) + parts.append(function('void rt_log_sync(void)')) + parts.append(MAIN) + work = ROOT / 'build' / 'test' / 'log_cap' + work.mkdir(parents=True, exist_ok=True) + src = work / 'log_cap_check.c' + src.write_text('\n'.join(parts), encoding='utf-8') + exe = work / ('log_cap_check.exe' if os.name == 'nt' else 'log_cap_check') + env = dict(os.environ) + if os.name == 'nt' and MSYS_BIN.exists(): + env['PATH'] = str(MSYS_BIN) + os.pathsep + env.get('PATH', '') + subprocess.check_call([compiler(), '-O1', '-g', '-Wall', '-Wno-unused-function', str(src), '-o', str(exe)], env=env) + bad = 0 + for how in ('ending', 'sync'): + bad += subprocess.run([str(exe), how], env=env, timeout=60).returncode != 0 + print(f'log_cap_check: {"FAILED" if bad else "ok"}') + return 1 if bad else 0 + + +if __name__ == '__main__': + sys.exit(main())