7 Commits

Author SHA1 Message Date
chrg6
b23acff301 Leave a line in the log when a module ends the process with ExitProcess, and write the gathered lines at a focus loss.
Two runs of 2026-11-13 (the 0.10.0 fresh install's nx2navi.1.log, 7,974,927 bytes, and the 0.9.2 test's
nx2navi.3.log) ended seconds after "window lost the focus" with exit code 0, no WER event and no line of their own:
an ExitProcess or exit() called by a module in the process and a kill from outside could not be told apart, and
both lose the up to 250 ms of lines the log thread was gathering. A direct ExitProcess skips perf.c's atexit sync.

(a) ExitProcess stops every other thread and then calls each module's detach, the executable's TLS callbacks
included; TerminateProcess calls none. win32.c exit_note_tls, in the .CRT$XLB list beside _tls_used, writes on
DLL_PROCESS_DETACH what the log queue holds (logq.c logq_peek: the bytes as they stand, no lock) and one line,
"exit: the process is ending through ExitProcess, not one of the game's own ends", with the return addresses that
led there. It runs under the loader lock with the other threads gone, so it uses no C runtime (hex written by hand)
and does not ask the loader: the addresses are named from a module list noted at start and at each focus loss
(plat_exit_note_modules: EnumProcessModules, two tables and a writers' lock the callback never takes), and
RtlCaptureStackBackTrace and WriteFile take no lock of the process. plat_exit, plat_terminate and plat_reexec set
the orderly flag (plat_exit_orderly), and main does once main_run has returned, so a tool mode's exit() leaves no
line; a library's exit() during a game run does, naming ucrtbase and its caller. main.c log_open sets it up for a
game run that writes a log file. Linux has empty stand-ins.

(b) gfx_window_focus_changed calls the new main.c rt_log_focus_lost at a focus loss: logq_nudge makes the log thread
write what it gathers at once (a flag log_main's gathering loop checks) and the module list is noted again.

Not reproduced before the change (the two ends are unexplained). The new tests/exit_tls_check.py links win32.c and
logq.c with a queued line still being gathered: ExitProcess from the program and exit() write the line and the note
naming exit_tls_check.exe; TerminateProcess, plat_exit and a return after plat_exit_orderly write no note.
tests/logq_check.c gains a nudge case, which fails with the flag left unset (252 ms) and passes with it.
thread_end_check, fatal_exit_check, crash_stack_check, exit_order_check, save_share_check and the compile checks of
every runtime file pass.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
2026-11-13 18:43:23 -05:00
chrg6
e39f71df39 Run every orderly exit through one sequence that puts RivaTuner's profile back before the slow pipeline save.
The window's close, the guest's ExitProcess and the end of a --seconds run each ran their own list. All three
waited for the pipeline save (up to 5 s for running builds, then the write) before they put RivaTuner Statistics
Server's profile back, stopped HD rumble, wrote the frame-time summary and flushed the save, so a console close,
a session end or an "End task" that killed the process in that wait left the game's limit in RTSS's profile (the
next run takes it for the player's own), a buzzing controller and no exit summary. ExitProcess also lacked
cfg_save and the rumble stop, and it and the window's close had no shared guard, so both could run at once and
write the summary twice while the present thread still added to it.

gfx_present.c rt_exit_begin is the one guard (the first caller runs; another thread waits for good; the same
thread again returns, and svc.c ends the process then rather than resume guest code). rt_exit_steps runs, in
order: fs_save_wait (a Commit under way finishes, none is refused), rtss_limit_restore, input_rumble_hd_stop,
cfg_save (not for --seconds), the prewarm marker clear, prof_write, vk_mem_exit_log, a non-final log flush
(the new logq.c logq_flush, bounded trylocks, queue left on), vk_pipeline_save_exit, and fs_save_flush last.
perf.c ft_stop keeps the present thread's frame-time updates out of the exit's summary and waits at most 50 ms,
on the exiting thread, for one under way. The restore relies on rtss_limit.c's closed flag to stay restored
while frames go on during the pipeline save. The log order changes: "frametime: exit" and the stutter-map exit
lines now come before the pipeline save's lines.

Not reproduced before the change. tests/exit_order_check.py (new: the step order, the once-guard with a second
thread, ft_stop's wait and bound, and statically that the three exits use the helper with the RTSS restore
before the pipeline save), tests/logq_check.py (with a logq_flush case), tests/save_share_check.py and the
compile checks pass.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
2026-11-13 18:42:10 -05:00
chrg6
d9429b0c00 Break the memory report down past VMA, by owner in system memory, and by growth over a session.
Every report adds a line for video memory outside VMA (the driver's usage and budget per heap against VMA's blocks, and counts of pipelines by kind and by last use, stage libraries, compute pipelines, layouts and descriptor pools, with the swapchain, DLSS and FSR sizes), a line that splits the process's commit by owner (the game's heap and maps, device-local memory, VMA's host blocks, the C runtime heap with the shader caches, pipeline tables, texture cache, log queue and flight recorder in it, the driver's pipeline cache data and the rest), and a line naming what grew by more than 64 MiB since the report before and since play began. Every ten minutes of play and at exit a ranking line orders the categories by growth and marks those that only climbed; tests/mem_growth_check.py checks that bookkeeping.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
2026-11-13 06:46:31 -05:00
chrg6
e682934bd0 Write the log file before stderr, and keep a blocked console from stopping the log and the exit.
A selection in the console window of a game started directly held back the write to stderr, and with it the log
file, the exit hook and the crash report. The log file now comes first, stderr goes past the C runtime's stream lock,
and the lines of an exit, a fatal error or a crash skip stderr while another thread is stuck in it. A game run turns
the console's QuickEdit mode off, and a closed console, Ctrl+C or Ctrl+Break ends the game the way a closed window
does, with the settings and saves written and the exit logged.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
2026-11-13 06:06:27 -05:00
chrg6
cc0b467a2c 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>
2026-11-12 15:12:51 -05:00
chrg6
c1951d2b37 Keep a thread's log lines in order when the log queue's lock is taken.
A thread that found the queue's lock taken for 4,000 spins wrote its line itself, ahead of the lines it had queued
earlier. On a busy machine the lock's holder loses the processor inside the copy and the lock stays taken for a time
slice, so one thread's lines reached the log out of order. A line now waits for the lock, and a line that finds no
room, or is larger than the queue, is written after everything queued before it.

tests/logq_check.py failed on this in 8 of 30 runs beside four busy processes and passes 100 of 100 now. It gained a
check that holds the queue's locks itself and fails on the old code every time, and it no longer depends on time: it
waits for the queue to empty, keeps the line about slow writes back except in the step that checks it, and counts the
lines that waited instead of timing the slowest.

Co-Authored-By: Claude Fable 5.2 <noreply@anthropic.com>
2026-11-10 10:26:51 -05:00
chrg6
a03e059d2b Write the log from a thread of its own, so a stalled write no longer holds the thread that logged.
Every log line was two writes on the thread that logged it, to stderr and to the log file. Such a write can stall for
tens or hundreds of milliseconds (a busy disk, a virus scanner, a console or a pipe that is slow to take it), and the
render thread logs too: a frame it spent in a write was a hitch with nothing else to show for it.

In a game run the lines now go into a queue that a log thread writes out in order (runtime/logq.c). A fatal error,
the crash report and the end of the process write the queue out on their own thread first and write their own lines
directly, so nothing is lost to an exit. A thread that finds the queue's lock held for long, or the queue full, writes
its line itself. NX2NAVI_LOG_ASYNC=0 writes every line where it is logged, as before.

Every write is timed in both modes: a "log: ... writes of the log took over 2 ms" line counts the slow ones, gives
the longest and says whose time they took.

tests/logq_check.py checks order and completeness with eight threads, a slow destination, a stopped destination with
the queue full, and the synchronous flush.

Co-Authored-By: Claude Fable 5.2 <noreply@anthropic.com>
2026-11-10 07:22:41 -05:00