Files
NX2navi/tests/exit_order_check.py
chrg6 bbea3ce2a0 Write the end of the run to the log file past its 64 MiB cap, up to a 4 MiB reserve counted on its own.
main.c log_sink wrote nothing to the file once g_log_bytes passed LOG_CAP: every later line, the exit summary,
"frametime: exit", the stutter map's exit lines and FATAL and crash lines included, went to stderr only, which a
game started from the launcher or Explorer does not keep. A trace = perf session reaches the cap in about 90
minutes (the fresh 0.10.0 log grew 12 KB/s), and the play-test asks for an hour or more of exactly that. A reserve
compared against g_log_bytes would not help: that counter adds every line, dropped ones too, so 4 MiB of dropped
lines (under 6 minutes at that rate) would use it up before the end came.

The new rt_log_ending marks the process as ending; rt_exit_begin (the orderly ends) and perf_summary_flush (the
frame-time summary, also on the cheats rebuild exit) call it, and rt_log_sync (a fatal error, the crash report)
counts as ending too. The exit summary and the stutter map are written before rt_log_sync, so keying on
g_log_final alone would have missed them. While ending, a line past the cap goes to the file through
g_log_tail, a counter of the bytes written past the cap, up to LOG_END_RESERVE (4 MiB), after one line saying the
end of the run follows. The cut line says the end will still come. The file can end 4 MiB past the cap.

perf_summary_flush now calls rt_log_ending before ft_stop, so tests/exit_order_check.py's static check of it wants
ft_stop before ft_report rather than first. The check also prints one closing line for the static checks and the
program together: the program's own "ok" line had hidden a failing static check.

Not reproduced before the change (no log here reached the cap). The new tests/log_cap_check.py builds log_sink
with a 4 KiB cap and a 2 KiB reserve: past the cap ordinary lines are dropped with one cut line, and after
rt_log_ending or rt_log_sync the end's lines fill the reserve after one "end follows" line, however much was
dropped before. exit_order_check (rt_exit_begin marks the end once; exit code 0 at this commit), logq_check and the
compile checks pass.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
2026-11-13 18:42:10 -05:00

200 lines
9.0 KiB
Python

"""The orderly end of the process (runtime/gfx_present.c rt_exit_begin and rt_exit_steps): the steps run in one order,
with what a kill of the process must not lose (a save Commit in flight, RivaTuner Statistics Server's profile, the
controller's rumble, the settings, the frame-time summary) before the slow pipeline save and the final save flush
last; it runs once, and a second caller on another thread stays where it is. The frame-time summary of the exit
(runtime/perf.c ft_stop) waits for a present thread's update under way and keeps later ones out. Builds those
functions into a test program against stand-ins, and checks statically that every orderly end goes through them.
No game files.
Usage: python tests/exit_order_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]
RT = ROOT / 'runtime'
MSYS_BIN = Path(r'C:\msys64\ucrt64\bin')
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 strip_comments(text):
return re.sub(r'//[^\n]*', '', text)
def function(source, 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]
def calls_in_order(body, names):
"""The position of each name's first call in body (comments left out), or None for a name that is missing."""
code = strip_comments(body)
return [m.start() if (m := re.search(r'\b' + re.escape(n) + r'\s*\(', code)) else None for n in names]
STEPS = ['fs_save_wait', 'rtss_limit_restore', 'input_rumble_hd_stop', 'cfg_save', 'vk_pipeline_prewarm_marker_clear',
'prof_write', 'vk_mem_exit_log', 'logq_flush', 'vk_pipeline_save_exit', 'fs_save_flush']
HARNESS = r'''
#include <windows.h>
#include <stdint.h>
#include <stdio.h>
#include <string.h>
static uint32_t plat_thread_id(void) { return GetCurrentThreadId(); }
static void plat_sleep_ms(uint32_t ms) { Sleep(ms); }
enum { RT_EXIT_SETTINGS = 1 };
static char seen[1024];
#define STEP(name) static void name(void) { strcat(seen, #name " "); }
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'''
static volatile LONG second_back = -1;
static DWORD WINAPI second(void *arg) { (void)arg; second_back = rt_exit_begin(); return 0; }
static volatile LONG updating;
static DWORD WINAPI present(void *arg) { // one present thread update that takes ms milliseconds
int ms = (int)(intptr_t)arg;
if (!ft_enter()) { ft_leave(); return 0; }
updating = 1;
Sleep(ms);
updating = 0;
ft_leave();
return 0;
}
int main(int argc, char **argv) {
int fails = 0;
rt_exit_steps(RT_EXIT_SETTINGS);
printf("window close, guest ExitProcess: %s\n", seen);
if (strcmp(seen, argv[1])) printf("FAIL: want %s\n", argv[1]), fails++;
seen[0] = 0;
rt_exit_steps(0);
printf("--seconds: %s\n", seen);
if (strcmp(seen, argv[2])) printf("FAIL: want %s\n", argv[2]), fails++;
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; 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);
while (!updating) Sleep(1);
ULONGLONG t0 = GetTickCount64();
ft_stop();
ULONGLONG waited = GetTickCount64() - t0;
int busy_after = updating;
WaitForSingleObject(p, INFINITE);
int later = ft_enter();
ft_leave();
printf("frame-time summary: ft_stop waited %llu ms for the update under way (%s), a later update %s\n",
(unsigned long long)waited, busy_after ? "still running: FAIL" : "done",
later ? "still added: FAIL" : "kept out");
if (busy_after || later) fails++;
// an update that does not end: ft_stop gives up after about 50 ms
__atomic_store_n(&ft_ending, 0, __ATOMIC_SEQ_CST);
p = CreateThread(NULL, 0, present, (void *)(intptr_t)2000, 0, NULL);
while (!updating) Sleep(1);
t0 = GetTickCount64();
ft_stop();
waited = GetTickCount64() - t0;
printf("frame-time summary: ft_stop with an update that hangs came back after %llu ms\n", (unsigned long long)waited);
if (waited > 1000) printf("FAIL: ft_stop must be bounded\n"), fails++;
printf("exit_order_check: %s\n", fails ? "FAILED" : "ok");
fflush(stdout);
ExitProcess(fails ? 1 : 0); // the parked thread never returns
}
'''
def static_checks():
bad = 0
gp = (RT / 'gfx_present.c').read_text(encoding='utf-8')
svc = (RT / 'svc.c').read_text(encoding='utf-8')
boot = (RT / 'boot.c').read_text(encoding='utf-8')
perf = (RT / 'perf.c').read_text(encoding='utf-8')
exit07 = svc[svc.index('case 0x07:'):]
exit07 = exit07[:exit07.index('svc_fatal(')]
paths = [('gfx_present.c gfx_window_closed', function(gp, 'void gfx_window_closed(void)'), 'rt_exit_steps(RT_EXIT_SETTINGS)'),
('svc.c ExitProcess (0x07)', exit07, 'rt_exit_steps(RT_EXIT_SETTINGS)'),
('boot.c rt_frame_presented (--seconds)', function(boot, 'void rt_frame_presented('), 'rt_exit_steps(0)')]
for name, body, steps in paths:
code = strip_comments(body)
a, b, c = code.find('rt_exit_begin()'), code.find(steps), code.rfind('plat_exit(')
own = [s for s in STEPS if re.search(r'\b' + s + r'\s*\(', code)]
ok = 0 <= a < b < c and not own
print(f'{name}: {"rt_exit_begin, then " + steps + ", then plat_exit" if ok else "FAIL"}'
+ (f'; calls exit steps of its own: {", ".join(own)}' if own else ''), flush=True)
bad += not ok
steps = function(gp, 'void rt_exit_steps(unsigned what)')
pos = calls_in_order(steps, ['rtss_limit_restore', 'vk_pipeline_save_exit'])
ok = None not in pos and pos[0] < pos[1]
print(f'rt_exit_steps: RivaTuner\'s profile put back before the pipeline save: {"ok" if ok else "FAIL"}')
bad += not ok
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()'))
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
def main():
sys.stdout.reconfigure(line_buffering=True)
bad = static_checks()
if os.name != 'nt':
print('exit_order_check: the program part runs on Windows only')
return 1 if bad else 0
gp = (RT / 'gfx_present.c').read_text(encoding='utf-8')
perf = (RT / 'perf.c').read_text(encoding='utf-8')
tid = re.search(r'static volatile uint32_t exit_tid;[^\n]*', gp).group(0)
ftvars = re.search(r'static volatile int32_t ft_ending, ft_busy;', perf).group(0)
src = '\n'.join([HARNESS, tid, function(gp, 'int rt_exit_begin(void)'), function(gp, 'void rt_exit_steps(unsigned what)'),
ftvars, function(perf, 'static int ft_enter(void)'), function(perf, 'static void ft_leave(void)'),
function(perf, 'static void ft_stop(void)'), MAIN])
work = ROOT / 'build' / 'test' / 'exit_order'
work.mkdir(parents=True, exist_ok=True)
(work / 'exit_order_check.c').write_text(src, encoding='utf-8')
exe = work / 'exit_order_check.exe'
env = dict(os.environ)
if MSYS_BIN.exists():
env['PATH'] = str(MSYS_BIN) + os.pathsep + env.get('PATH', '')
subprocess.check_call([compiler(), '-O1', '-g', '-Wall', '-Wno-unused-function', str(work / 'exit_order_check.c'),
'-o', str(exe)], env=env)
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
if __name__ == '__main__':
sys.exit(main())