From e7c2fc6a6b6dc590e566082ca16bc160f55522f8 Mon Sep 17 00:00:00 2001 From: chrg6 Date: Fri, 13 Nov 2026 08:23:11 -0500 Subject: [PATCH] Make the stutter map name the areas without the perf trace, and count a hitch only when the frames after it are shorter: a hitch is now measured against the median of the last 32 frames, so a steady change of pace (the game drawing at 60 fps after 200) is no longer counted as a run of hitches. Co-Authored-By: Claude Opus 5.5 --- runtime/romfs.c | 6 +- runtime/stutter_map.c | 139 ++++++++++++++++++++++++----------- tests/stutter_hitch_check.c | 61 +++++++++++++++ tests/stutter_hitch_check.py | 40 ++++++++++ tests/stutter_map_check.py | 9 ++- tools/stutter_map.py | 7 +- 6 files changed, 210 insertions(+), 52 deletions(-) create mode 100644 tests/stutter_hitch_check.c create mode 100644 tests/stutter_hitch_check.py diff --git a/runtime/romfs.c b/runtime/romfs.c index f2be3fc4..0ffafda1 100644 --- a/runtime/romfs.c +++ b/runtime/romfs.c @@ -42,6 +42,7 @@ #include "platform/platform.h" #include "restbl.h" #include "sha256.h" +#include "stutter_map.h" #include @@ -1183,7 +1184,8 @@ static void open_note(uint64_t i, const char *path) { "(romfs-check.json lists the files found damaged)", path); } -// NX2NAVI_TRACE=perf: an area's static placement, Banc//__Static.bcett.byml.zs, is read once when the +// NX2NAVI_TRACE=perf and the stutter map (stutter_map.c): an area's static placement, +// Banc//__Static.bcett.byml.zs, is read once when the // area loads (the game streams a neighbouring area the same way): perf_scene names it. static int area_name(const char *p, char *name, size_t cap) { static const char tail[] = "_Static.bcett.byml"; @@ -1241,7 +1243,7 @@ uint32_t romfs_open(uint64_t *out, const char *path, int mode) { return FS_R_PATH_NOT_FOUND; } open_note(i, p); - if (rt_trace & RT_TRACE_PERF) scene_note(p); + if ((rt_trace & RT_TRACE_PERF) || stutter_map_on) scene_note(p); // the stutter map counts hitches by area if (!strcasecmp(p, CAMPACK)) cam_pack_opened(); // its values come into memory at the start's factor (camera_speed.c) uint32_t ov = overlay_slot(i); PlatFile *f = NULL; diff --git a/runtime/stutter_map.c b/runtime/stutter_map.c index 0a000367..0a8a2d86 100644 --- a/runtime/stutter_map.c +++ b/runtime/stutter_map.c @@ -3,10 +3,14 @@ // list (tools/pipeline_list.py merge) and shader preparation must take in. Off by default; while it is off every hook // returns at its first test. // -// A hitch is a frame whose interval is over 2.5 times the mean of the frames before it (a running mean of the frames -// that were not hitches), and at least 12 ms; any frame over 25 ms is one too. At 140 fps that is a frame over 17.5 ms, -// at 60 fps one over 25 ms. Frames within SM_LOAD_NS of an area's load count apart, as the load's: an area load -// shows as a few long frames that are not a stutter in play. +// A hitch is a frame that stands out from the frames around it: its interval is over 2.5 times the median of the 32 +// frames before it and at least 12 ms (or over 25 ms), and both of the next two frames are under two thirds of it +// (a frame over SM_HITCH_SURE_NS is one whatever follows). At 140 fps that is a frame over 17.5 ms followed by shorter +// ones. The look at the next two frames keeps a change of pace out: the game drawing its menus or a scene at a steady +// 60 or 30 fps after 140 is a slower rate, not a run of hitches, and the median takes the new rate within 16 frames. +// The decision waits two presents; the line and the counts carry what the frame itself waited for. Frames within +// SM_LOAD_NS of an area's load count apart, as the load's: an area load shows as a few long frames that are not a +// stutter in play. // // What a hitch went to comes from the frame-time summary's split (perf.c ft_frame: pipeline, translation, texture, // fence, pacing, replay, unattributed), with the draws that met a pipeline or a shader missing between the previous @@ -36,7 +40,11 @@ int stutter_map_on; #define SM_LOAD_NS 3000000000ull // after an area load, frames count as the load's for this long #define SM_HITCH_MIN_NS 12000000.0 // a hitch is at least this long... #define SM_HITCH_ANY_NS 25000000ull // ...and any frame over this is one -#define SM_HITCH_FACTOR 2.5 // times the running mean of the frames that were not hitches +#define SM_HITCH_FACTOR 2.5 // times the median of the frames before it +#define SM_HITCH_SURE_NS 100000000ull // a frame this long is a hitch whatever follows it +#define SM_MEDIAN_N 32 // frames the median is taken over +#define SM_AFTER 2 // frames after a candidate that must be shorter... +#define SM_AFTER_RATIO 1.5 // ...by this factor #define SM_PIPES 4096 // pipelines kept for the ranking (open addressing) #define SM_RING 256 // draws that met something missing, between two presents #define SM_LINES_MAX 4000 @@ -78,17 +86,27 @@ static uint64_t ring_tail; // present thread: draws taken so far static uint64_t ring_lost; // present thread -static double mean_ns; -static uint64_t t_first, t_report, line_sec, lines_in_sec, lines, frames_seen; +static uint64_t recent[SM_MEDIAN_N]; // the last frames' intervals, every frame (hitches too, so a new pace is learnt) +static uint64_t t_first, t_report, line_sec, lines_in_sec, lines, frames_seen, paced_out; +// A frame that may be a hitch, waiting for the SM_AFTER frames after it: its line (made when it happened, with the +// draws that met something missing then), its area and what it is charged to. +typedef struct { + char line[1400]; + uint64_t frame, d, after_max; + int area, load, cause, after; +} Cand; +static Cand cand[SM_AFTER + 1]; +static int n_cand; void stutter_map_init(void) { stutter_map_on = cfg_bool("NX2NAVI_STUTTER_MAP"); if (!stutter_map_on) return; snprintf(areas[0].name, sizeof areas[0].name, "%s", "(before the first area)"); - rt_log("stutter map: on (NX2NAVI_STUTTER_MAP): a hitch is a frame over %.1f times the frames before it and at " - "least %.0f ms, or over %llu ms; frames within %llu s of an area load count as the load's; the map every %llu " - "minutes and at exit", SM_HITCH_FACTOR, SM_HITCH_MIN_NS / 1e6, SM_HITCH_ANY_NS / 1000000ull, - SM_LOAD_NS / 1000000000ull, SM_REPORT_NS / 60000000000ull); + rt_log("stutter map: on (NX2NAVI_STUTTER_MAP): a hitch is a frame over %.1f times the median of the %d before it " + "and at least %.0f ms (or over %llu ms) whose next %d frames are under 1/%.1f of it (or one over %llu ms); " + "frames within %llu s of an area load count as the load's; the map every %llu minutes and at exit", + SM_HITCH_FACTOR, SM_MEDIAN_N, SM_HITCH_MIN_NS / 1e6, SM_HITCH_ANY_NS / 1000000ull, SM_AFTER, SM_AFTER_RATIO, + SM_HITCH_SURE_NS / 1000000ull, SM_LOAD_NS / 1000000000ull, SM_REPORT_NS / 60000000000ull); } static uint32_t id4(const uint8_t *id) { @@ -198,6 +216,41 @@ static void take_misses(Area *a, char *line, int *o, size_t cap) { plat_mutex_unlock(&sm_lock); } +// The median of the last SM_MEDIAN_N frames' intervals (fewer at the start). +static uint64_t median_recent(void) { + uint64_t v[SM_MEDIAN_N], n = frames_seen < SM_MEDIAN_N ? frames_seen : SM_MEDIAN_N; + if (!n) return 0; + memcpy(v, recent, (size_t)n * sizeof v[0]); + for (uint64_t i = 1; i < n; i++) + for (uint64_t k = i; k > 0 && v[k - 1] > v[k]; k--) { + uint64_t t = v[k]; + v[k] = v[k - 1], v[k - 1] = t; + } + return v[n / 2]; +} + +// A candidate the SM_AFTER frames after it have been seen for: a hitch, counted and its line logged, or a change of +// pace (the frames after it as long), left out. +static void cand_decide(const Cand *c, uint64_t now) { + if (c->d <= SM_HITCH_SURE_NS && (double)c->after_max * SM_AFTER_RATIO >= (double)c->d) { + paced_out++; + return; + } + Area *a = &areas[c->area]; + if (c->load) a->load_hitch++; + else { + a->hitch++; + if (c->cause >= 0 && c->cause < SM_CAUSES) a->by_cause[c->cause]++, a->cause_ns[c->cause] += c->d; + if (c->d > a->worst_ns) a->worst_ns = c->d, a->worst_frame = c->frame; + } + uint64_t sec = (now - t_first) / 1000000000ull; + if (sec != line_sec) line_sec = sec, lines_in_sec = 0; + if (lines >= SM_LINES_MAX || lines_in_sec >= SM_LINES_PER_S) return; + rt_log("%s", c->line); + lines++, lines_in_sec++; + if (lines == SM_LINES_MAX) rt_log("stutter: the last such line of this run; the map's counts go on"); +} + void stutter_frame(uint64_t frame, uint64_t now, uint64_t d, const uint64_t *part, const char *const *names, int n, int cause) { if (!stutter_map_on || !d) return; @@ -206,41 +259,38 @@ void stutter_frame(uint64_t frame, uint64_t now, uint64_t d, const uint64_t *par Area *a = &areas[ai]; a->ns += d, a->frames++; a->over25 += d > SM_HITCH_ANY_NS; + // this frame is one of the frames after each waiting candidate + for (int i = 0; i < n_cand;) { + Cand *c = &cand[i]; + if (d > c->after_max) c->after_max = d; + if (++c->after < SM_AFTER) { + i++; + continue; + } + cand_decide(c, now); + memmove(&cand[i], &cand[i + 1], (size_t)(n_cand - i - 1) * sizeof cand[0]); // at most two others + n_cand--; + } + uint64_t med = median_recent(); + recent[frames_seen % SM_MEDIAN_N] = d; frames_seen++; - double lim = mean_ns * SM_HITCH_FACTOR; + double lim = (double)med * SM_HITCH_FACTOR; if (lim < SM_HITCH_MIN_NS) lim = SM_HITCH_MIN_NS; - int hitch = (frames_seen > 30 && (double)d > lim) || d > SM_HITCH_ANY_NS; - if (!hitch) { - mean_ns = mean_ns > 0 ? mean_ns + ((double)d - mean_ns) / 32.0 : (double)d; + int maybe = (frames_seen > SM_MEDIAN_N && (double)d > lim) || d > SM_HITCH_ANY_NS; + if (!maybe || n_cand >= SM_AFTER + 1) { take_misses(a, NULL, NULL, 0); } else { - int load = now - __atomic_load_n(&load_at, __ATOMIC_RELAXED) < SM_LOAD_NS; - if (load) a->load_hitch++; - else { - a->hitch++; - if (cause >= 0 && cause < SM_CAUSES) a->by_cause[cause]++, a->cause_ns[cause] += d; - if (d > a->worst_ns) a->worst_ns = d, a->worst_frame = frame; - } - char line[1400]; - int o = 0; - uint64_t sec = (now - t_first) / 1000000000ull; - if (sec != line_sec) line_sec = sec, lines_in_sec = 0; - int say = lines < SM_LINES_MAX && lines_in_sec < SM_LINES_PER_S; - if (say) { - o = snprintf(line, sizeof line, "stutter: frame %llu at %.1f s, %.1f ms (frames about %.1f ms) in %s%s:", - (unsigned long long)frame, (now - t_first) / 1e9, d / 1e6, mean_ns / 1e6, a->name, - load ? ", after its load" : ""); - for (int c = 0; c < n && o < (int)sizeof line - 40; c++) - if (part[c] >= 500000) o += snprintf(line + o, sizeof line - (size_t)o, " %s %.1f", names[c], part[c] / 1e6); - if (cause >= 0 && cause < n && o < (int)sizeof line - 40) - o += snprintf(line + o, sizeof line - (size_t)o, " (charged to %s)", names[cause]); - } - take_misses(a, say ? line : NULL, &o, sizeof line); - if (say) { - rt_log("%s", line); - lines++, lines_in_sec++; - if (lines == SM_LINES_MAX) rt_log("stutter: the last such line of this run; the map's counts go on"); - } + Cand *c = &cand[n_cand++]; + c->frame = frame, c->d = d, c->after_max = 0, c->after = 0, c->area = ai, c->cause = cause; + c->load = now - __atomic_load_n(&load_at, __ATOMIC_RELAXED) < SM_LOAD_NS; + int o = snprintf(c->line, sizeof c->line, "stutter: frame %llu at %.1f s, %.1f ms (frames about %.1f ms) in %s%s:", + (unsigned long long)frame, (now - t_first) / 1e9, d / 1e6, med / 1e6, a->name, + c->load ? ", after its load" : ""); + for (int k = 0; k < n && o < (int)sizeof c->line - 40; k++) + if (part[k] >= 500000) o += snprintf(c->line + o, sizeof c->line - (size_t)o, " %s %.1f", names[k], part[k] / 1e6); + if (cause >= 0 && cause < n && o < (int)sizeof c->line - 40) + o += snprintf(c->line + o, sizeof c->line - (size_t)o, " (charged to %s)", names[cause]); + take_misses(a, c->line, &o, sizeof c->line); } if (now - t_report >= SM_REPORT_NS) { t_report = now; @@ -278,8 +328,9 @@ void stutter_report(const char *tag) { } char line[1400]; int o = snprintf(line, sizeof line, "stutter map (%s): %.1f min of play in %d areas; %llu hitches in play and %llu " - "after area loads; in play by cause:", tag, ns / 6e10, na, (unsigned long long)hitch, - (unsigned long long)load); + "after area loads; %llu long frames were a change of pace (the frames after them as long), not " + "hitches; in play by cause:", tag, ns / 6e10, na, (unsigned long long)hitch, (unsigned long long)load, + (unsigned long long)paced_out); for (int c = 0; c < SM_CAUSES; c++) if (cause[c]) o += snprintf(line + o, sizeof line - (size_t)o, " %s %llu", cause_short[c], (unsigned long long)cause[c]); rt_log("%s", line); diff --git a/tests/stutter_hitch_check.c b/tests/stutter_hitch_check.c new file mode 100644 index 00000000..469a7011 --- /dev/null +++ b/tests/stutter_hitch_check.c @@ -0,0 +1,61 @@ +// tests/stutter_hitch_check.py builds this: runtime/stutter_map.c's hitch rule on made-up frame times, with the few +// runtime functions it calls stubbed. A steady change of pace (the game drawing at 60 fps after 200) counts no hitch; +// isolated long frames each count one; a frame over SM_HITCH_SURE_NS counts whatever follows it. +#include +#include + +#include "../runtime/stutter_map.c" + +static uint64_t clock_ns; +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; } +static int logged; +void rt_log(const char *fmt, ...) { + (void)fmt; + logged++; +} + +static const char *const names[7] = {"pipeline", "translation", "texture", "fence", "pacing", "replay", "unattributed"}; +static uint64_t frame_no; + +static void frames(int n, double ms) { + uint64_t part[7] = {0}; + for (int i = 0; i < n; i++) { + uint64_t d = (uint64_t)(ms * 1e6); + clock_ns += d; + part[6] = d; + stutter_frame(++frame_no, clock_ns, d, part, names, 7, 6); + } +} + +static int fails; +static void expect(const char *what, uint64_t got, uint64_t want) { + if (got != want) printf("FAIL %s: %llu, expected %llu\n", what, (unsigned long long)got, (unsigned long long)want), fails++; +} + +int main(void) { + stutter_map_init(); + clock_ns = 10000000000ull; // well past any area load + frames(200, 5.0); + expect("steady 200 fps", areas[0].hitch, 0); + frames(300, 16.6); // the game's menus at 60 fps + expect("a change to 60 fps", areas[0].hitch, 0); + if (!paced_out) printf("FAIL the change of pace was not counted as one\n"), fails++; + frames(200, 7.0); + for (int k = 0; k < 5; k++) frames(1, 30.0), frames(60, 7.0); // five isolated spikes + expect("five isolated spikes", areas[0].hitch, 5); + frames(1, 150.0), frames(1, 150.0), frames(60, 7.0); // two long frames in a row: the second stands out + expect("two frames over the sure line", areas[0].hitch, 7); + frames(1, 40.0), frames(1, 40.0), frames(60, 7.0); // a double spike: the second one counts + expect("a double spike", areas[0].hitch, 8); + stutter_area("Kakariko"); // a load: what follows within SM_LOAD_NS is the load's + frames(1, 60.0), frames(30, 7.0); + expect("a spike right after a load (play)", areas[1].hitch, 0); + expect("a spike right after a load (load)", areas[1].load_hitch, 1); + if (!logged) printf("FAIL nothing was logged\n"), fails++; + if (fails) return 1; + printf("stutter_hitch_check: all checks passed\n"); + return 0; +} diff --git a/tests/stutter_hitch_check.py b/tests/stutter_hitch_check.py new file mode 100644 index 00000000..a702e157 --- /dev/null +++ b/tests/stutter_hitch_check.py @@ -0,0 +1,40 @@ +"""Build and run tests/stutter_hitch_check.c: runtime/stutter_map.c's hitch rule on made-up frame times. A steady +change of pace is no hitch, isolated long frames are, and frames right after an area load count as the load's. + +No GPU, no game files, any Python. + +Usage: stutter_hitch_check.py +""" +import os +import shutil +import subprocess +import sys +from pathlib import Path + +ROOT = Path(__file__).resolve().parents[1] +MSYS_BIN = Path(r'C:\msys64\ucrt64\bin') + + +def compiler(): + """$CC, else MSYS2 UCRT64's clang, else clang on PATH (as tests/diff/common.py picks it, without its Unicorn).""" + 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 main(): + work = ROOT / 'build' / 'test' / 'stutter_hitch' + work.mkdir(parents=True, exist_ok=True) + exe = work / ('stutter_hitch_check.exe' if os.name == 'nt' else 'stutter_hitch_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(), '-std=gnu11', '-O1', '-Wall', '-Werror', '-I', str(ROOT / 'runtime'), + str(ROOT / 'tests' / 'stutter_hitch_check.c'), '-o', str(exe)], env=env) + return subprocess.run([str(exe)], env=env).returncode + + +if __name__ == '__main__': + sys.exit(main()) diff --git a/tests/stutter_map_check.py b/tests/stutter_map_check.py index 22f025b4..acb688f9 100644 --- a/tests/stutter_map_check.py +++ b/tests/stutter_map_check.py @@ -23,7 +23,8 @@ def main(): src = C_SOURCE.read_text(encoding='utf-8') # the format strings the parser depends on must still be in the runtime for piece in ('stutter map (%s): %.1f min of play in %d areas; %llu hitches in play and %llu ', - '"after area loads; in play by cause:"', 'stutter map: %s: %.1f min at %.0f fps; hitches %llu (%.2f a minute', + '"after area loads; %llu long frames were a change of pace (the frames after them as long), not "', + '"hitches; in play by cause:"', 'stutter map: %s: %.1f min at %.0f fps; hitches %llu (%.2f a minute', '"; %s %llu, %.1f ms avg"', '"), worst %.1f ms (frame %llu); over 25 ms %llu; after its "', '"loads %llu; draws that met a pipeline missing %llu, a shader %llu, %.1f ms on the replay thread"', 'stutter: frame %llu at %.1f s, %.1f ms (frames about %.1f ms) in %s%s:', '" (charged to %s)"', @@ -37,7 +38,8 @@ def main(): '[host] ' + c_fmt('stutter: frame %llu at %.1f s, %.1f ms (frames about %.1f ms) in %s%s:', 1300, 80.0, 60.0, 7.0, 'Kakariko Village', ', after its load') + ' unattributed 55.0 (charged to unattributed)', '[host] ' + c_fmt('stutter map (%s): %.1f min of play in %d areas; %llu hitches in play and %llu ' - 'after area loads; in play by cause:', 'exit', 12.5, 2, 3, 1) + ' pipeline 2 texture 1', + 'after area loads; %llu long frames were a change of pace (the frames after them as long), not ' + 'hitches; in play by cause:', 'exit', 12.5, 2, 3, 1, 7) + ' pipeline 2 texture 1', '[host] ' + c_fmt('stutter map: %s: %.1f min at %.0f fps; hitches %llu (%.2f a minute', 'Kakariko Village', 10.0, 139.6, 3, 0.3) + c_fmt('; %s %llu, %.1f ms avg', 'pipeline', 2, 30.2) + c_fmt('; %s %llu, %.1f ms avg', 'texture', 1, 19.0) @@ -74,7 +76,8 @@ def main(): out = Path(d) / 'map.md' stutter_map.report([log], out) text = out.read_text(encoding='utf-8') - assert '**3 hitches in play**' in text and '| Kakariko Village | 10.0 | 140 |' in text, text + assert block['head'][5] == '7' and block['head'][6] == ' pipeline 2 texture 1', block['head'] + assert '7 long frames left out' in text and '**3 hitches in play**' in text and '| Kakariko Village | 10.0 | 140 |' in text, text print('stutter_map_check: ok') return 0 diff --git a/tools/stutter_map.py b/tools/stutter_map.py index ae68780c..fee50c23 100644 --- a/tools/stutter_map.py +++ b/tools/stutter_map.py @@ -23,7 +23,7 @@ sys.path.insert(0, str(Path(__file__).resolve().parent)) import pipeline_list # noqa: E402 HEAD = re.compile(r'stutter map \(([^)]*)\): ([\d.]+) min of play in (\d+) areas; (\d+) hitches in play and (\d+) after ' - r'area loads; in play by cause:(.*)$') + r'area loads; (?:(\d+) long frames were a change of pace.*?not hitches; )?in play by cause:(.*)$') AREA = re.compile(r'stutter map: (.+?): ([\d.]+) min at (\d+) fps; hitches (\d+) \(([\d.]+) a minute(.*?)\), worst ' r'([\d.]+) ms \(frame (\d+)\); over 25 ms (\d+); after its loads (\d+); draws that met a pipeline ' r'missing (\d+), a shader (\d+), ([\d.]+) ms on the replay thread') @@ -81,9 +81,10 @@ def report(logs, out): if not block: lines += ['No stutter map in this log (stutter_map = 1 in nx2navi.ini turns it on).', ''] continue - tag, mins, nareas, hitch, load, causes = block['head'] + tag, mins, nareas, hitch, load, paced, causes = block['head'] lines += [f'{float(mins):.1f} min of play in {nareas} areas ({tag}): **{hitch} hitches in play**, {load} right ' - f'after area loads. In play by cause:{causes}.', ''] + f'after area loads' + (f', {paced} long frames left out as a change of pace' if paced else '') + + f'. In play by cause:{causes}.', ''] lines += ['| Area | Minutes | fps | Hitches | a minute | Causes | Worst ms | Pipelines met missing | Shaders met ' 'missing |', '|---|---|---|---|---|---|---|---|---|'] for a in block['areas']: