From b4556957c2233395f606210142a2e73b6668defa Mon Sep 17 00:00:00 2001 From: chrg6 Date: Fri, 13 Nov 2026 17:38:20 -0500 Subject: [PATCH] Add a hang watch that logs a report when no frame is shown with the window in front, or the GPU does not finish, for 20 s. A present, a submission or a completion that never came back (a deadlock, a driver wait that does not return, a GPU hang without a reset) left a log that just stopped: kernel.c wait_watch covers guest lock and thread-end waits only and is off by default, and nothing watched the present, submit or completion threads. hang_watch.c runs a thread of its own in a game run (main.c starts it before the boot; never in the tool modes). Once a second it reads, without a lock, gfx_counters.frames and the submissions issued and done (the new vk_sync.c vk_sync_progress, no device call). It reports a stall of the frames while the guest runs, the window is in front and not minimized (gfx_window_in_front) and no orderly end has begun (rt_exit_started): the game stops presenting without the focus, so a focus change starts the count again, and the boot screen is not judged. It reports submissions issued and not done, "done" unchanged for N s, whatever the focus. One report per stall, a new stall needs progress, at most 3 a run. A report names the stall with the counts, the focus and the world clock; who holds the present, queue and window-start locks (gfx_present.c gfx_lock_holders, read from PlatRMutex.owner and depth); the guest threads' lock and thread-end waits (kernel.c kern_wait_report, wait_watch's walk factored out as wait_pass, run with limit 0 under ten 10 ms trylocks of the kernel lock); and then writes the log out with logq_flush, never rt_log_sync, which would put every later line on the thread that logs it in a run that may recover. It never ends the process and adds no wait to a drawing thread. The per-thread wait sites and lock owner wrappers are left for a later change. NX2NAVI_HANG_WATCH_S sets the seconds (default 20, 0..600, read at start, 0 off): a metas row, a known[] name, a diagnostics sections[] entry and an nx2navi.ini.example entry. Not reproduced before the change (a diagnostic). The new tests/hang_watch_check.py drives hang_watch.c's decisions on made-up readings: no report while things move, unfocused, minimized or ending; one per stall of the frames with the window in front and one again after progress; one for submissions not done whatever the focus; none for an idle GPU; at most 3; logq_flush called and logq_sync never. tests/cfg_rows_check.py (0 problems), the scratchpad rows check ("missing []") and the compile checks of every runtime file pass. Co-Authored-By: Claude Opus 5.5 --- nx2navi.ini.example | 4 ++ runtime/cfg.c | 5 ++ runtime/gfx.h | 4 ++ runtime/gfx_present.c | 14 +++++ runtime/hang_watch.c | 105 ++++++++++++++++++++++++++++++++++++++ runtime/host.h | 4 ++ runtime/kernel.c | 64 +++++++++++++++-------- runtime/main.c | 1 + runtime/vk_sync.c | 7 +++ tests/hang_watch_check.c | 91 +++++++++++++++++++++++++++++++++ tests/hang_watch_check.py | 53 +++++++++++++++++++ 11 files changed, 332 insertions(+), 20 deletions(-) create mode 100644 runtime/hang_watch.c create mode 100644 tests/hang_watch_check.c create mode 100644 tests/hang_watch_check.py diff --git a/nx2navi.ini.example b/nx2navi.ini.example index 65f1527f..dc21c477 100644 --- a/nx2navi.ini.example +++ b/nx2navi.ini.example @@ -994,6 +994,10 @@ # it waits for and what that one is doing (at most 24 lines a run): a game that stops then leaves the chain in its log. # Off by default: its thread takes the game's thread lock every 2 seconds. 10 is a good value for a hang report. # wait_watch_s = 0 +# A report in the log when nothing moves for this many seconds: no frame shown while the window is in front, or a GPU +# submission not finished. It names who holds the present and queue locks and what the game's threads wait for, at +# most three times a run; the game goes on. 0 turns it off. Read at start. +# hang_watch_s = 20 # Diagnosis: one log line per frame while Link stands near a moving floor (the floating platforms): the frame's step, # how far he moved and how far the floor moved. 1 writes 4000 lines, a larger number that many; 0 is off. # floor_probe = 0 diff --git a/runtime/cfg.c b/runtime/cfg.c index 65b26c93..ee8ee7e5 100644 --- a/runtime/cfg.c +++ b/runtime/cfg.c @@ -91,6 +91,8 @@ static const char *const known[] = { // developer switches read with cfg_get, rt_knob or vk_caps.c env_u32, without a menu row (tests/cfg_rows_check.py) "AUDIO_DUMP", "DEFER_STAMP", "DEPTH_TWIN", "DLAA_ZFIT", "DUMP_SKIP_RUNS", "DUMP_TEX", "DUMP_UBO", "EVENT_ORDER", "GATHER_BIAS", "PIN_SWEEP", "REC_CHECK", "REC_DELAY_US", "REG_ORDER", "SHADOW", "ZERO_LOCALS", + // hang_watch.c: the hang watch's seconds + "HANG_WATCH_S", // retired: the settings of the co-op of versions up to 0.9.2; read by nothing, listed so that a file which still // sets them logs no unknown key "COOP", "COOP_BETA", "COOP_NAME", "COOP_SERVER", "COOP_PORT", "COOP_ROOM", "COOP_AUTO", "COOP_DROP", @@ -173,6 +175,7 @@ static const struct { const char *key, *section; } sections[] = { {"WB_MERGE_MAX", "diagnostics"}, {"MV_SURVEY", "diagnostics"}, {"TEXUP_LOG_MS", "diagnostics"}, {"WAIT_WATCH_S", "diagnostics"}, {"HANDLE_CENSUS", "diagnostics"}, + {"HANG_WATCH_S", "diagnostics"}, {"VMA_BLOCK_MB", "diagnostics"}, {"DEVICE_LOST_AT", "diagnostics"}, {"STAGING_FAIL_AT", "diagnostics"}, {"VRAM_BALLAST_MB", "diagnostics"}, {"COPY_RETIRE", "diagnostics"}, {"MEM_BUDGET_TEST_VRAM_MB", "diagnostics"}, {"MEM_BUDGET_TEST_RAM_MB", "diagnostics"}, @@ -431,6 +434,8 @@ static const CfgMeta metas[] = { {"WAIT_WATCH_S", "0", "0..3600", RESTART}, // kernel.c wait_watch: a lock or thread-end wait this long is logged; 0 off // perf.c hc_main: with NX2NAVI_TRACE=perf, the process's handles by kind when their count grew {"HANDLE_CENSUS", "0", "0|1", RESTART}, + // hang_watch.c: a report when no frame is shown with the window in front, or the GPU does not finish, this long; 0 off + {"HANG_WATCH_S", "20", "0..600", RESTART}, {"VMA_BLOCK_MB", "64", "16..256", RESTART}, // vk_headroom.c vk_vma_block_size // vk_texture.c compact_on: idle textures move out of sparsely used blocks of video memory; the free space inside // the blocks from which a pass starts, and the bytes moved per frame (also the largest texture that moves) diff --git a/runtime/gfx.h b/runtime/gfx.h index 3e74bfcf..14a85f0d 100644 --- a/runtime/gfx.h +++ b/runtime/gfx.h @@ -27,6 +27,10 @@ uint64_t gfx_vsync_ticks(void); // ticks since start uint64_t gfx_vsync_time_ns(uint64_t tick); // kern_now_ns() time of a tick (pacing) double gfx_window_refresh_hz(void); // refresh rate of the window's monitor; 0 unknown int gfx_window_focused(void); +// gfx_present.c: who holds the present, queue and window-start locks, read without taking them (the hang watch) +typedef struct { uint32_t present, present_depth, queue, queue_depth, start; } GfxLockHolders; +void gfx_lock_holders(GfxLockHolders *h); +int gfx_window_in_front(void); // the window has the focus and is not minimized: the game is expected to present int vk_hdr_native(void); // NX2NAVI_HDR = native: the game's own HDR picture (vk_hdr.c) int gfx_picture_rect(float out[4]); // where the last present put the picture, fractions of the swapchain (x, y, w, h); 0 before one diff --git a/runtime/gfx_present.c b/runtime/gfx_present.c index b4225655..1aac8f2d 100644 --- a/runtime/gfx_present.c +++ b/runtime/gfx_present.c @@ -126,6 +126,8 @@ int rt_exit_begin(void) { for (;;) plat_sleep_ms(1000); } +int rt_exit_started(void) { return __atomic_load_n(&exit_tid, __ATOMIC_ACQUIRE) != 0; } + // What every orderly end saves and puts back, in this order. What a kill of the process must not lose and what is quick // comes first: Windows ends a closed console about 5 s after the close, a session's end and an "End task" sooner, and // the pipeline save alone can take that long (vk_pipeline_save_exit waits up to 5 s for the builds that run). So a @@ -2013,3 +2015,15 @@ void gfx_window_start(void) { plat_rmutex_unlock(&g_start_lock); vsync_ensure(); } + +int gfx_window_in_front(void) { return gfx_window_focused() && !wsys_minimized(); } + +// For the hang watch's report (hang_watch.c): who holds the present, queue and window-start locks now, read without +// taking them (0: free). The fields may be caught mid-change; the report only names them. +void gfx_lock_holders(GfxLockHolders *h) { + h->present = __atomic_load_n(&g_pl.owner, __ATOMIC_RELAXED); + h->present_depth = __atomic_load_n(&g_pl.depth, __ATOMIC_RELAXED); + h->queue = __atomic_load_n(&g_ql.owner, __ATOMIC_RELAXED); + h->queue_depth = __atomic_load_n(&g_ql.depth, __ATOMIC_RELAXED); + h->start = __atomic_load_n(&g_start_lock.owner, __ATOMIC_RELAXED); +} diff --git a/runtime/hang_watch.c b/runtime/hang_watch.c new file mode 100644 index 00000000..6bff8db6 --- /dev/null +++ b/runtime/hang_watch.c @@ -0,0 +1,105 @@ +// The hang watch: a report in the log when nothing moves for NX2NAVI_HANG_WATCH_S seconds (default 20; 0 off). A +// present, a GPU submission or the completion of one that never comes back (a deadlock, a driver wait that does not +// return, a GPU hang without a reset) left a log that just stopped, and nothing in it said where the threads were. +// +// Its own thread reads, once a second and without a lock, what moves while the game runs: the frames shown +// (gfx_counters.frames) and the GPU submissions issued and done (vk_sync.c vk_sync_progress). Two stalls are reported: +// - no frame shown for N s while the guest runs, the window is in front and not minimized and the process is not +// ending: the game stops presenting when it loses the focus, so a focus change starts the count again, and the boot +// screen (before the guest starts) is not judged; +// - submissions issued and not done, with "done" unchanged for N s, whatever the focus. +// One report per stall, and a new stall needs progress first; at most HW_REPORTS a run. The report names the stall, +// who holds the present, queue and window-start locks (gfx_present.c gfx_lock_holders), the guest threads' lock and +// thread-end waits (kernel.c kern_wait_report), and then writes the log out with logq_flush, which leaves the log +// thread on: rt_log_sync would make every later line a write on the thread that logs it, drawing threads included, +// in a run that may yet recover. The watch never ends the process, never calls the device, and takes no lock a +// drawing thread waits for, but for the kernel lock it tries during a report (kernel.c kern_wait_report). +#include "cfg.h" +#include "gfx.h" +#include "host.h" +#include "logq.h" +#include "nvn_api.h" +#include "platform/platform.h" + +#define HW_REPORTS 3 + +typedef struct { // what the watch reads each second + uint64_t now_ns, frames, issued, done; + int judge_present; // the guest runs, the window is in front and not minimized, the process is not ending +} HwBeat; + +typedef struct { + uint64_t limit_ns; + uint64_t frames, frames_at; // the frame count last seen, and since when nothing moved while judged + uint64_t done, done_at; // the same for the submissions done, while some are outstanding + int present_told, gpu_told; // this stall is reported + int reports; +} HangWatch; + +enum { HW_NONE, HW_PRESENT, HW_GPU }; + +// One second's reading: which stall to report now, if any. +static int hw_step(HangWatch *w, const HwBeat *b) { + if (b->frames != w->frames || !b->judge_present) { // progress, or not judged: the count starts again + w->frames = b->frames; + w->frames_at = b->now_ns; + w->present_told = 0; + } + if (b->done != w->done || b->issued <= b->done) { + w->done = b->done; + w->done_at = b->now_ns; + w->gpu_told = 0; + } + if (w->reports >= HW_REPORTS) return HW_NONE; + int gpu = !w->gpu_told && b->issued > b->done && b->now_ns - w->done_at >= w->limit_ns; + int present = !w->present_told && b->judge_present && b->now_ns - w->frames_at >= w->limit_ns; + if (!gpu && !present) return HW_NONE; + w->reports++; + w->present_told = 1; // a GPU stall stops the frames too: one report for both + if (gpu) w->gpu_told = 1; + return gpu ? HW_GPU : HW_PRESENT; +} + +static void hw_read(HwBeat *b) { + b->now_ns = plat_now_ns(); + b->frames = __atomic_load_n(&gfx_counters.frames, __ATOMIC_RELAXED); + vk_sync_progress(&b->issued, &b->done); + b->judge_present = __atomic_load_n(&rt_guest_start_ns, __ATOMIC_RELAXED) && gfx_window_in_front() && + !rt_exit_started(); +} + +static void hw_report(int kind, const HwBeat *b, const HangWatch *w) { + int64_t world = frame_step_world_us(); + uint64_t since = b->now_ns - (kind == HW_GPU ? w->done_at : w->frames_at); + rt_log("hang watch: %s for %.0f s (frames shown %llu; GPU submissions issued up to %llu, done up to %llu; window " + "%s; world clock %.1f s); report %d of at most %d, the game goes on", + kind == HW_GPU ? "GPU submissions not done" : "no frame shown with the window in front", since / 1e9, + (unsigned long long)b->frames, (unsigned long long)b->issued, (unsigned long long)b->done, + gfx_window_in_front() ? "in front" : "not in front", world >= 0 ? world / 1e6 : -1.0, w->reports, HW_REPORTS); + GfxLockHolders h; + gfx_lock_holders(&h); + rt_log("hang watch: the present lock is held by thread %u (depth %u), the queue lock by thread %u (depth %u), the " + "window start lock by thread %u (0: free)", h.present, h.present_depth, h.queue, h.queue_depth, h.start); + kern_wait_report(); + logq_flush(); +} + +static void hang_watch_main(void *arg) { + HangWatch w = {.limit_ns = (uint64_t)(uintptr_t)arg * 1000000000ull}; + HwBeat b; + hw_read(&b); + w.frames = b.frames, w.frames_at = b.now_ns, w.done = b.done, w.done_at = b.now_ns; + while (w.reports < HW_REPORTS) { + plat_sleep_ms(1000); + hw_read(&b); + int kind = hw_step(&w, &b); + if (kind) hw_report(kind, &b, &w); + } +} + +void hang_watch_start(void) { + int s = cfg_int("NX2NAVI_HANG_WATCH_S"); + if (s <= 0) return; + if (!plat_thread_spawn(hang_watch_main, (void *)(uintptr_t)s, "hang watch", 0)) + rt_log("hang watch: its thread did not start"); +} diff --git a/runtime/host.h b/runtime/host.h index 06628673..8220c15d 100644 --- a/runtime/host.h +++ b/runtime/host.h @@ -25,6 +25,9 @@ void rt_log_raw(const char *p, size_t n); const char *rt_log_path(void); // the log file, NULL when this run writes none void rt_log_sync(void); // writes the queued log lines now; later lines are written as they are made void rt_log_ending(void); // the process is ending: its lines reach the log file past its 64 MiB cap +void hang_watch_start(void); // hang_watch.c: NX2NAVI_HANG_WATCH_S's thread, in a game run +void kern_wait_report(void); // kernel.c: the guest threads' lock and thread-end waits, for a hang report +void vk_sync_progress(uint64_t *issued, uint64_t *done); // vk_sync.c: submissions issued and done, no lock or device call enum { RT_TRACE_SVC = 1, RT_TRACE_HOSTCALL = 2, RT_TRACE_IPC = 4, RT_TRACE_FS = 8, RT_TRACE_GFX = 16, RT_TRACE_PERF = 32, RT_TRACE_SCHED = 64, RT_TRACE_AUDIO = 128, RT_TRACE_PRESENT = 256 }; extern unsigned rt_trace; // from NX2NAVI_TRACE=svc,host,ipc,fs,gfx,perf,sched,audio,present (or all) @@ -116,6 +119,7 @@ void gfx_window_closed(void); // gfx_present.c (gfx_wsys.h): t // --seconds). rt_exit_begin: 1 for the first caller; another thread waits there for good; 0 for that caller's own // thread again. rt_exit_steps: the saves and the put-backs, the slow pipeline save late and the final save flush last. int rt_exit_begin(void); +int rt_exit_started(void); // an orderly end has begun (the hang watch stops judging presents) enum { RT_EXIT_SETTINGS = 1 }; // rt_exit_steps also writes the menu's changes to nx2navi.ini void rt_exit_steps(unsigned what); void perf_gpu_wait(uint64_t t0); // a wait for a GPU fence ended (any thread; the render thread's also counts as PERF_FENCE) diff --git a/runtime/kernel.c b/runtime/kernel.c index 687579cb..5556fef4 100644 --- a/runtime/kernel.c +++ b/runtime/kernel.c @@ -968,6 +968,35 @@ static void wait_watch_holder(char *out, size_t cap, const RtThread *h) { (kern_now_ns() - h->blk_since) / 1e9, kinds[k], (unsigned long long)h->wobj); } +// One walk over the guest threads, G held: each one that has waited `limit` ns or longer for a lock or for another +// thread's end gets a line, at most max of them. mark: a wait gets its line once (wait_watch); the hang watch's report +// (kern_wait_report) lists every such wait as it stands. Returns the lines written. +static int wait_pass(uint64_t limit, int max, int mark) { + int lines = 0; + uint64_t now = kern_now_ns(); + for (RtThread *t = g_all; t && lines < max; t = t->all) { + if (!t->blk_since || (mark && t->blk_told) || now - t->blk_since < limit) continue; + char who[160]; + if (t->wkind == W_LOCK) { // the lock word's owner field is the holder's handle + wait_watch_holder(who, sizeof who, h_peek((uint32_t)t->wobj, O_THREAD)); + rt_log("kernel: thread %#x (priority %d) has waited %.0f s for the lock at %#llx held by %s", + t->handle, t->prio, (now - t->blk_since) / 1e9, (unsigned long long)t->waddr, who); + } else if (t->wkind == W_SYNC && t->whs) { + const RtThread *end = NULL; + for (int i = 0; i < t->wn && !end; i++) end = h_peek(t->whs[i], O_THREAD); + if (!end) continue; + wait_watch_holder(who, sizeof who, end); + rt_log("kernel: thread %#x (priority %d) has waited %.0f s for the end of %s", t->handle, t->prio, + (now - t->blk_since) / 1e9, who); + } else { + continue; + } + if (mark) t->blk_told = 1; + lines++; + } + return lines; +} + static void wait_watch(void *arg) { (void)arg; uint64_t limit = (uint64_t)atoi(cfg_value("NX2NAVI_WAIT_WATCH_S")) * 1000000000ull; @@ -976,31 +1005,26 @@ static void wait_watch(void *arg) { while (lines < WAIT_WATCH_LINES) { plat_wait_ns(2000000000ull); lock(); - uint64_t now = kern_now_ns(); - for (RtThread *t = g_all; t && lines < WAIT_WATCH_LINES; t = t->all) { - if (!t->blk_since || t->blk_told || now - t->blk_since < limit) continue; - char who[160]; - if (t->wkind == W_LOCK) { // the lock word's owner field is the holder's handle - wait_watch_holder(who, sizeof who, h_peek((uint32_t)t->wobj, O_THREAD)); - rt_log("kernel: thread %#x (priority %d) has waited %.0f s for the lock at %#llx held by %s", - t->handle, t->prio, (now - t->blk_since) / 1e9, (unsigned long long)t->waddr, who); - } else if (t->wkind == W_SYNC && t->whs) { - const RtThread *end = NULL; - for (int i = 0; i < t->wn && !end; i++) end = h_peek(t->whs[i], O_THREAD); - if (!end) continue; - wait_watch_holder(who, sizeof who, end); - rt_log("kernel: thread %#x (priority %d) has waited %.0f s for the end of %s", t->handle, t->prio, - (now - t->blk_since) / 1e9, who); - } else { - continue; - } - t->blk_told = 1, lines++; - } + lines += wait_pass(limit, WAIT_WATCH_LINES - lines, 1); unlock(); } rt_log("kernel: %d long waits logged: no more", lines); } +// The hang watch's report (hang_watch.c): the guest threads' lock and thread-end waits as they stand. G is only tried, +// ten times 10 ms apart: its holder may be the thread that hangs, and the watch adds no wait of its own. +void kern_wait_report(void) { + int got = 0; + for (int i = 0; i < 10 && !(got = plat_mutex_trylock(&G)); i++) plat_sleep_ms(10); + if (!got) { + rt_log("kernel: the thread lock stayed taken for 100 ms; the guest threads' waits are not listed"); + return; + } + int lines = wait_pass(0, 16, 0); + unlock(); + if (!lines) rt_log("kernel: no guest thread waits for a lock or for another thread's end"); +} + int kern_core_away(void) { RtThread *t = tcur; if (!t || t->cur_core < 0) return 0; diff --git a/runtime/main.c b/runtime/main.c index dd8fa6c1..a6cbf0b3 100644 --- a/runtime/main.c +++ b/runtime/main.c @@ -754,6 +754,7 @@ static int main_run(int argc, char **argv) { if (plat_console_setup(console_closed)) rt_log("console: QuickEdit off; closing the console ends the game as its window does"); mem_start_note(0); // memory.c: a warning when the machine has less memory free than the game takes + hang_watch_start(); // a report in the log when the frames or the GPU stop (hang_watch.c); never in tool modes cfg.boot = cfg.seconds > 0; // --seconds starts the game like --boot, with its checkpoints vk_driver_cache_env(); // before the threads below and rt_boot's, any of which may load the Vulkan driver discord_init(); // the Rich Presence thread (discord_rpc.c); it reads nx2navi.ini itself and idles while off diff --git a/runtime/vk_sync.c b/runtime/vk_sync.c index 22eefc9c..2c1ef61c 100644 --- a/runtime/vk_sync.c +++ b/runtime/vk_sync.c @@ -988,6 +988,13 @@ void vk_sync_lost_report(void) { rt_log("vk: when the device was lost: %s", t); } +// The hang watch's reading (hang_watch.c): the newest value submitted and the newest done, without a lock or a device +// call. +void vk_sync_progress(uint64_t *issued_out, uint64_t *done_out) { + *issued_out = __atomic_load_n(&issued, __ATOMIC_ACQUIRE); + *done_out = __atomic_load_n(&done, __ATOMIC_ACQUIRE); +} + static void completion_main(void *arg) { VkCtx *c = arg; __atomic_store_n(&cb_tid, plat_thread_id(), __ATOMIC_RELEASE); diff --git a/tests/hang_watch_check.c b/tests/hang_watch_check.c new file mode 100644 index 00000000..796af92f --- /dev/null +++ b/tests/hang_watch_check.c @@ -0,0 +1,91 @@ +// runtime/hang_watch.c's decisions on made-up readings, a second apart, with stand-ins for what it reads and calls. +// Built and run by tests/hang_watch_check.py; prints each failed check and exits 1 on any. +#include "hang_watch.c" + +#include +#include + +static int fails; +#define CHECK(c, ...) do { if (!(c)) { fails++; printf("FAIL line %d: ", __LINE__); printf(__VA_ARGS__); printf("\n"); } } while (0) + +// ---- the runtime hang_watch.c reaches +GfxStats gfx_counters; +uint64_t rt_guest_start_ns = 1; +static int focused = 1, minimized, ending, flushes, syncs, wait_reports; +static uint64_t issued_v, done_v; +void vk_sync_progress(uint64_t *issued, uint64_t *done) { *issued = issued_v, *done = done_v; } +int gfx_window_in_front(void) { return focused && !minimized; } +int rt_exit_started(void) { return ending; } +int64_t frame_step_world_us(void) { return 1000000; } +void gfx_lock_holders(GfxLockHolders *h) { *h = (GfxLockHolders){7, 1, 0, 0, 0}; } +void kern_wait_report(void) { wait_reports++; } +void logq_flush(void) { flushes++; } +void logq_sync(void) { syncs++; } +void rt_log(const char *fmt, ...) { + va_list ap; + va_start(ap, fmt); + printf(" log: "); + vprintf(fmt, ap); + printf("\n"); + va_end(ap); +} +int cfg_int(const char *name) { (void)name; return 20; } + +// ---- the readings: t seconds, the frames shown so far, focus, and the GPU's issued and done values +static HangWatch w; +static uint64_t t_s; +static int run(int seconds, int frames_move, int gpu_move) { + int reports = 0; + for (int i = 0; i < seconds; i++) { + t_s++; + if (frames_move) gfx_counters.frames++; + if (gpu_move) issued_v++, done_v++; + HwBeat b; + hw_read(&b); + b.now_ns = t_s * 1000000000ull; + int kind = hw_step(&w, &b); + if (kind) { + hw_report(kind, &b, &w); + reports++; + } + } + return reports; +} + +int main(void) { + setvbuf(stdout, NULL, _IONBF, 0); + w = (HangWatch){.limit_ns = 20000000000ull}; + CHECK(!run(100, 1, 1), "a report while frames and the GPU move"); + focused = 0; + CHECK(!run(100, 0, 0), "a report while the window is not in front"); + focused = 1, minimized = 1; + CHECK(!run(100, 0, 0), "a report while the window is minimized"); + minimized = 0, ending = 1; + CHECK(!run(100, 0, 0), "a report while the process ends"); + ending = 0; + int r = run(19, 0, 0); + CHECK(!r, "a report before 20 s without a frame in front"); + r = run(60, 0, 0); + CHECK(r == 1, "%d reports for one stall of the frames, want 1", r); + CHECK(flushes == 1 && wait_reports == 1 && !syncs, "the report wrote %d flushes, %d wait lists and %d syncs", flushes, + wait_reports, syncs); + r = run(5, 1, 1) + run(30, 0, 0); + CHECK(r == 1, "%d reports for a second stall after progress, want 1", r); + focused = 0; // the GPU stops: reported whatever the focus + issued_v += 3; + r = run(30, 0, 0); + CHECK(r == 1, "%d reports for submissions not done, want 1", r); + issued_v = done_v; + r = run(5, 1, 1); + focused = 1; + r += run(60, 0, 0); + CHECK(r == 0, "%d reports after the third: at most 3 a run", r); + CHECK(w.reports == 3, "%d reports in all, want 3", w.reports); + // a fresh watch: the GPU idle (nothing outstanding) is no stall + w = (HangWatch){.limit_ns = 20000000000ull}; + focused = 0; + issued_v = done_v; + CHECK(!run(100, 0, 0), "a report for an idle GPU"); + printf("hang_watch_check: %s\n", fails ? "FAILED" : "ok"); + return fails ? 1 : 0; +} diff --git a/tests/hang_watch_check.py b/tests/hang_watch_check.py new file mode 100644 index 00000000..305ed30e --- /dev/null +++ b/tests/hang_watch_check.py @@ -0,0 +1,53 @@ +"""Build and run tests/hang_watch_check.c: runtime/hang_watch.c's decisions on made-up readings. No report while the +frames and the GPU move, while the window is not in front or minimized, or while the process ends; one report for a +stall of the frames with the window in front, another after progress and a new stall, one for GPU submissions not +done whatever the focus, none for an idle GPU, at most three a run. A report writes the log out with logq_flush and +never with logq_sync, which would turn the log thread off. No game files, no GPU. + +Usage: hang_watch_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') + +LAYOUT = '''// A stand-in for the generated layout.h (tests/hang_watch_check.py). +#pragma once +#define MOD_MAIN_BASE 0x7000000000ull +#define MOD_MAIN_SIZE 0x4ea0000ull +''' + + +def compiler(): + 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' / 'hang_watch' + work.mkdir(parents=True, exist_ok=True) + (work / 'layout.h').write_text(LAYOUT) + win = os.name == 'nt' + exe = work / ('hang_watch_check.exe' if win else 'hang_watch_check') + env = dict(os.environ) + if win and MSYS_BIN.exists(): + env['PATH'] = str(MSYS_BIN) + os.pathsep + env.get('PATH', '') + rt = ROOT / 'runtime' + plat = [rt / 'platform' / ('win32.c' if win else 'linux.c'), rt / 'platform' / 'common.c'] + libs = ['-lbcrypt', '-lws2_32', '-lpsapi', '-lwinmm', '-ldbghelp', '-lshell32', '-lole32', '-luser32', '-ladvapi32'] if win \ + else ['-lpthread'] + subprocess.check_call([compiler(), '-O1', '-g', '-Wall', '-Wno-unused-function', '-fno-strict-aliasing', + '-march=x86-64-v3', '-I', str(rt), '-I', str(work), str(ROOT / 'tests' / 'hang_watch_check.c'), + *map(str, plat), '-o', str(exe), '-lm', *libs], env=env) + return subprocess.run([str(exe)], env=env, timeout=120).returncode + + +if __name__ == '__main__': + sys.exit(main())