diff --git a/runtime/dispatch.c b/runtime/dispatch.c index a9d6e0df..89a460b5 100644 --- a/runtime/dispatch.c +++ b/runtime/dispatch.c @@ -59,6 +59,10 @@ void rt_fatal_notes(void) { __attribute__((weak)) void fs_save_crash_wait(void) {} // fs_host.c; builds without it (the unit checks) have no saves +// The frame-time summary and the stutter map at a fatal error (perf.c); builds without perf.c (the unit checks) have +// none. +__attribute__((weak)) void perf_summary_flush_try(void) {} + // HD rumble's neutral value before a failed run ends (input.c input_rumble_hd_stop); builds without input.c (the unit // checks) have no controller. __attribute__((weak)) void input_rumble_hd_stop(void) {} @@ -111,6 +115,7 @@ static void fatal_end(int code, const char *fmt, va_list ap) { rt_fatal_notes(); kern_free_cores_note(); fs_save_crash_wait(); // a save the game already reported as done finishes first (bounded) + perf_summary_flush_try(); // "frametime: at a fatal error" and the stutter map: the session's last period prof_sampler_write(); // NX2NAVI_PROFILE: what was sampled until now, else a crash loses the whole profile // RivaTuner Statistics Server's profile as it was: left with the game's limit in it, the next run would take that // limit for the player's own (rtss_limit.c; it gives up after a second if the failing thread holds its lock) diff --git a/runtime/host.h b/runtime/host.h index 8220c15d..ee1ceef9 100644 --- a/runtime/host.h +++ b/runtime/host.h @@ -112,6 +112,7 @@ void perf_present(uint64_t frame); void perf_cpu_start(void); // the process's logical processors (NX2NAVI_CACHE_DIE, NX2NAVI_ONE_PER_CORE), at start int perf_cpu_on_cache_die(void); // 1 while the process runs on the die with the largest L3 cache alone (perf.c cpu_placement) void perf_summary_flush(void); // prints the frame-time summary of the running period (exit); the 60 s lines come from perf_present +void perf_summary_flush_try(void); // the same at a fatal error, the stutter map only if its lock is free void perf_focus_lost(void); // the window lost the focus: the session's reports at the next present, in play void gfx_exit_log(void); // back end's lines for the exit summary (weak no-op in prof_win.c) void gfx_window_closed(void); // gfx_present.c (gfx_wsys.h): the end of a closed window; does not return diff --git a/runtime/perf.c b/runtime/perf.c index 5b4db880..5522a250 100644 --- a/runtime/perf.c +++ b/runtime/perf.c @@ -775,6 +775,19 @@ void perf_summary_flush(void) { // at exit (prof_write) summary_t0 = 0; } +// A fatal error's frame-time summary (dispatch.c fatal_end), on the failing thread, which may hold any lock: the +// running period's "frametime" lines and the stutter map so far, the map only when its lock is free. The back end's +// exit lines (gfx_exit_log) and the trace's segments (seg_close) are left out: they read state the failure may have +// left half made. The present thread's numbers may be caught mid-frame if it still runs past ft_stop's wait. +void perf_summary_flush_try(void) { + ft_stop(); + if (summary_t0) { + ft_report(kern_now_ns(), "at a fatal error"); + if (!stutter_report_as("at a fatal error", 1)) rt_log("stutter map: its lock is held; not written at the fatal error"); + } + summary_t0 = 0; +} + // Returns the replay time since the previous present. add 0: the exit's summary is written (ft_stop), so the frame // is not added to it. static uint64_t ft_frame(uint64_t frame, uint64_t now, uint64_t d, int add) { diff --git a/runtime/stutter_map.c b/runtime/stutter_map.c index 8b689b05..bf6de34b 100644 --- a/runtime/stutter_map.c +++ b/runtime/stutter_map.c @@ -427,14 +427,20 @@ typedef struct { const Pipe *list[SM_PIPES]; } MapCopy; -void stutter_report(const char *tag) { - if (!stutter_map_on) return; +// try_only: sm_lock is only tried (a fatal error's summary, perf.c perf_summary_flush_try, on a thread that may +// hold it); 0 when it was held and nothing was written. +int stutter_report_as(const char *tag, int try_only) { + if (!stutter_map_on) return 1; MapCopy *m = malloc(sizeof *m); if (!m) { rt_log("stutter map (%s): no memory for the report", tag); - return; + return 1; + } + if (!try_only) plat_mutex_lock(&sm_lock); + else if (!plat_mutex_trylock(&sm_lock)) { + free(m); + return 0; } - plat_mutex_lock(&sm_lock); int na = n_areas; memcpy(m->areas, areas, (size_t)na * sizeof *areas); uint32_t np = 0, lost = pipes_lost; @@ -502,4 +508,7 @@ void stutter_report(const char *tag) { p->fresh ? ", a shader translated in play" : ""); } free(m); + return 1; } + +void stutter_report(const char *tag) { stutter_report_as(tag, 0); } diff --git a/runtime/stutter_map.h b/runtime/stutter_map.h index de259af4..70cc0fc5 100644 --- a/runtime/stutter_map.h +++ b/runtime/stutter_map.h @@ -28,3 +28,4 @@ void stutter_ready(int mesh, const uint8_t *vi, const uint8_t *fi, double ms, in void stutter_frame(uint64_t frame, uint64_t now, uint64_t d, const uint64_t *part, const char *const *names, int n, int cause); void stutter_report(const char *tag); // the map so far; every 5 minutes of play, at a focus loss in play and at exit +int stutter_report_as(const char *tag, int try_only); // try_only 1: only when its lock is free (0: it was not, nothing written) diff --git a/tests/fatal_exit_check.c b/tests/fatal_exit_check.c index b398d87c..4c40d9f8 100644 --- a/tests/fatal_exit_check.c +++ b/tests/fatal_exit_check.c @@ -60,6 +60,9 @@ void prof_sampler_write(void) {} void rtss_limit_restore(void) {} void kern_checkpoint(void) {} +// perf.c's summary at a fatal error, which dispatch.c calls through a weak symbol +void perf_summary_flush_try(void) { say("frametime: at a fatal error\n"); } + // input.c's stop, which dispatch.c calls through a weak symbol: says it ran, or hangs as when SDL's lock is held static int rumble_hangs; void input_rumble_hd_stop(void) { diff --git a/tests/fatal_exit_check.py b/tests/fatal_exit_check.py index 12df584e..19e62205 100644 --- a/tests/fatal_exit_check.py +++ b/tests/fatal_exit_check.py @@ -78,6 +78,13 @@ def static_checks(): print(f'static: main.c crash_handler starts with the shared guard: {"ok" if ok else "FAIL (" + first + ")"}', flush=True) bad += not ok + # the fatal error's summary leaves out what the failure may have left half made, and only tries the map's lock + flush = re.sub(r'//[^\n]*', '', function((RT / 'perf.c').read_text(encoding='utf-8'), 'void perf_summary_flush_try(void)')) + ok = ('stutter_report_as(' in flush and 'stutter_report(' not in flush and 'gfx_exit_log' not in flush + and 'seg_close' not in flush) + print(f'static: perf.c perf_summary_flush_try tries the stutter map\'s lock and leaves the back end out: ' + f'{"ok" if ok else "FAIL"}', flush=True) + bad += not ok # both failed ends stop HD rumble through the bounded stop, after RivaTuner's restore fatal = re.sub(r'//[^\n]*', '', function((RT / 'dispatch.c').read_text(encoding='utf-8'), 'static void fatal_end(int code, const char *fmt, va_list ap) {')) @@ -92,7 +99,7 @@ def static_checks(): CASES = [ # mode, exit code, lines that must be there, lines that must not - ('fatal', 70, ['FATAL: the test\'s fatal error 1', 'rumble: stopped'], ['detach:']), + ('fatal', 70, ['FATAL: the test\'s fatal error 1', 'frametime: at a fatal error', 'rumble: stopped'], ['detach:']), # the rumble stop hangs (SDL's lock held by a thread that crashed): the end goes on after 300 ms ('fatal_rumble', 70, ['FATAL: the test\'s fatal error 1'], ['rumble: stopped', 'detach:']), # two faults at once: the first report whole, the second thread waits (dispatch.c rt_ending_enter) diff --git a/tests/stutter_hitch_check.c b/tests/stutter_hitch_check.c index 65f73bb2..9de2f1ee 100644 --- a/tests/stutter_hitch_check.c +++ b/tests/stutter_hitch_check.c @@ -11,6 +11,7 @@ int cfg_bool(const char *name) { return !strcmp(name, "NX2NAVI_STUTTER_MAP"); } uint64_t kern_now_ns(void) { return clock_ns; } void plat_mutex_lock(PlatMutex *m) { (void)m; } void plat_mutex_unlock(PlatMutex *m) { (void)m; } +int plat_mutex_trylock(PlatMutex *m) { (void)m; return 1; } static int logged; static char head[1400]; // the last report's first line void rt_log(const char *fmt, ...) {