mirror of
https://github.com/tangerineturtle1/NX2navi.git
synced 2026-11-15 19:19:58 -04:00
c040ca6c5f
dispatch.c fatal_end wrote only the profiler's samples, so a run that ended in a FATAL had no "frametime" or stutter-map lines for its last period: the numbers that would show what the game was doing before it failed. perf.c perf_summary_flush_try (weak in dispatch.c for builds without perf.c) runs after fs_save_crash_wait: ft_stop, then the running period's "frametime: at a fatal error" lines and the stutter map. The failing thread may hold any lock, so stutter_map.c gains stutter_report_as(tag, try_only), which only tries sm_lock and writes nothing when it is taken (stutter_report keeps the blocking take); the back end's exit lines (gfx_exit_log) and the trace's segments (seg_close) are left out, as they read state the failure may have left half made. The crash report keeps no summary: its state may be damaged. Not reproduced before the change (a missing diagnostic). tests/fatal_exit_check.py now wants the summary at rt_fatal and checks statically that perf_summary_flush_try only tries the map's lock and leaves the back end out; tests/stutter_hitch_check.c gets the trylock stand-in it needs. fatal_exit_check, stutter_hitch_check, stutter_map_check and the compile checks of every runtime file pass. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
1219 lines
67 KiB
C
1219 lines
67 KiB
C
// Frame timing (NX2NAVI_TRACE=perf, the frame-time summary, the performance overlay's counts), the A/B switches (rt_ab,
|
|
// rt_knob) and NX2NAVI_ONE_PER_CORE. The sampling profiler (NX2NAVI_PROFILE) is the OS's (prof_win.c); without one the weak
|
|
// prof_sampler_* below do nothing.
|
|
#include <stdio.h>
|
|
#include <stdlib.h>
|
|
#include <string.h>
|
|
|
|
#include "cfg.h"
|
|
#include "bugcap.h"
|
|
#include "flight.h"
|
|
#include "gfx.h"
|
|
#include "host.h"
|
|
#include "nvn_api.h"
|
|
#include "perf_census.h"
|
|
#include "perfmon.h"
|
|
#include "prof.h"
|
|
#include "stutter_map.h"
|
|
#include "platform/platform.h"
|
|
|
|
volatile uint32_t prof_render_tid, prof_main_tid, prof_replay_tid;
|
|
|
|
__attribute__((weak)) int prof_sampler_start(void) {
|
|
if (cfg_get("NX2NAVI_PROFILE")) rt_log("prof: NX2NAVI_PROFILE: no sampling profiler on this OS");
|
|
return 0;
|
|
}
|
|
__attribute__((weak)) void prof_sampler_write(void) {}
|
|
__attribute__((weak)) void prof_sampler_frame(uint64_t frame, uint64_t now, uint64_t d) { (void)frame, (void)now, (void)d; }
|
|
__attribute__((weak)) int prof_commit_census(uint64_t frame, uint64_t *wc) { (void)frame, *wc = 0; return 0; }
|
|
__attribute__((weak)) void mem_guest_census(uint64_t frame) { (void)frame; }
|
|
__attribute__((weak)) void mem_lazy_heap_report(uint64_t frame) { (void)frame; }
|
|
|
|
// NX2NAVI_TRACE=perf, NX2NAVI_FLIGHT=1 or the full performance overlay: event counts are taken. Wait times are always taken
|
|
// (frame-time summary). perf_base: the part fixed at start.
|
|
static int perf_on, perf_base;
|
|
static int overlay; // performance overlay mode (perf_set_overlay): 0 off, 1 fps, 2 full
|
|
|
|
void perf_set_overlay(int mode) {
|
|
__atomic_store_n(&overlay, mode, __ATOMIC_RELAXED);
|
|
__atomic_store_n(&perf_on, perf_base || mode == 2, __ATOMIC_RELAXED);
|
|
}
|
|
|
|
static int gpu_want; // perf_gpu_timing_want: a feature reads GPU time (dynamic resolution)
|
|
|
|
void perf_gpu_timing_want(int on) { __atomic_store_n(&gpu_want, on != 0, __ATOMIC_RELAXED); }
|
|
|
|
int perf_gpu_timing(void) {
|
|
return (rt_trace & RT_TRACE_PERF) || __atomic_load_n(&overlay, __ATOMIC_RELAXED) == 2 ||
|
|
__atomic_load_n(&gpu_want, __ATOMIC_RELAXED);
|
|
}
|
|
|
|
static volatile int64_t gpu_busy_total;
|
|
|
|
void perf_gpu_busy(uint64_t ns) { plat_add64(&gpu_busy_total, (int64_t)ns); }
|
|
|
|
uint64_t perf_gpu_busy_total(void) { return (uint64_t)__atomic_load_n(&gpu_busy_total, __ATOMIC_RELAXED); }
|
|
|
|
// Registered before the handlers below, so it runs after them (atexit's order is the reverse): a process that ends
|
|
// through exit() rather than plat_exit, whose log sync this is, gets the lines of the frame-time summary, the stutter
|
|
// map and everything queued before them into the log instead of losing them with the log thread's queue.
|
|
static void log_sync_at_exit(void) { rt_log_sync(); }
|
|
static void hc_start(void);
|
|
|
|
void prof_start(void) {
|
|
flight_init();
|
|
stutter_map_init();
|
|
atexit(log_sync_at_exit);
|
|
atexit(perf_summary_flush); // boot.c's _exit path goes through prof_write instead
|
|
perf_base = (rt_trace & RT_TRACE_PERF) || flight_on;
|
|
perf_on = perf_base || overlay == 2;
|
|
hc_start();
|
|
if (prof_sampler_start()) atexit(prof_write); // a --seconds run ends in _exit: boot.c calls prof_write itself first
|
|
}
|
|
|
|
void prof_write(void) {
|
|
perf_summary_flush();
|
|
prof_sampler_write();
|
|
}
|
|
|
|
// ---- NX2NAVI_TRACE=perf: frame interval and the time the render thread spends waiting, logged every 60 presents. The
|
|
// flight recorder (NX2NAVI_FLIGHT=1, flight.c) takes the same numbers per frame.
|
|
static uint64_t wait_ns[PERF_N], frame_ns[PERF_N], worst_ns[PERF_N]; // window totals, this frame, the slowest frame
|
|
|
|
uint64_t perf_begin(void) { return kern_now_ns(); }
|
|
|
|
void perf_replay_thread(void) { prof_replay_tid = plat_thread_id(); }
|
|
void perf_main_thread(void) { prof_main_tid = plat_thread_id(); }
|
|
|
|
void perf_end(int kind, uint64_t t0) {
|
|
if (!t0) return;
|
|
uint32_t tid = plat_thread_id();
|
|
if (tid != prof_render_tid && tid != prof_replay_tid) return;
|
|
uint64_t d = kern_now_ns() - t0;
|
|
if (tid == prof_render_tid && !prof_replay_tid) { // one thread adds: no atomics on the synchronous path
|
|
wait_ns[kind] += d;
|
|
frame_ns[kind] += d;
|
|
return;
|
|
}
|
|
__atomic_fetch_add(&wait_ns[kind], d, __ATOMIC_RELAXED);
|
|
__atomic_fetch_add(&frame_ns[kind], d, __ATOMIC_RELAXED);
|
|
}
|
|
|
|
// The waits of other threads that hold the frame all the same: a game may acquire its window image on a thread other
|
|
// than the one that presents (vk_lowlat.c vk_lowlat_pace's comment notes it), and perf_end leaves those waits out, so
|
|
// the pacer's wait in the acquire showed nowhere. Added to frame_ns and wait_ns by the present (perf_present) before
|
|
// the frame's parts are read.
|
|
static volatile int64_t any_ns[PERF_N];
|
|
|
|
void perf_end_any(int kind, uint64_t t0) {
|
|
if (!t0 || (unsigned)kind >= PERF_N) return;
|
|
uint32_t tid = plat_thread_id();
|
|
if (tid == prof_render_tid || tid == prof_replay_tid) {
|
|
perf_end(kind, t0);
|
|
return;
|
|
}
|
|
plat_add64(&any_ns[kind], (int64_t)(kern_now_ns() - t0));
|
|
}
|
|
|
|
static volatile int64_t other_wait_ns; // perf_gpu_wait on threads other than the render thread, over the window
|
|
static volatile int64_t render_wait_ns; // the same on the render thread
|
|
void (*perf_gpu_stats)(PerfGpu *out);
|
|
|
|
void perf_gpu_wait(uint64_t t0) {
|
|
if (!t0 || !__atomic_load_n(&perf_on, __ATOMIC_RELAXED)) return;
|
|
int64_t d = (int64_t)(kern_now_ns() - t0);
|
|
plat_add64(plat_thread_id() == prof_render_tid ? &render_wait_ns : &other_wait_ns, d);
|
|
}
|
|
|
|
static volatile int64_t replay_ns; // perf_replay: summed over the window, any thread
|
|
static volatile int64_t frame_replay_ns; // the same since the previous present (frame-time summary)
|
|
// The replaying thread's CPU time over the same spans (perf_replay_cpu): the rest of the replay's wall time it was
|
|
// waiting (a lock, the recorder) or not running (preempted). Since the previous present, and over the period.
|
|
static volatile int64_t frame_replay_cpu_ns;
|
|
static uint64_t per_replay_ns, per_replay_cpu_ns;
|
|
|
|
void perf_replay_cpu(uint64_t ns) { plat_add64(&frame_replay_cpu_ns, (int64_t)ns); }
|
|
|
|
void perf_replay(uint64_t t0) {
|
|
if (!t0) return;
|
|
int64_t d = (int64_t)(kern_now_ns() - t0);
|
|
plat_add64(&frame_replay_ns, d);
|
|
if (__atomic_load_n(&perf_on, __ATOMIC_RELAXED)) plat_add64(&replay_ns, d);
|
|
}
|
|
|
|
static volatile int64_t counts[PERF_CNT_N]; // running totals: the perf log and the flight recorder take differences
|
|
|
|
void perf_count(int kind) {
|
|
if (__atomic_load_n(&perf_on, __ATOMIC_RELAXED)) plat_inc64(&counts[kind]);
|
|
}
|
|
|
|
// ---- NX2NAVI_TRACE=perf work marks (host.h PERF_M_*): any thread adds; the present takes the frame's sums (mark_frame),
|
|
// names them on a slow frame's line and adds them to the 60-frame window's line.
|
|
static const char *const mark_name[PERF_M_N] = {"file reads", "zstd decodes", "pipeline creates", "guest memory maps",
|
|
"pool init/finalize", "device memory allocations",
|
|
"DLSS feature creates"};
|
|
static volatile int64_t mk_ns[PERF_M_N], mk_n[PERF_M_N], mk_bytes[PERF_M_N], mk_max[PERF_M_N]; // since the last present
|
|
typedef struct { uint64_t ns[PERF_M_N], n[PERF_M_N], bytes[PERF_M_N], max[PERF_M_N]; } MarkSums;
|
|
static MarkSums mk_win; // the 60-frame window's, present thread only
|
|
|
|
uint64_t perf_mark_begin(void) { return (rt_trace & RT_TRACE_PERF) ? kern_now_ns() : 0; }
|
|
|
|
void perf_mark_add(int kind, uint64_t ns, uint64_t bytes) {
|
|
if (!(rt_trace & RT_TRACE_PERF) || (unsigned)kind >= PERF_M_N) return;
|
|
plat_add64(&mk_ns[kind], (int64_t)ns);
|
|
plat_inc64(&mk_n[kind]);
|
|
plat_add64(&mk_bytes[kind], (int64_t)bytes);
|
|
int64_t m = __atomic_load_n(&mk_max[kind], __ATOMIC_RELAXED);
|
|
while ((int64_t)ns > m && !__atomic_compare_exchange_n(&mk_max[kind], &m, (int64_t)ns, 1, __ATOMIC_RELAXED, __ATOMIC_RELAXED)) {}
|
|
}
|
|
|
|
void perf_mark_end(int kind, uint64_t t0, uint64_t bytes) {
|
|
if (t0) perf_mark_add(kind, kern_now_ns() - t0, bytes);
|
|
}
|
|
|
|
// Takes the sums since the last present into *f and adds them to the window.
|
|
static void mark_frame(MarkSums *f) {
|
|
for (int k = 0; k < PERF_M_N; k++) {
|
|
f->ns[k] = (uint64_t)plat_xchg64(&mk_ns[k], 0), f->n[k] = (uint64_t)plat_xchg64(&mk_n[k], 0);
|
|
f->bytes[k] = (uint64_t)plat_xchg64(&mk_bytes[k], 0), f->max[k] = (uint64_t)plat_xchg64(&mk_max[k], 0);
|
|
mk_win.ns[k] += f->ns[k], mk_win.n[k] += f->n[k], mk_win.bytes[k] += f->bytes[k];
|
|
if (f->max[k] > mk_win.max[k]) mk_win.max[k] = f->max[k];
|
|
}
|
|
}
|
|
|
|
// "; on any thread: file reads 12.3 ms (40, 5.1 MiB, longest 2.0 ms), ..." for the kinds with work, appended at line + n.
|
|
static int mark_text(const MarkSums *s, char *line, int n, size_t cap) {
|
|
int any = 0;
|
|
for (int k = 0; k < PERF_M_N && n >= 0 && n < (int)cap - 100; k++) {
|
|
if (!s->n[k]) continue;
|
|
n += snprintf(line + n, cap - (size_t)n, "%s %s %.1f ms (%llu, %.1f MiB, longest %.1f ms)",
|
|
any ? "," : "; on any thread:", mark_name[k], s->ns[k] / 1e6, (unsigned long long)s->n[k],
|
|
s->bytes[k] / 1048576.0, s->max[k] / 1e6);
|
|
any = 1;
|
|
}
|
|
return n;
|
|
}
|
|
|
|
// ---- NX2NAVI_TRACE=perf segments (host.h perf_segment) and scenes (perf_scene). The present thread keeps the running
|
|
// segment's frame times in 50 us bins (SEG_BINS, up to 204.8 ms; slower frames land in the last bin, the worst is kept
|
|
// apart), so a segment's 1% low is exact to 50 us at any frame rate. perf_segment and perf_scene come from any thread
|
|
// (the input script's guest thread, the game's loading threads) and leave a request under seg_lock for the present.
|
|
#define SEG_BINS 4096
|
|
#define SEG_BIN_NS 50000ull
|
|
#define SCENE_SETTLE_NS 10000000000ull
|
|
static PlatMutex seg_lock = PLAT_MUTEX_INIT;
|
|
static char seg_next[96], scene_name[256]; // seg_lock: the requested segment's name; the areas loaded since the last snapshot
|
|
static int seg_asked; // seg_lock: a segment was asked for
|
|
static uint64_t scene_at; // seg_lock: the last area load (plat_now_ns), 0 none since the last snapshot
|
|
static struct {
|
|
char name[96];
|
|
uint64_t f0, t0, frames, sum, max, max_frame, over25, over50, over100;
|
|
int64_t w0;
|
|
uint32_t hist[SEG_BINS];
|
|
MarkSums marks;
|
|
int on;
|
|
} seg;
|
|
|
|
__attribute__((weak)) void vk_mem_snapshot(uint64_t frame) { (void)frame; }
|
|
|
|
// ---- "mem: sizes" lines (host.h PerfSizes): one line per group; a line that grows past the log's line size goes out
|
|
// and the group goes on in the next.
|
|
#define SIZES_WEAK(f) __attribute__((weak)) void f(PerfSizes *s) { (void)s; }
|
|
SIZES_WEAK(mem_sizes) SIZES_WEAK(kern_sizes) SIZES_WEAK(setjmp_sizes) SIZES_WEAK(fs_host_sizes) SIZES_WEAK(romfs_sizes)
|
|
SIZES_WEAK(zstd_sizes) SIZES_WEAK(cfg_sizes) SIZES_WEAK(vk_mem_sizes) SIZES_WEAK(vk_gpa_sizes) SIZES_WEAK(vk_texture_sizes)
|
|
SIZES_WEAK(vk_exec_sizes) SIZES_WEAK(vk_sync_sizes) SIZES_WEAK(vk_usnap_sizes) SIZES_WEAK(nvn_cmd_sizes)
|
|
SIZES_WEAK(vk_pipeline_sizes) SIZES_WEAK(gfx_shader_sizes)
|
|
|
|
static void sizes_flush(PerfSizes *s) {
|
|
if (s->n > 0) rt_log("mem: sizes frame %llu, %s:%s", (unsigned long long)s->frame, s->group, s->line);
|
|
s->n = 0, s->line[0] = 0;
|
|
}
|
|
|
|
void perf_size(PerfSizes *s, const char *name, uint64_t count, uint64_t limit, uint64_t bytes) {
|
|
if (s->n > (int)sizeof s->line - 120) sizes_flush(s);
|
|
int n = snprintf(s->line + s->n, sizeof s->line - (size_t)s->n, " %s", name);
|
|
if (count != PERF_SIZE_NONE) n += snprintf(s->line + s->n + n, sizeof s->line - (size_t)(s->n + n), " %llu", (unsigned long long)count);
|
|
if (limit) n += snprintf(s->line + s->n + n, sizeof s->line - (size_t)(s->n + n), "/%llu", (unsigned long long)limit);
|
|
if (bytes != PERF_SIZE_NONE)
|
|
n += snprintf(s->line + s->n + n, sizeof s->line - (size_t)(s->n + n), "%s%.1f MiB", count != PERF_SIZE_NONE ? ", " : " ",
|
|
bytes / 1048576.0);
|
|
n += snprintf(s->line + s->n + n, sizeof s->line - (size_t)(s->n + n), ";");
|
|
if (n > 0 && s->n + n < (int)sizeof s->line) s->n += n;
|
|
else s->line[s->n] = 0;
|
|
}
|
|
|
|
static void sizes_log(uint64_t frame) {
|
|
static const struct { const char *group; void (*fn[7])(PerfSizes *); } groups[] = {
|
|
{"guest memory, kernel, files and settings", {mem_sizes, kern_sizes, setjmp_sizes, fs_host_sizes, romfs_sizes, zstd_sizes, cfg_sizes}},
|
|
{"GPU memory and textures", {vk_mem_sizes, vk_gpa_sizes, vk_texture_sizes}},
|
|
{"replay and submission", {vk_exec_sizes, vk_sync_sizes, vk_usnap_sizes, nvn_cmd_sizes}},
|
|
{"pipelines and shaders", {vk_pipeline_sizes, gfx_shader_sizes}},
|
|
};
|
|
PerfSizes s;
|
|
for (size_t g = 0; g < sizeof groups / sizeof *groups; g++) {
|
|
s.n = 0, s.line[0] = 0, s.frame = frame, s.group = groups[g].group;
|
|
for (int i = 0; i < 7 && groups[g].fn[i]; i++) groups[g].fn[i](&s);
|
|
sizes_flush(&s);
|
|
}
|
|
}
|
|
|
|
// ---- NX2NAVI_HANDLE_CENSUS=1 with NX2NAVI_TRACE=perf: the process's OS handles by kind (platform.h plat_handle_census)
|
|
// at the 600-frame report, when their count (the sizes line's "process handles") grew by HC_GROWTH or more since the
|
|
// last census. In a session of 2026-11-13 that count rose at every area load, 683 to 1095 in 11 minutes, and never
|
|
// fell, while the guest's handles stayed at 116-122: this says which kind grows. The census reads the system's whole
|
|
// handle table (2-5 ms and a buffer of a few MiB), so it runs on one thread of its own, started with the trace and
|
|
// woken by the report; a new thread per census would add its own Thread handle to what it counts.
|
|
#define HC_GROWTH 16
|
|
#define HC_KINDS 64
|
|
static PlatEvent hc_ev;
|
|
static volatile uint64_t hc_frame; // the report's frame, for the line
|
|
static int hc_on;
|
|
|
|
static int hc_cmp(const void *x, const void *y) {
|
|
const PlatHandleKind *a = x, *b = y;
|
|
return a->n < b->n ? 1 : a->n > b->n ? -1 : strcmp(a->name, b->name);
|
|
}
|
|
|
|
static void hc_main(void *arg) {
|
|
(void)arg;
|
|
static PlatHandleKind now[HC_KINDS], last[HC_KINDS];
|
|
int n_last = -1;
|
|
uint32_t count_last = 0, total_last = 0;
|
|
for (;;) {
|
|
plat_event_wait(&hc_ev);
|
|
uint64_t frame = __atomic_load_n(&hc_frame, __ATOMIC_RELAXED);
|
|
uint32_t count = plat_handle_count();
|
|
if (n_last >= 0 && count < count_last + HC_GROWTH) continue;
|
|
uint64_t t0 = kern_now_ns();
|
|
int n = plat_handle_census(now, HC_KINDS);
|
|
if (n < 0) {
|
|
rt_log("mem: handles frame %llu: the census by kind failed; not tried again", (unsigned long long)frame);
|
|
return;
|
|
}
|
|
double ms = (kern_now_ns() - t0) / 1e6;
|
|
qsort(now, (size_t)n, sizeof *now, hc_cmp);
|
|
uint32_t total = 0;
|
|
for (int i = 0; i < n; i++) total += now[i].n;
|
|
char line[1600];
|
|
int o = snprintf(line, sizeof line, "mem: handles frame %llu: %u in all", (unsigned long long)frame, total);
|
|
if (n_last >= 0) o += snprintf(line + o, sizeof line - (size_t)o, " (%+d since the last census)", (int)(total - total_last));
|
|
o += snprintf(line + o, sizeof line - (size_t)o, ":");
|
|
for (int i = 0; i < n && o < (int)sizeof line - 80; i++) {
|
|
o += snprintf(line + o, sizeof line - (size_t)o, "%s %s %u", i ? "," : "", now[i].name, now[i].n);
|
|
if (n_last < 0) continue;
|
|
int64_t was = 0;
|
|
for (int k = 0; k < n_last; k++)
|
|
if (!strcmp(last[k].name, now[i].name)) was = last[k].n;
|
|
if (now[i].n != was) o += snprintf(line + o, sizeof line - (size_t)o, " (%+lld)", (long long)now[i].n - was);
|
|
}
|
|
if (o < (int)sizeof line - 40) snprintf(line + o, sizeof line - (size_t)o, "; the census took %.1f ms", ms);
|
|
rt_log("%s", line);
|
|
memcpy(last, now, (size_t)n * sizeof *now);
|
|
n_last = n, count_last = count, total_last = total;
|
|
}
|
|
}
|
|
|
|
static void hc_start(void) {
|
|
if (!(rt_trace & RT_TRACE_PERF) || !cfg_bool("NX2NAVI_HANDLE_CENSUS")) return;
|
|
plat_event_init(&hc_ev, 0, 0);
|
|
hc_on = plat_thread_spawn(hc_main, NULL, "handle census", 0);
|
|
}
|
|
|
|
// The 600-frame report (perf_present): wakes the census thread, which decides whether the count grew enough.
|
|
static void hc_report(uint64_t frame) {
|
|
if (!hc_on) return;
|
|
__atomic_store_n(&hc_frame, frame, __ATOMIC_RELAXED);
|
|
plat_event_set(&hc_ev);
|
|
}
|
|
|
|
// The memory lines of a segment's end or a settled scene: the back end's (vk_mem_snapshot), then the sizes. Their
|
|
// time on the presenting thread delays the next frame: its "report" part.
|
|
static void mem_snapshot(uint64_t frame) {
|
|
uint64_t t0 = kern_now_ns();
|
|
vk_mem_snapshot(frame);
|
|
sizes_log(frame);
|
|
perf_report_part(kern_now_ns() - t0);
|
|
}
|
|
__attribute__((weak)) int vk_mem_vram(uint64_t *used, uint64_t *budget, int *exact) {
|
|
(void)used, (void)budget, (void)exact;
|
|
return 0;
|
|
}
|
|
|
|
// The world clock as the segment and scene lines give it: seconds, or "-" before the loaded save's first frame.
|
|
static const char *wtxt(int64_t w, char *b) {
|
|
if (w < 0) return "-";
|
|
snprintf(b, 24, "%.1f", w / 1e6);
|
|
return b;
|
|
}
|
|
|
|
void perf_segment(const char *name) {
|
|
if (!(rt_trace & RT_TRACE_PERF)) return;
|
|
plat_mutex_lock(&seg_lock);
|
|
snprintf(seg_next, sizeof seg_next, "%s", name && *name ? name : "(unnamed)");
|
|
seg_asked = 1;
|
|
plat_mutex_unlock(&seg_lock);
|
|
}
|
|
|
|
static volatile uint64_t area_load_ns; // plat_now_ns of the last area load (perf_scene), 0 none
|
|
|
|
uint64_t perf_area_load_ns(void) { return __atomic_load_n(&area_load_ns, __ATOMIC_RELAXED); }
|
|
|
|
void perf_scene(const char *name) {
|
|
__atomic_store_n(&area_load_ns, plat_now_ns(), __ATOMIC_RELAXED);
|
|
stutter_area(name);
|
|
if (!(rt_trace & RT_TRACE_PERF)) return;
|
|
char wb[24];
|
|
rt_log("scene: %s loads (frame %llu, world %s s)", name,
|
|
(unsigned long long)__atomic_load_n(&gfx_counters.frames, __ATOMIC_RELAXED), wtxt(frame_step_world_us(), wb));
|
|
plat_mutex_lock(&seg_lock);
|
|
size_t n = strlen(scene_name);
|
|
if (n + strlen(name) + 2 < sizeof scene_name) snprintf(scene_name + n, sizeof scene_name - n, "%s%s", n ? ", " : "", name);
|
|
scene_at = plat_now_ns();
|
|
plat_mutex_unlock(&seg_lock);
|
|
}
|
|
|
|
// The process's memory and the VRAM in use, for the segment and scene lines.
|
|
static void mem_text(char *out, size_t cap, int vram) {
|
|
uint64_t res, prv, used, budget;
|
|
int exact;
|
|
plat_process_memory(&res, &prv);
|
|
int n = snprintf(out, cap, "ram working set %.0f MiB, private %.0f MiB", res / 1048576.0, prv / 1048576.0);
|
|
if (vram && vk_mem_vram(&used, &budget, &exact) && n > 0 && (size_t)n < cap)
|
|
snprintf(out + n, cap - (size_t)n, "; vram %.0f of %.0f MiB", used / 1048576.0, budget / 1048576.0);
|
|
}
|
|
|
|
static void seg_close(uint64_t frame, uint64_t now, int at_exit) {
|
|
if (!seg.on) return;
|
|
seg.on = 0;
|
|
char mem[160], marks[700];
|
|
mem_text(mem, sizeof mem, !at_exit);
|
|
marks[0] = 0;
|
|
mark_text(&seg.marks, marks, 0, sizeof marks);
|
|
if (!seg.frames || !seg.sum) {
|
|
rt_log("segment: '%s' ended at frame %llu with no frames timed; %s", seg.name, (unsigned long long)frame, mem);
|
|
return;
|
|
}
|
|
uint64_t cut = (seg.frames + 99) / 100, acc = 0, low = 0; // the slowest 1% of frames: the upper edge of its bin
|
|
for (int b = SEG_BINS - 1; b >= 0; b--)
|
|
if ((acc += seg.hist[b]) >= cut) { low = (uint64_t)(b + 1) * SEG_BIN_NS; break; }
|
|
if (low > seg.max) low = seg.max;
|
|
char w0[24], w1[24];
|
|
rt_log("segment: '%s' frames %llu-%llu, world %s to %s s: %llu frames in %.1f s, mean %.2f ms (%.1f fps), 1%% low %.1f "
|
|
"fps (%.2f ms), worst %.1f ms at frame %llu; over 25 ms %llu, 50 ms %llu, 100 ms %llu; %s%s",
|
|
seg.name, (unsigned long long)seg.f0, (unsigned long long)frame, wtxt(seg.w0, w0), wtxt(frame_step_world_us(), w1),
|
|
(unsigned long long)seg.frames, (now - seg.t0) / 1e9, seg.sum / 1e6 / seg.frames, seg.frames * 1e9 / seg.sum,
|
|
low ? 1e9 / low : 0.0, low / 1e6, seg.max / 1e6, (unsigned long long)seg.max_frame,
|
|
(unsigned long long)seg.over25, (unsigned long long)seg.over50, (unsigned long long)seg.over100, mem, marks);
|
|
if (!at_exit) mem_snapshot(frame);
|
|
}
|
|
|
|
static void seg_open(const char *name, uint64_t frame, uint64_t now) {
|
|
memset(&seg, 0, sizeof seg);
|
|
snprintf(seg.name, sizeof seg.name, "%s", name);
|
|
seg.f0 = frame, seg.t0 = now, seg.w0 = frame_step_world_us(), seg.on = 1;
|
|
}
|
|
|
|
// Each present while the trace is on: the frame into the running segment (d 0: the first present), then a requested
|
|
// segment change and a settled scene's snapshot.
|
|
static void seg_frame(uint64_t frame, uint64_t now, uint64_t d, const MarkSums *fm) {
|
|
if (!seg.on && seg.f0 == 0) seg_open("boot", frame, now); // the first present opens the boot segment
|
|
if (seg.on && d) {
|
|
seg.frames++, seg.sum += d;
|
|
uint64_t b = d / SEG_BIN_NS;
|
|
seg.hist[b < SEG_BINS ? b : SEG_BINS - 1]++;
|
|
if (d > seg.max) seg.max = d, seg.max_frame = frame;
|
|
seg.over25 += d > 25000000ull, seg.over50 += d > 50000000ull, seg.over100 += d > 100000000ull;
|
|
for (int k = 0; k < PERF_M_N; k++) {
|
|
seg.marks.ns[k] += fm->ns[k], seg.marks.n[k] += fm->n[k], seg.marks.bytes[k] += fm->bytes[k];
|
|
if (fm->max[k] > seg.marks.max[k]) seg.marks.max[k] = fm->max[k];
|
|
}
|
|
}
|
|
char name[96], scenes[256];
|
|
int asked = 0, settled = 0;
|
|
plat_mutex_lock(&seg_lock);
|
|
if (seg_asked) asked = 1, seg_asked = 0, memcpy(name, seg_next, sizeof name);
|
|
if (scene_at && now - scene_at >= SCENE_SETTLE_NS)
|
|
settled = 1, scene_at = 0, memcpy(scenes, scene_name, sizeof scenes), scene_name[0] = 0;
|
|
plat_mutex_unlock(&seg_lock);
|
|
if (asked) {
|
|
seg_close(frame, now, 0);
|
|
seg_open(name, frame, now);
|
|
char wb[24];
|
|
rt_log("segment: '%s' starts at frame %llu, world %s s", name, (unsigned long long)frame, wtxt(seg.w0, wb));
|
|
}
|
|
if (settled) {
|
|
char mem[160];
|
|
mem_text(mem, sizeof mem, 1);
|
|
char wb[24];
|
|
rt_log("scene: %s settled (no area loaded for 10 s) at frame %llu, world %s s; %s", scenes,
|
|
(unsigned long long)frame, wtxt(frame_step_world_us(), wb), mem);
|
|
mem_snapshot(frame);
|
|
}
|
|
}
|
|
|
|
// ---- Frame-time summary, always on: every 60 s of play and at exit one line of frame count, mean fps, 1% low and the
|
|
// frames over 25/50/100 ms, then the worst frames of the period with the render thread's waits in them. Per frame: a
|
|
// histogram increment, the compare against the worst list, a memset of the wait array. No allocation.
|
|
#define FT_BINS 1024 // 0.25 ms bins up to 256 ms; slower frames land in the last bin
|
|
#define FT_WORST 5
|
|
#define FT_PERIOD_NS 60000000000ull
|
|
typedef struct {
|
|
uint64_t frame, ns, wait[PERF_N], replay;
|
|
uint64_t op_ns[PERF_RP_N], op_n[PERF_RP_N], max_ns, hold_ns; // NX2NAVI_REPLAY_TIME: the frame's replay ops
|
|
uint64_t replay_cpu; // the replaying thread's CPU time in the frame's replay
|
|
uint32_t max_op;
|
|
} FtWorst;
|
|
// What a frame over 25 ms spent its time on, so a count of slow frames says where to look instead of only that they
|
|
// happened. A frame is charged to the largest part when that part is at least a quarter of it, and to "unattributed"
|
|
// otherwise - the part of a slow frame none of the recorded waits explains (the GPU, or a stall outside them).
|
|
// The replay's part is its time without the pipeline, translation and texture waits, which all happen inside it: with
|
|
// them in, every frame that waited 900 ms for a pipeline was charged to "replay", the larger number, and a log
|
|
// could not tell a pipeline stall from a slow replay.
|
|
// "census" is the address-space walk of NX2NAVI_MEM_CENSUS: census_check's on the presenting thread after a present,
|
|
// whose time is charged to the next frame, which it delays, and the part of a frame vk_memory.c census_main's walk on
|
|
// its own thread overlapped (perf_census.h census_charge). "report" is the memory report's time on the presenting
|
|
// thread (vk_memory.c vk_mem_census every 600 frames with the perf trace, every 3600 without; the snapshots and sizes
|
|
// lines here), charged to the next frame too. "hand-off" is the wait for the present thread to take the previous
|
|
// picture (PERF_HANDOFF): its own pacing and its present call, an overlay's frame limiter included.
|
|
// stutter_map.c cause_short and tools/stutter_map.py read these names, in this order.
|
|
enum { FT_C_PIPE, FT_C_XLATE, FT_C_TEX, FT_C_FENCE, FT_C_PACE, FT_C_HANDOFF, FT_C_REPLAY, FT_C_CENSUS, FT_C_REPORT,
|
|
FT_C_OTHER, FT_C_N };
|
|
_Static_assert(FT_C_N == STUTTER_CAUSES, "stutter_map.c cause_short and its counts follow FT_C_*");
|
|
static const char *const ft_cause_name[FT_C_N] = { "pipeline", "translation", "texture", "fence", "pacing", "hand-off",
|
|
"replay", "census", "report", "unattributed" };
|
|
static uint64_t census_part_ns; // present thread: the census walks since the last present (census_check)
|
|
static volatile int64_t report_part_ns; // the memory report's time since the last present (perf_report_part), any thread
|
|
static volatile uint64_t walk_t0, walk_t1; // census_main's last walk (perf_census_walk); walk_t1 0 while it runs
|
|
static volatile uint64_t census_walked = UINT64_MAX; // the frame census_check walked last
|
|
|
|
void perf_census_walk(int begin) {
|
|
if (begin) {
|
|
__atomic_store_n(&walk_t1, 0, __ATOMIC_RELAXED);
|
|
__atomic_store_n(&walk_t0, kern_now_ns(), __ATOMIC_RELEASE);
|
|
} else {
|
|
__atomic_store_n(&walk_t1, kern_now_ns(), __ATOMIC_RELEASE);
|
|
}
|
|
}
|
|
|
|
void perf_report_part(uint64_t ns) { plat_add64(&report_part_ns, (int64_t)ns); }
|
|
|
|
uint64_t perf_census_walked_frame(void) { return __atomic_load_n(&census_walked, __ATOMIC_ACQUIRE); }
|
|
static struct {
|
|
uint64_t t0, frames, sum, over25, over50, over100;
|
|
uint32_t hist[FT_BINS];
|
|
uint64_t slow_n[FT_C_N], slow_ns[FT_C_N]; // frames over 25 ms by cause
|
|
FtWorst worst[FT_WORST]; // slowest first
|
|
int nworst;
|
|
} ft;
|
|
static uint64_t summary_t0; // start of the current period (0: not started)
|
|
|
|
// The exit's summary (perf_summary_flush) runs on the exiting thread while the present thread may still add frames to
|
|
// `ft` and write its own reports (ft_frame, session_report), with no lock between them: the exit lines came out torn,
|
|
// or twice. ft_stop marks the end, after which the present thread adds nothing, and waits a little for an update
|
|
// already under way; it is the exiting thread that waits, never the present thread. Both sides are sequentially
|
|
// consistent, so either the present thread sees ft_ending or ft_stop sees it counted in ft_busy.
|
|
static volatile int32_t ft_ending, ft_busy;
|
|
|
|
static int ft_enter(void) {
|
|
__atomic_add_fetch(&ft_busy, 1, __ATOMIC_SEQ_CST);
|
|
return !__atomic_load_n(&ft_ending, __ATOMIC_SEQ_CST);
|
|
}
|
|
|
|
static void ft_leave(void) { __atomic_sub_fetch(&ft_busy, 1, __ATOMIC_SEQ_CST); }
|
|
|
|
static void ft_stop(void) {
|
|
__atomic_store_n(&ft_ending, 1, __ATOMIC_SEQ_CST);
|
|
for (int i = 0; i < 50 && __atomic_load_n(&ft_busy, __ATOMIC_SEQ_CST); i++) plat_sleep_ms(1);
|
|
}
|
|
|
|
// NX2NAVI_REPLAY_TIME=1: how the replay splits between the kinds of op it walks, reported with the frame-time summary.
|
|
// The replay is recorded on one thread, so these need no atomics. The kinds are PERF_RP_* in host.h.
|
|
// NX2NAVI_LOCK_TIME=1 (default 0): the replay threads time every lock they have to wait for (platform.h
|
|
// plat_lock_timing), kept per asking site, and the frame-time summary lists the sites that waited longest since the last
|
|
// summary, with the recorder's full-ring and drain waits. Sites are code addresses; "ref" is perf_lock_timing_here's,
|
|
// which the link map names, so the others resolve as offsets from it.
|
|
#define LT_N 512
|
|
static struct { void *site; uint64_t ns, n, max, ns0, n0; } lt[LT_N];
|
|
static struct { void *site; uint64_t ns, n, max, ns0, n0; } lh[LT_N]; // texture lock holds over 1 ms (perf_lock_hold)
|
|
static struct { void *site; uint64_t ns, n, max, ns0, n0; } lq[LT_N]; // queue lock holds of 5 ms or more (perf_qlock_hold)
|
|
static uint64_t lt_lost_ns, lt_rec0[2];
|
|
static volatile int64_t fr_hold_ns; // the texture lock's holds over 1 ms since the last present (ft_frame)
|
|
void (*perf_rec_waits)(uint64_t *full_ns, uint64_t *drain_ns);
|
|
|
|
static void lt_add(typeof(lt[0]) *tab, void *site, uint64_t ns) {
|
|
uint32_t h = (uint32_t)(((uintptr_t)site * 0x9E3779B97F4A7C15ull) >> 55);
|
|
for (uint32_t k = 0; k < 32; k++) {
|
|
typeof(lt[0]) *e = &tab[(h + k) % LT_N];
|
|
void *cur = __atomic_load_n(&e->site, __ATOMIC_ACQUIRE);
|
|
if (!cur && __atomic_compare_exchange_n(&e->site, &cur, site, 0, __ATOMIC_ACQ_REL, __ATOMIC_ACQUIRE)) cur = site;
|
|
if (cur != site) continue;
|
|
__atomic_fetch_add(&e->ns, ns, __ATOMIC_RELAXED);
|
|
__atomic_fetch_add(&e->n, 1, __ATOMIC_RELAXED);
|
|
uint64_t m = __atomic_load_n(&e->max, __ATOMIC_RELAXED);
|
|
while (ns > m && !__atomic_compare_exchange_n(&e->max, &m, ns, 1, __ATOMIC_RELAXED, __ATOMIC_RELAXED)) {}
|
|
return;
|
|
}
|
|
__atomic_fetch_add(<_lost_ns, ns, __ATOMIC_RELAXED);
|
|
}
|
|
|
|
static void lt_note(void *site, uint64_t ns) { lt_add(lt, site, ns); }
|
|
void perf_lock_hold(void *site, uint64_t ns) {
|
|
lt_add((typeof(lt[0]) *)lh, site, ns);
|
|
plat_add64(&fr_hold_ns, (int64_t)ns);
|
|
}
|
|
void perf_qlock_hold(void *site, uint64_t ns) { lt_add((typeof(lt[0]) *)lq, site, ns); }
|
|
|
|
static int lt_on = -1;
|
|
int perf_lock_holds_on(void) {
|
|
if (lt_on < 0) lt_on = cfg_bool("NX2NAVI_LOCK_TIME");
|
|
return lt_on;
|
|
}
|
|
void perf_lock_timing_here(void) {
|
|
if (lt_on < 0) lt_on = cfg_bool("NX2NAVI_LOCK_TIME");
|
|
if (lt_on) plat_lock_timing(lt_note);
|
|
}
|
|
|
|
// The eight sites of tab with the most time since the last summary, appended to line; returns the period's total and
|
|
// sets *count, then starts a new period.
|
|
static uint64_t lt_top(typeof(lt[0]) *tab, char *line, int *n, size_t cap, uint64_t *count) {
|
|
uint64_t all = 0, cnt = 0;
|
|
int top[8], ntop = 0;
|
|
for (int i = 0; i < LT_N; i++) {
|
|
if (!__atomic_load_n(&tab[i].site, __ATOMIC_ACQUIRE)) continue;
|
|
uint64_t d = __atomic_load_n(&tab[i].ns, __ATOMIC_RELAXED) - tab[i].ns0;
|
|
all += d, cnt += __atomic_load_n(&tab[i].n, __ATOMIC_RELAXED) - tab[i].n0;
|
|
int at;
|
|
if (ntop < 8) at = ntop++;
|
|
else if (d > tab[top[7]].ns - tab[top[7]].ns0) at = 7;
|
|
else continue;
|
|
top[at] = i;
|
|
for (int j = at; j > 0; j--) { // keep top sorted by this period's time
|
|
uint64_t x = tab[top[j]].ns - tab[top[j]].ns0, y = tab[top[j - 1]].ns - tab[top[j - 1]].ns0;
|
|
if (x <= y) break;
|
|
int t = top[j]; top[j] = top[j - 1], top[j - 1] = t;
|
|
}
|
|
}
|
|
for (int j = 0; j < ntop && *n >= 0 && *n < (int)cap - 80; j++) {
|
|
typeof(lt[0]) *e = &tab[top[j]];
|
|
*n += snprintf(line + *n, cap - *n, " %p %.1f ms (%llu, max %.2f ms);", e->site, (e->ns - e->ns0) / 1e6,
|
|
(unsigned long long)(e->n - e->n0), e->max / 1e6);
|
|
}
|
|
for (int i = 0; i < LT_N; i++) tab[i].ns0 = tab[i].ns, tab[i].n0 = tab[i].n, tab[i].max = 0;
|
|
*count = cnt;
|
|
return all;
|
|
}
|
|
|
|
// The lock lines of a summary: the replay threads' waits with the recorder's, then the texture lock's and the queue
|
|
// lock's long holds.
|
|
static void lt_report(void) {
|
|
uint64_t rec[2] = {0, 0}, waits, holds;
|
|
if (perf_rec_waits) perf_rec_waits(&rec[0], &rec[1]);
|
|
char line[1400], top[1200];
|
|
int n = 0;
|
|
top[0] = 0;
|
|
uint64_t all = lt_top(lt, top, &n, sizeof top, &waits);
|
|
rt_log("frametime: replay lock waits: %.0f ms (%llu waits, %.0f ms unplaced); recorder ring full %.0f ms, drains "
|
|
"%.0f ms; ref %p:%s", all / 1e6, (unsigned long long)waits, lt_lost_ns / 1e6, (rec[0] - lt_rec0[0]) / 1e6,
|
|
(rec[1] - lt_rec0[1]) / 1e6, (void *)perf_lock_timing_here, top);
|
|
n = 0, top[0] = 0;
|
|
all = lt_top((typeof(lt[0]) *)lh, top, &n, sizeof top, &holds);
|
|
snprintf(line, sizeof line, "frametime: texture lock held over 1 ms: %.0f ms (%llu holds):%s", all / 1e6,
|
|
(unsigned long long)holds, top);
|
|
rt_log("%s", line);
|
|
n = 0, top[0] = 0;
|
|
all = lt_top((typeof(lt[0]) *)lq, top, &n, sizeof top, &holds);
|
|
snprintf(line, sizeof line, "frametime: queue lock held 5 ms or more: %.0f ms (%llu holds):%s", all / 1e6,
|
|
(unsigned long long)holds, top);
|
|
rt_log("%s", line);
|
|
lt_rec0[0] = rec[0], lt_rec0[1] = rec[1], lt_lost_ns = 0;
|
|
}
|
|
|
|
static uint64_t rp_ns[PERF_RP_N], rp_n[PERF_RP_N];
|
|
void perf_replay_op(int cat, uint64_t ns) {
|
|
if ((unsigned)cat < PERF_RP_N) rp_ns[cat] += ns, rp_n[cat]++;
|
|
}
|
|
|
|
// The replay ops since the last present (NX2NAVI_REPLAY_TIME), so a frame over 25 ms charged to the replay can say
|
|
// what its replay was: how many ops of each kind, their time, the slowest op and how long the texture lock was held
|
|
// over 1 ms (NX2NAVI_LOCK_TIME). The present thread takes and clears them in ft_frame; the replay adds.
|
|
static volatile int64_t fr_ns[PERF_RP_N], fr_n[PERF_RP_N], fr_max_ns, fr_max_op;
|
|
// Over the period: the frames over 25 ms charged to the replay, their sums, and how often each op was a frame's slowest.
|
|
static uint64_t sr_n, sr_ns[PERF_RP_N], sr_cnt[PERF_RP_N], sr_max_ns, sr_hold_ns, sr_max_op[256], sr_wall, sr_cpu;
|
|
|
|
void perf_replay_op_at(int cat, uint32_t op, uint64_t ns) {
|
|
if ((unsigned)cat >= PERF_RP_N) return;
|
|
perf_replay_op(cat, ns);
|
|
plat_add64(&fr_ns[cat], (int64_t)ns);
|
|
plat_add64(&fr_n[cat], 1);
|
|
// one replay thread at a time records ops; a race with the present only misnames the frame's slowest op
|
|
if ((int64_t)ns > fr_max_ns) fr_max_ns = (int64_t)ns, fr_max_op = op;
|
|
}
|
|
|
|
static void ft_report(uint64_t now, const char *tag) {
|
|
if (ft.frames && ft.sum) {
|
|
uint64_t cut = (ft.frames + 99) / 100, acc = 0, low = 0; // the slowest 1% of frames
|
|
for (int b = FT_BINS - 1; b >= 0; b--) {
|
|
acc += ft.hist[b];
|
|
if (acc >= cut) { low = (uint64_t)(b + 1) * 250000ull; break; } // upper edge of the bin
|
|
}
|
|
rt_log("frametime: %s: %llu frames in %.1f s, mean %.1f fps, 1%% low %.1f fps, over 25 ms %llu, 50 ms %llu, 100 ms %llu",
|
|
tag, (unsigned long long)ft.frames, (now - ft.t0) / 1e9, ft.frames * 1e9 / ft.sum, low ? 1e9 / low : 0.0,
|
|
(unsigned long long)ft.over25, (unsigned long long)ft.over50, (unsigned long long)ft.over100);
|
|
if (ft.over25) {
|
|
char line[512];
|
|
int n = snprintf(line, sizeof line, "frametime: over 25 ms by cause:");
|
|
for (int c = 0; c < FT_C_N && n > 0 && n < (int)sizeof line; c++)
|
|
if (ft.slow_n[c])
|
|
n += snprintf(line + n, sizeof line - n, " %s %llu (%.1f ms avg)", ft_cause_name[c],
|
|
(unsigned long long)ft.slow_n[c], (double)ft.slow_ns[c] / ft.slow_n[c] / 1e6);
|
|
if (n > 0) rt_log("%s", line);
|
|
}
|
|
if (rp_n[PERF_RP_DRAW] || rp_n[PERF_RP_BIND] || rp_n[PERF_RP_XFER] || rp_n[PERF_RP_OTHER]) {
|
|
uint64_t all = 0;
|
|
for (int c = 0; c < PERF_RP_N; c++) all += rp_ns[c];
|
|
rt_log("frametime: replay ops: %.0f ms in all (%.0f%% of the period); draw %.0f ms (%llu), bind %.0f ms (%llu), "
|
|
"xfer %.0f ms (%llu), other %.0f ms (%llu)", all / 1e6, 100.0 * all / (now - ft.t0),
|
|
rp_ns[PERF_RP_DRAW] / 1e6, (unsigned long long)rp_n[PERF_RP_DRAW], rp_ns[PERF_RP_BIND] / 1e6,
|
|
(unsigned long long)rp_n[PERF_RP_BIND], rp_ns[PERF_RP_XFER] / 1e6, (unsigned long long)rp_n[PERF_RP_XFER],
|
|
rp_ns[PERF_RP_OTHER] / 1e6, (unsigned long long)rp_n[PERF_RP_OTHER]);
|
|
}
|
|
if (lt_on > 0) lt_report();
|
|
if (per_replay_ns && per_replay_cpu_ns)
|
|
rt_log("frametime: replay: %.0f ms, the replaying thread on the CPU for %.0f ms of it (%.0f%%); the frames over "
|
|
"25 ms charged to the replay: %.0f ms, on the CPU %.0f ms (%.0f%%)", per_replay_ns / 1e6,
|
|
per_replay_cpu_ns / 1e6, 100.0 * per_replay_cpu_ns / per_replay_ns, sr_wall / 1e6, sr_cpu / 1e6,
|
|
sr_wall ? 100.0 * sr_cpu / sr_wall : 0.0);
|
|
if (sr_n && (sr_cnt[PERF_RP_DRAW] || sr_cnt[PERF_RP_BIND])) { // the replay of the frames over 25 ms charged to it, per frame
|
|
int top[3] = {-1, -1, -1};
|
|
for (int o = 0; o < 256; o++)
|
|
for (int j = 0; j < 3; j++)
|
|
if (sr_max_op[o] && (top[j] < 0 || sr_max_op[o] > sr_max_op[top[j]])) {
|
|
for (int k = 2; k > j; k--) top[k] = top[k - 1];
|
|
top[j] = o;
|
|
break;
|
|
}
|
|
char ops[160];
|
|
int n = 0;
|
|
ops[0] = 0;
|
|
for (int j = 0; j < 3 && top[j] >= 0; j++)
|
|
n += snprintf(ops + n, sizeof ops - n, "%s%s %llu", j ? ", " : "", nvn_op_name((uint32_t)top[j]),
|
|
(unsigned long long)sr_max_op[top[j]]);
|
|
rt_log("frametime: slow replay frames %llu, per frame: draws %.1f ms (%.0f), binds %.1f ms (%.0f), transfers "
|
|
"%.1f ms (%.0f); its slowest op %.1f ms (%s); texture lock held over 1 ms %.1f ms",
|
|
(unsigned long long)sr_n, sr_ns[PERF_RP_DRAW] / 1e6 / sr_n, (double)sr_cnt[PERF_RP_DRAW] / sr_n,
|
|
sr_ns[PERF_RP_BIND] / 1e6 / sr_n, (double)sr_cnt[PERF_RP_BIND] / sr_n, sr_ns[PERF_RP_XFER] / 1e6 / sr_n,
|
|
(double)sr_cnt[PERF_RP_XFER] / sr_n, sr_max_ns / 1e6 / sr_n, ops, sr_hold_ns / 1e6 / sr_n);
|
|
}
|
|
for (int i = 0; i < ft.nworst; i++) {
|
|
const FtWorst *w = &ft.worst[i];
|
|
char ops[200] = "";
|
|
if (w->op_n[PERF_RP_DRAW] || w->op_n[PERF_RP_BIND] || w->op_n[PERF_RP_XFER])
|
|
snprintf(ops, sizeof ops, "; ops: draws %.1f ms (%llu), binds %.1f ms (%llu), transfers %.1f ms (%llu), slowest "
|
|
"%s %.1f ms, texture lock held %.1f ms", w->op_ns[PERF_RP_DRAW] / 1e6,
|
|
(unsigned long long)w->op_n[PERF_RP_DRAW], w->op_ns[PERF_RP_BIND] / 1e6,
|
|
(unsigned long long)w->op_n[PERF_RP_BIND], w->op_ns[PERF_RP_XFER] / 1e6,
|
|
(unsigned long long)w->op_n[PERF_RP_XFER], nvn_op_name(w->max_op), w->max_ns / 1e6, w->hold_ns / 1e6);
|
|
rt_log("frametime: worst frame %llu: %.1f ms; shader translation %.1f, pipeline build %.1f, texture upload %.1f (astc %.1f), replay %.1f (on the CPU %.1f), fence/present wait %.1f, pacing %.1f, hand-off %.1f%s",
|
|
(unsigned long long)w->frame, w->ns / 1e6, w->wait[PERF_XLATE] / 1e6, w->wait[PERF_PIPE] / 1e6,
|
|
w->wait[PERF_TEX] / 1e6, w->wait[PERF_ASTC] / 1e6, w->replay / 1e6, w->replay_cpu / 1e6,
|
|
(w->wait[PERF_FENCE] + w->wait[PERF_DRAIN]) / 1e6, w->wait[PERF_PACE] / 1e6,
|
|
w->wait[PERF_HANDOFF] / 1e6, ops);
|
|
}
|
|
}
|
|
memset(&ft, 0, sizeof ft);
|
|
memset(rp_ns, 0, sizeof rp_ns);
|
|
memset(rp_n, 0, sizeof rp_n);
|
|
sr_n = sr_max_ns = sr_hold_ns = sr_wall = sr_cpu = 0;
|
|
per_replay_ns = per_replay_cpu_ns = 0;
|
|
memset(sr_ns, 0, sizeof sr_ns), memset(sr_cnt, 0, sizeof sr_cnt), memset(sr_max_op, 0, sizeof sr_max_op);
|
|
ft.t0 = now;
|
|
}
|
|
|
|
__attribute__((weak)) void gfx_exit_log(void) {}
|
|
__attribute__((weak)) void vk_gpu_parts_log(uint64_t frame, uint64_t t0, uint64_t t1, double fence_ms) {
|
|
(void)frame, (void)t0, (void)t1, (void)fence_ms;
|
|
}
|
|
__attribute__((weak)) void vk_mem_rank_log(const char *when) { (void)when; }
|
|
|
|
// The session's reports when the window loses the focus in play: the frame-time summary of the period so far (which
|
|
// starts a new period), the stutter map and the memory report's growth ranking, at most every SESSION_REPORT_GAP_NS.
|
|
// They are written at the exit too (perf_summary_flush, vk_mem_exit_log), but a process ended from outside, or by a
|
|
// path that skips them, leaves none: a session of 2026-11-13 ended 8 s after its window lost the focus, after 7 minutes
|
|
// of play, with no ranking (one every 10 minutes then) and no map of its last minute. gfx_present.c
|
|
// gfx_window_focus_changed asks for them; the present thread writes them at its next present (perf_present). Formatting
|
|
// only, after copying the stutter map under its lock (stutter_map.c stutter_report): no device call, no wait.
|
|
#define SESSION_REPORT_GAP_NS 60000000000ull
|
|
static volatile int32_t session_due;
|
|
|
|
void perf_focus_lost(void) {
|
|
if (frame_step_world_us() >= 0) plat_xchg32(&session_due, 1); // in play: the loaded save's world clock runs
|
|
}
|
|
|
|
static void session_report(uint64_t now) {
|
|
static uint64_t last;
|
|
if (last && now - last < SESSION_REPORT_GAP_NS) return;
|
|
last = now;
|
|
if (summary_t0) {
|
|
ft_report(now, "at focus loss");
|
|
summary_t0 = now;
|
|
}
|
|
stutter_report("at focus loss");
|
|
vk_mem_rank_log("at focus loss, after");
|
|
}
|
|
// The renderer's per-frame texture work (vk_texture.c): closes the frame's sums; d is the frame's interval.
|
|
__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) {
|
|
ft_report(kern_now_ns(), "exit");
|
|
stutter_report("exit");
|
|
gfx_exit_log();
|
|
}
|
|
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) {
|
|
int64_t rep = plat_xchg64(&frame_replay_ns, 0);
|
|
vk_texstat_frame(frame, d);
|
|
uint64_t f_cpu = (uint64_t)plat_xchg64(&frame_replay_cpu_ns, 0);
|
|
per_replay_ns += rep > 0 ? (uint64_t)rep : 0, per_replay_cpu_ns += f_cpu;
|
|
uint64_t f_ns[PERF_RP_N], f_n[PERF_RP_N], f_max = (uint64_t)plat_xchg64(&fr_max_ns, 0);
|
|
uint64_t f_hold = (uint64_t)plat_xchg64(&fr_hold_ns, 0);
|
|
uint32_t f_op = (uint32_t)fr_max_op;
|
|
for (int c = 0; c < PERF_RP_N; c++) f_ns[c] = (uint64_t)plat_xchg64(&fr_ns[c], 0), f_n[c] = (uint64_t)plat_xchg64(&fr_n[c], 0);
|
|
if (!add) return (uint64_t)rep;
|
|
if (!summary_t0) { // the first present starts the period; there is no interval yet
|
|
summary_t0 = now;
|
|
ft.t0 = now;
|
|
return (uint64_t)rep;
|
|
}
|
|
ft.frames++;
|
|
ft.sum += d;
|
|
uint64_t b = d / 250000ull;
|
|
ft.hist[b < FT_BINS ? b : FT_BINS - 1]++;
|
|
if (d > 25000000ull) ft.over25++;
|
|
if (d > 50000000ull) ft.over50++;
|
|
if (d > 100000000ull) ft.over100++;
|
|
// which part it went to: for a frame over 25 ms, and for the stutter map's hitches, which are 12 ms at least
|
|
// (stutter_map.c)
|
|
uint64_t part[FT_C_N] = {0};
|
|
int best = FT_C_OTHER;
|
|
uint64_t census_ns = census_part_ns;
|
|
census_part_ns = 0;
|
|
int64_t report_ns = __atomic_load_n(&report_part_ns, __ATOMIC_RELAXED) ? plat_xchg64(&report_part_ns, 0) : 0;
|
|
if (d > 25000000ull || (stutter_map_on && d >= 12000000ull)) {
|
|
part[FT_C_CENSUS] = census_ns < d ? census_ns : d;
|
|
part[FT_C_REPORT] = report_ns <= 0 ? 0 : (uint64_t)report_ns < d ? (uint64_t)report_ns : d;
|
|
part[FT_C_PIPE] = frame_ns[PERF_PIPE];
|
|
part[FT_C_XLATE] = frame_ns[PERF_XLATE];
|
|
part[FT_C_TEX] = frame_ns[PERF_TEX];
|
|
part[FT_C_FENCE] = frame_ns[PERF_FENCE] + frame_ns[PERF_DRAIN];
|
|
part[FT_C_PACE] = frame_ns[PERF_PACE];
|
|
part[FT_C_HANDOFF] = frame_ns[PERF_HANDOFF];
|
|
part[FT_C_REPLAY] = rep > 0 ? (uint64_t)rep : 0;
|
|
uint64_t inside = part[FT_C_PIPE] + part[FT_C_XLATE] + part[FT_C_TEX]; // waits on the replay thread
|
|
part[FT_C_REPLAY] = part[FT_C_REPLAY] > inside ? part[FT_C_REPLAY] - inside : 0;
|
|
uint64_t known = 0;
|
|
for (int c = 0; c < FT_C_OTHER; c++) known += part[c];
|
|
part[FT_C_OTHER] = d > known ? d - known : 0;
|
|
uint64_t w0 = __atomic_load_n(&walk_t0, __ATOMIC_ACQUIRE), w1 = __atomic_load_n(&walk_t1, __ATOMIC_ACQUIRE);
|
|
census_charge(now, d, w0, w1, &part[FT_C_REPLAY], &part[FT_C_OTHER], &part[FT_C_CENSUS]);
|
|
for (int c = 0; c < FT_C_N; c++)
|
|
if (part[c] > part[best]) best = c;
|
|
if (part[best] * 4 < d) best = FT_C_OTHER; // no recorded part explains a quarter of the frame
|
|
}
|
|
stutter_frame(frame, now, d, part, ft_cause_name, FT_C_N, best);
|
|
if (d > 25000000ull) {
|
|
ft.slow_n[best]++;
|
|
ft.slow_ns[best] += d;
|
|
if (best == FT_C_REPLAY) {
|
|
sr_n++, sr_max_ns += f_max, sr_hold_ns += f_hold, sr_max_op[f_op & 255]++;
|
|
sr_wall += rep > 0 ? (uint64_t)rep : 0, sr_cpu += f_cpu;
|
|
for (int c = 0; c < PERF_RP_N; c++) sr_ns[c] += f_ns[c], sr_cnt[c] += f_n[c];
|
|
}
|
|
}
|
|
if (d > 25000000ull && (ft.nworst < FT_WORST || d > ft.worst[FT_WORST - 1].ns)) {
|
|
int i = ft.nworst < FT_WORST ? ft.nworst++ : FT_WORST - 1;
|
|
while (i > 0 && ft.worst[i - 1].ns < d) ft.worst[i] = ft.worst[i - 1], i--;
|
|
ft.worst[i].frame = frame;
|
|
ft.worst[i].ns = d;
|
|
memcpy(ft.worst[i].wait, frame_ns, sizeof frame_ns);
|
|
ft.worst[i].replay = (uint64_t)rep;
|
|
memcpy(ft.worst[i].op_ns, f_ns, sizeof f_ns), memcpy(ft.worst[i].op_n, f_n, sizeof f_n);
|
|
ft.worst[i].max_ns = f_max, ft.worst[i].max_op = f_op, ft.worst[i].hold_ns = f_hold, ft.worst[i].replay_cpu = f_cpu;
|
|
}
|
|
if (now - summary_t0 >= FT_PERIOD_NS) {
|
|
ft_report(now, "60 s");
|
|
summary_t0 = now;
|
|
}
|
|
return (uint64_t)rep;
|
|
}
|
|
|
|
// The write-combined memory of the process (device-local memory the driver maps into it, which Windows charges to the
|
|
// process's private bytes) as the latest walk of the address space counted it: vk_memory.c census_main every 600 frames
|
|
// and the commit census below, both only with NX2NAVI_MEM_CENSUS=1. vram_used: the driver's device-local figure at that
|
|
// walk, so that a later estimate can add what the device memory grew since.
|
|
static PlatMutex wc_lock = PLAT_MUTEX_INIT;
|
|
static uint64_t wc_bytes, wc_vram, wc_at; // wc_lock; wc_at 0: no walk yet
|
|
|
|
void perf_note_wc(uint64_t wc, uint64_t vram_used) {
|
|
plat_mutex_lock(&wc_lock);
|
|
wc_bytes = wc, wc_vram = vram_used, wc_at = kern_now_ns();
|
|
plat_mutex_unlock(&wc_lock);
|
|
}
|
|
|
|
int perf_wc_recent(uint64_t max_age_ns, uint64_t *wc, uint64_t *vram_used) {
|
|
plat_mutex_lock(&wc_lock);
|
|
int ok = wc_at && kern_now_ns() - wc_at <= max_age_ns;
|
|
if (ok) *wc = wc_bytes, *vram_used = wc_vram;
|
|
plat_mutex_unlock(&wc_lock);
|
|
return ok;
|
|
}
|
|
|
|
// The process's commit without the device memory charged to it: the private bytes less the write-combined memory of
|
|
// the last walk and less what the driver's device-local figure grew since (before any walk, less that figure alone).
|
|
// The device-local figure (heapUsage) lies 0.2-1.1 GiB under the write-combined total, so it serves for the change only.
|
|
// Where the commit does not count device memory (plat_commit_counts_vram) it is the private bytes.
|
|
static uint64_t host_commit(uint64_t prv, const PerfGpu *g) {
|
|
if (!plat_commit_counts_vram()) return prv;
|
|
uint64_t wc, at_vram;
|
|
int64_t dev;
|
|
if (perf_wc_recent(~0ull, &wc, &at_vram))
|
|
dev = (int64_t)wc + (g->have_vram && at_vram ? (int64_t)g->vram_used - (int64_t)at_vram : 0);
|
|
else
|
|
dev = g->have_vram ? (int64_t)g->vram_used : 0;
|
|
if (dev <= 0) return prv;
|
|
return (uint64_t)dev >= prv ? 0 : prv - (uint64_t)dev;
|
|
}
|
|
|
|
// Where the committed memory lies (NX2NAVI_MEM_CENSUS=1 only), every 3600 frames and when the process's own commit
|
|
// (host_commit) rose 1 GiB over the highest it was at a census: the process has run out of commit in long sessions
|
|
// while the game's own pools stayed flat. The walk holds the address-space lock the game's threads take at every page
|
|
// fault and runs here on the presenting thread, so each one delays the next frame by 130-260 ms (ft_frame charges it
|
|
// to "census"). In a session of 2026-11-13 the trigger read the private bytes, which take in the device memory Windows
|
|
// charges to the process, so every gigabyte of textures re-armed it: 22 of the 33 walks came from it, 120 frames
|
|
// apart in bursts, while the process's own commit grew 307 MiB in 7 minutes of play. So the trigger reads the commit
|
|
// without the device memory against the highest it was at a census (a figure that falls and rises again does not
|
|
// re-arm it), and a growth census waits CENSUS_GAP_NS after the last walk. The scheduled ones stay.
|
|
#define CENSUS_GAP_NS 60000000000ull
|
|
static void census_check(uint64_t frame, uint64_t prv, const PerfGpu *g) {
|
|
static int census_on = -1;
|
|
static uint64_t census_high, census_ns;
|
|
if (census_on < 0) census_on = cfg_bool("NX2NAVI_MEM_CENSUS");
|
|
if (!census_on) return;
|
|
uint64_t host = host_commit(prv, g), t0 = kern_now_ns();
|
|
int grown = host >= census_high + (1ull << 30) && (!census_ns || t0 - census_ns >= CENSUS_GAP_NS);
|
|
if (frame % 3600 && !grown) return;
|
|
// This frame's memory report (vk_memory.c heap_log, after this present) leaves out its own walk: one is enough,
|
|
// and the second, 100-240 ms on census_main's thread, delayed the frames after it once more.
|
|
__atomic_store_n(&census_walked, frame, __ATOMIC_RELEASE);
|
|
uint64_t wc = 0;
|
|
if (prof_commit_census(frame, &wc)) perf_note_wc(wc, g->have_vram ? g->vram_used : 0); // one walk for both lines
|
|
else mem_guest_census(frame);
|
|
uint64_t t1 = kern_now_ns();
|
|
census_part_ns += t1 - t0, census_ns = t1;
|
|
host = host_commit(prv, g); // with the walk's own write-combined figure
|
|
if (host > census_high) census_high = host;
|
|
}
|
|
|
|
// The second line of the 60-frame window: GPU busy time (timestamps), the time threads waited for GPU fences, VRAM and
|
|
// process memory, and which side holds the frame back. pace: the frame waited for pacing (vsync, the frame limiter) at
|
|
// least 15% of the window; gpu: the GPU was busy for 80% of the frame interval or more (without timestamps: threads
|
|
// waited for fences for half the interval or more); cpu otherwise.
|
|
// With calibrated timestamps a third line splits the GPU's idle time between timed parts: the part was submitted only
|
|
// after the previous one had ended (the GPU waited for the CPU's replay or the game), or it was already queued (untimed
|
|
// work such as uploads and presents ran there, or a wait held it).
|
|
static void perf_gpu_line(uint64_t frame, double interval_ms, double pace_share, uint64_t n) {
|
|
PerfGpu g;
|
|
memset(&g, 0, sizeof g);
|
|
if (perf_gpu_stats) perf_gpu_stats(&g);
|
|
double rw = plat_xchg64(&render_wait_ns, 0) / 1e6 / n, ow = plat_xchg64(&other_wait_ns, 0) / 1e6 / n;
|
|
double gpu_ms = g.have_gpu ? g.gpu_ns / 1e6 / n : 0;
|
|
char gs[160], vs[96];
|
|
if (g.have_gpu) snprintf(gs, sizeof gs, "gpu avg %.2f ms (%llu parts timed, %llu not; copies into VRAM mirrors %.2f ms)",
|
|
gpu_ms, (unsigned long long)g.gpu_parts, (unsigned long long)g.gpu_missed, g.mirror_ns / 1e6 / n);
|
|
else snprintf(gs, sizeof gs, "gpu avg n/a");
|
|
if (g.have_vram) snprintf(vs, sizeof vs, "vram %.0f of %.0f MiB%s", g.vram_used / 1048576.0, g.vram_budget / 1048576.0,
|
|
g.vram_exact ? "" : " (own allocations of the heap size)");
|
|
else snprintf(vs, sizeof vs, "vram n/a");
|
|
uint64_t res, prv;
|
|
plat_process_memory(&res, &prv);
|
|
double ws = res / 1048576.0, priv = prv / 1048576.0;
|
|
const char *bound = pace_share >= 0.15 ? "pace"
|
|
: g.have_gpu ? (gpu_ms >= 0.8 * interval_ms ? "gpu" : "cpu")
|
|
: (rw + ow >= 0.5 * interval_ms ? "gpu" : "cpu");
|
|
rt_log("perf: frame %llu: %s; fence wait per frame: render thread %.2f ms, other threads %.2f ms; %s; ram working set "
|
|
"%.0f MiB, private %.0f MiB; bound: %s",
|
|
(unsigned long long)frame, gs, rw, ow, vs, ws, priv, bound);
|
|
census_check(frame, prv, &g);
|
|
mem_lazy_heap_report(frame);
|
|
if (g.have_gpu && g.have_idle)
|
|
rt_log("perf: frame %llu: gpu idle per frame %.2f ms between timed parts: %.2f ms waiting for the next submission, "
|
|
"%.2f ms with it queued (untimed work or waits); %.1f gaps over 0.5 ms, longest %.2f ms; submit to start avg %.2f ms",
|
|
(unsigned long long)frame, g.idle_ns / 1e6 / n, g.starved_ns / 1e6 / n, (g.idle_ns - g.starved_ns) / 1e6 / n,
|
|
(double)g.idle_gaps / n, g.max_gap_ns / 1e6, g.gpu_parts ? g.queued_ns / 1e6 / g.gpu_parts : 0.0);
|
|
}
|
|
|
|
int rt_ab(void) {
|
|
static int64_t period = -1; // us of world clock; 0: off
|
|
if (period < 0) {
|
|
const char *e = cfg_get("NX2NAVI_AB");
|
|
period = e && *e ? (int64_t)(atof(e) * 1e6) : 0;
|
|
}
|
|
int64_t w = period ? frame_step_world_us() : -1;
|
|
if (w < 0) return 0; // before the world clock: A
|
|
int64_t k = w / period % 4;
|
|
return k == 1 || k == 2;
|
|
}
|
|
|
|
// rt_knob reads "0" as off, "ab" as the A/B blocks and anything else as on, so "off", "false" or "0 ; a note" turn a
|
|
// switch on. A value other than 0, 1 and ab is logged once per switch; the names are string literals, so the table
|
|
// holds their pointers (a full table logs no more). The value is still read as on: taking such words as off would
|
|
// change what a written setting does.
|
|
#define KNOB_WARNED 32
|
|
static const char *knob_warned[KNOB_WARNED];
|
|
|
|
static void knob_warn(const char *name, const char *key, const char *value) {
|
|
for (int i = 0; i < KNOB_WARNED; i++) {
|
|
const char *cur = __atomic_load_n(&knob_warned[i], __ATOMIC_ACQUIRE);
|
|
if (!cur && __atomic_compare_exchange_n(&knob_warned[i], &cur, name, 0, __ATOMIC_ACQ_REL, __ATOMIC_ACQUIRE)) {
|
|
rt_log("cfg: %s = '%s' is not 0, 1 or ab: read as 1", key, value);
|
|
return;
|
|
}
|
|
if (cur == name) return; // logged already (another thread may have taken this slot for it just now)
|
|
}
|
|
}
|
|
|
|
int rt_knob(const char *name, const char *def) {
|
|
char key[64];
|
|
snprintf(key, sizeof key, "NX2NAVI_%s", name);
|
|
const char *e = cfg_get(key);
|
|
if (!e || !*e) e = def;
|
|
if (!strcmp(e, "ab")) return 2;
|
|
if (strcmp(e, "0") && strcmp(e, "1")) knob_warn(name, key, e);
|
|
return strcmp(e, "0") != 0;
|
|
}
|
|
|
|
// NX2NAVI_ONE_PER_CORE=1: the process keeps the first logical processor of each physical core, so busy threads (the
|
|
// render thread, the guest cores, the job workers) never share a core's execution units with another; "ab" switches
|
|
// it with the A/B blocks. Off by default until measured here; the same rule
|
|
// is reported to give +4-10% on an 8-core SMT CPU.
|
|
//
|
|
// NX2NAVI_CACHE_DIE=1, the default: on a processor whose dies have L3 caches of different sizes (AMD's two-die
|
|
// X3D processors, 3D V-Cache on one die) the process runs on the die with the larger cache, so the guest cores, the
|
|
// render thread and the recorder share one L3 and never cross dies. Windows' own placement of games on that die
|
|
// (game mode with AMD's driver) depends on recognizing the exe as a game. 0 leaves the placement to the OS; "ab"
|
|
// switches it with the A/B blocks. No change on one-die and Intel processors.
|
|
//
|
|
// The placement is set at start (perf_cpu_start, before the thread pools count the usable processors) and checked at
|
|
// every present for the A/B switches. The rules narrow the processors the process was given (start /affinity, a
|
|
// launcher's or a benchmark's pin), never widen them; with both off nothing is set.
|
|
static int one_mode = -1, die_mode;
|
|
static uint64_t cpu_all, cpu_one, cpu_die, cpu_applied; // cpu_applied: the mask set last, 0 none
|
|
|
|
static void cpu_placement(void) {
|
|
if (one_mode < 0) {
|
|
one_mode = rt_knob("ONE_PER_CORE", "0");
|
|
die_mode = rt_knob("CACHE_DIE", "1");
|
|
int cores = plat_cpu_cores(&cpu_all, &cpu_one);
|
|
uint32_t kb = 0;
|
|
cpu_die = plat_cpu_cache_die(&kb);
|
|
if (one_mode && cpu_one && cpu_one != cpu_all)
|
|
rt_log("cpu: %d cores, %d logical processors: one per core%s", cores, __builtin_popcountll(cpu_all),
|
|
one_mode == 2 ? " in the B blocks" : "");
|
|
else
|
|
one_mode = 0;
|
|
// The largest L3 is a reason to stay on its processors only where it serves enough cores to run the game: two
|
|
// dies of one design, one of them with stacked cache (a two-die X3D desktop part, 8 cores a die). A die of
|
|
// fewer cores holds the game to them: the 4 large cores of a mobile part whose 8 small cores share a smaller
|
|
// L3, or the 6 of a 12-core X3D part, where the recording thread's own core (vk_exec.c rec_claim) left 5.
|
|
int die_cores = __builtin_popcountll(cpu_die & cpu_one);
|
|
if (cpu_die && cpu_die != cpu_all && die_cores < 8) {
|
|
rt_log("cpu: logical processors %#llx of %#llx share the largest L3 cache (%u MiB), but only %d cores: not "
|
|
"used", (unsigned long long)cpu_die, (unsigned long long)cpu_all, kb >> 10, die_cores);
|
|
cpu_die = 0;
|
|
}
|
|
if (cpu_die && cpu_die != cpu_all)
|
|
rt_log("cpu: logical processors %#llx of %#llx share the largest L3 cache (%u MiB)%s",
|
|
(unsigned long long)cpu_die, (unsigned long long)cpu_all, kb >> 10,
|
|
!die_mode ? "; cache_die = 0: not used" : die_mode == 2 ? ": the process runs there in the B blocks"
|
|
: ": the process runs there");
|
|
if (!cpu_die || cpu_die == cpu_all) die_mode = 0;
|
|
}
|
|
uint64_t want = cpu_all;
|
|
if (RT_KNOB_ON(die_mode)) want &= cpu_die;
|
|
if (RT_KNOB_ON(one_mode)) want &= cpu_one;
|
|
if (!want) want = cpu_all;
|
|
if (want == (cpu_applied ? cpu_applied : cpu_all)) return; // nothing new; never restricted: as it was given
|
|
cpu_applied = want;
|
|
if (!plat_process_affinity(want)) rt_log("cpu: could not move the process to logical processors %#llx", (unsigned long long)want);
|
|
}
|
|
|
|
void perf_cpu_start(void) { cpu_placement(); }
|
|
|
|
int perf_cpu_on_cache_die(void) { return cpu_applied && cpu_die && (cpu_applied & ~cpu_die) == 0; }
|
|
|
|
// NX2NAVI_CRASH_FILTER_GUARD (default 1; 0 off): once a second, the crash report's last-chance exception filter is put
|
|
// back if a DLL loaded after the start (a GPU driver, an overlay) set its own in its place. Without it, a fault in such
|
|
// a DLL ends the process with no FATAL line in the log. The first eight replacements are logged with the module.
|
|
static void crash_filter_guard(uint64_t frame) {
|
|
static int on = -1, logged;
|
|
if (on < 0) on = rt_knob("CRASH_FILTER_GUARD", "1");
|
|
if (!on || frame % 60) return;
|
|
char who[160];
|
|
if (plat_crash_filter_reassert(who, sizeof who) && logged < 8) {
|
|
logged++;
|
|
rt_log("diag: frame %llu: an exception filter from %s had replaced the crash report's; the crash report's is "
|
|
"back (NX2NAVI_CRASH_FILTER_GUARD)", (unsigned long long)frame, who);
|
|
}
|
|
}
|
|
|
|
// A thread the recording thread starts through a library inherits its reserved core, and the core would stay reserved
|
|
// after the recording thread ended (plat_cpu_reserve_sweep): every RESERVE_SWEEP presents both are put right.
|
|
#define RESERVE_SWEEP 300
|
|
static void reserve_sweep(uint64_t frame) {
|
|
static int logged;
|
|
if (frame % RESERVE_SWEEP) return;
|
|
int n = plat_cpu_reserve_sweep();
|
|
if (!n || logged >= 8) return;
|
|
logged++;
|
|
if (n < 0) rt_log("cpu: frame %llu: the recording thread has ended; its core is open to every thread again",
|
|
(unsigned long long)frame);
|
|
else rt_log("cpu: frame %llu: %d thread%s started from the recording thread had its core alone; now on the other "
|
|
"processors", (unsigned long long)frame, n, n > 1 ? "s" : "");
|
|
}
|
|
|
|
void perf_present(uint64_t frame) {
|
|
static uint64_t last, sum, max, n, win_start, ab_b, pace_any; // pace_any: other threads' pacing in the window
|
|
crash_filter_guard(frame);
|
|
static int64_t win_prev[PERF_CNT_N];
|
|
prof_render_tid = plat_thread_id();
|
|
if (rt_trace & RT_TRACE_SCHED) kern_sched_report(frame);
|
|
uint64_t now = kern_now_ns(), d = last ? now - last : 0;
|
|
prof_sampler_frame(frame, now, last ? d : 0);
|
|
for (int k = 0; k < PERF_N; k++) { // other threads' waits for this frame (perf_end_any), before its parts are read
|
|
int64_t a = __atomic_load_n(&any_ns[k], __ATOMIC_RELAXED) ? plat_xchg64(&any_ns[k], 0) : 0;
|
|
if (a <= 0) continue;
|
|
__atomic_fetch_add(&frame_ns[k], (uint64_t)a, __ATOMIC_RELAXED);
|
|
__atomic_fetch_add(&wait_ns[k], (uint64_t)a, __ATOMIC_RELAXED);
|
|
if (k == PERF_PACE) pace_any += (uint64_t)a;
|
|
}
|
|
int ft_add = ft_enter(); // 0 once the exit's summary is written
|
|
uint64_t rep = ft_frame(frame, now, d, ft_add); // d is 0 on the first present: it only starts the period
|
|
if (ft_add && __atomic_load_n(&session_due, __ATOMIC_RELAXED) && plat_xchg32(&session_due, 0)) session_report(now);
|
|
ft_leave();
|
|
ab_b += rt_ab();
|
|
cpu_placement();
|
|
reserve_sweep(frame);
|
|
if (__atomic_load_n(&overlay, __ATOMIC_RELAXED)) // the overlay's only cost while it is off: this branch
|
|
perfmon_frame(now, d, frame_ns, rep, __atomic_load_n(&counts[PERF_CNT_TEX_UP], __ATOMIC_RELAXED));
|
|
kern_core_diag_frame(frame, d);
|
|
if (flight_on) flight_frame(frame, now, d, frame_ns, counts);
|
|
bugcap_frame(frame, now, d, rep); // F8: a bug capture (bugcap.c); otherwise one record into its ring
|
|
if (!(rt_trace & RT_TRACE_PERF)) {
|
|
memset(frame_ns, 0, sizeof frame_ns);
|
|
last = now;
|
|
return;
|
|
}
|
|
static uint64_t slow_ns; // NX2NAVI_PERF_SLOW_MS (default 50): frames at least this long get a line of their own
|
|
if (!slow_ns) {
|
|
const char *e = cfg_get("NX2NAVI_PERF_SLOW_MS");
|
|
slow_ns = (uint64_t)(e && atoi(e) > 0 ? atoi(e) : 50) * 1000000ull;
|
|
}
|
|
MarkSums fm;
|
|
mark_frame(&fm);
|
|
seg_frame(frame, now, last ? d : 0, &fm);
|
|
// A frame whose render thread waited 20 ms or more for GPU fences: at the next present, the GPU's timed parts that
|
|
// ended in its interval (vk_sync.c vk_gpu_parts_log), read then, so that the completion thread has read them.
|
|
static uint64_t parts_frame, parts_t0, parts_t1;
|
|
static double parts_fence;
|
|
if (parts_frame) vk_gpu_parts_log(parts_frame, parts_t0, parts_t1, parts_fence), parts_frame = 0;
|
|
if (last && frame_ns[PERF_FENCE] >= 20000000ull)
|
|
parts_frame = frame, parts_t0 = plat_now_ns() - d, parts_t1 = plat_now_ns(), parts_fence = frame_ns[PERF_FENCE] / 1e6;
|
|
if (last) {
|
|
sum += d;
|
|
n++;
|
|
if (d > max) max = d, memcpy(worst_ns, frame_ns, sizeof worst_ns);
|
|
if (d >= slow_ns) {
|
|
char marks[700];
|
|
marks[0] = 0;
|
|
mark_text(&fm, marks, 0, sizeof marks);
|
|
// drain: the wait for the present thread's previous job; handoff: the wait to hand it the next one;
|
|
// replay: the replays since the last present, the pipeline, translation and texture waits above included
|
|
// (the rest of a slow frame is the game's own work)
|
|
rt_log("perf: slow frame %llu: %.1f ms; blocked pipeline %.1f xlate %.1f texture %.1f astc %.1f fence %.1f pacing %.1f "
|
|
"drain %.1f handoff %.1f; replay %.1f%s",
|
|
(unsigned long long)frame, d / 1e6, frame_ns[PERF_PIPE] / 1e6, frame_ns[PERF_XLATE] / 1e6,
|
|
frame_ns[PERF_TEX] / 1e6, frame_ns[PERF_ASTC] / 1e6, frame_ns[PERF_FENCE] / 1e6,
|
|
frame_ns[PERF_PACE] / 1e6, frame_ns[PERF_DRAIN] / 1e6, frame_ns[PERF_HANDOFF] / 1e6, rep / 1e6, marks);
|
|
}
|
|
}
|
|
memset(frame_ns, 0, sizeof frame_ns);
|
|
last = now;
|
|
if (!win_start) win_start = now;
|
|
if (frame % 60) return;
|
|
uint64_t span = now - win_start;
|
|
int64_t win[PERF_CNT_N];
|
|
for (int i = 0; i < PERF_CNT_N; i++) {
|
|
int64_t v = __atomic_load_n(&counts[i], __ATOMIC_RELAXED);
|
|
win[i] = v - win_prev[i];
|
|
win_prev[i] = v;
|
|
}
|
|
int64_t async = win[PERF_CNT_PIPE_ASYNC], skips = win[PERF_CNT_PIPE_SKIP], up = win[PERF_CNT_TEX_UP];
|
|
int64_t reup = win[PERF_CNT_TEX_REUP], sskip = win[PERF_CNT_SHADER_SKIP], waited = win[PERF_CNT_PIPE_WAIT];
|
|
int64_t oneshot = win[PERF_CNT_ONESHOT_WAIT];
|
|
uint64_t shader_keys, shader_xlated, disk[3];
|
|
static uint64_t disk_prev[3];
|
|
gfx_shader_counts(&shader_keys, &shader_xlated);
|
|
gfx_shader_disk_counts(&disk[0], &disk[1], &disk[2]);
|
|
uint64_t dwin[3];
|
|
for (int i = 0; i < 3; i++) dwin[i] = disk[i] - disk_prev[i], disk_prev[i] = disk[i];
|
|
// The pacing share counts other threads' pacing too (perf_end_any: the acquire's wait of a game that acquires its
|
|
// window images on a thread other than the presenting one, which the one-time "nvn: the game acquires" line of
|
|
// nvn_api_obj.c nvnWindowAcquireTexture names). That wait can overlap the render thread's own work, so for such a
|
|
// game the shares can add up to more than 100%. "render busy" takes out only the render thread's own pacing.
|
|
uint64_t pace_own = wait_ns[PERF_PACE] > pace_any ? wait_ns[PERF_PACE] - pace_any : 0;
|
|
if (n && span)
|
|
rt_log("perf: frame %llu: interval avg %.2f ms max %.2f ms (%.1f fps); render thread blocked: pacing %.0f%% fence %.0f%% drain %.0f%% handoff %.0f%% pipeline build %.0f%% shader xlate %.0f%% texture %.0f%% (astc %.0f%%); pipelines built in background %lld, draws skipped pending %lld, waited %lld, waiting for a shader %lld, one-shot waited %lld; textures uploaded %lld re-uploaded %lld; slowest frame: xlate %.1f ms texture %.1f ms (astc %.1f) pipeline %.1f ms fence %.1f ms; shaders: %llu keys, %llu translated; render busy avg %.2f ms; replay avg %.2f ms; ab %llu/%llu; world %.1f s; shader disk reads: %llu on the render thread (%.1f ms), %llu by the loaders",
|
|
(unsigned long long)frame, sum / 1e6 / n, max / 1e6, n * 1e9 / sum, 100.0 * wait_ns[PERF_PACE] / span,
|
|
100.0 * wait_ns[PERF_FENCE] / span, 100.0 * wait_ns[PERF_DRAIN] / span, 100.0 * wait_ns[PERF_HANDOFF] / span,
|
|
100.0 * wait_ns[PERF_PIPE] / span, 100.0 * wait_ns[PERF_XLATE] / span,
|
|
100.0 * wait_ns[PERF_TEX] / span, 100.0 * wait_ns[PERF_ASTC] / span, (long long)async, (long long)skips, (long long)waited, (long long)sskip, (long long)oneshot,
|
|
(long long)up, (long long)reup, worst_ns[PERF_XLATE] / 1e6, worst_ns[PERF_TEX] / 1e6,
|
|
worst_ns[PERF_ASTC] / 1e6, worst_ns[PERF_PIPE] / 1e6, worst_ns[PERF_FENCE] / 1e6,
|
|
(unsigned long long)shader_keys, (unsigned long long)shader_xlated,
|
|
(span > pace_own ? span - pace_own : 0) / 1e6 / n,
|
|
plat_xchg64(&replay_ns, 0) / 1e6 / n, (unsigned long long)ab_b, (unsigned long long)n, frame_step_world_us() / 1e6,
|
|
(unsigned long long)dwin[0], dwin[1] / 1e6, (unsigned long long)dwin[2]);
|
|
if (n && span) perf_gpu_line(frame, sum / 1e6 / n, (double)wait_ns[PERF_PACE] / span, n);
|
|
char marks[700];
|
|
if (mark_text(&mk_win, marks, 0, sizeof marks) > 0) rt_log("perf: frame %llu: work in the window%s", (unsigned long long)frame, marks);
|
|
memset(&mk_win, 0, sizeof mk_win);
|
|
sum = max = n = ab_b = pace_any = 0;
|
|
memset(wait_ns, 0, sizeof wait_ns);
|
|
win_start = now;
|
|
if (frame % 600 == 0) { // beside vk_memory.c's 600-frame memory lines, and like them the next frame's "report"
|
|
uint64_t s0 = kern_now_ns();
|
|
sizes_log(frame), hc_report(frame);
|
|
perf_report_part(kern_now_ns() - s0);
|
|
}
|
|
}
|