From e4f10a5a0261c65aa598496c69f745d091a9d5f5 Mon Sep 17 00:00:00 2001 From: chrg6 Date: Fri, 13 Nov 2026 18:33:31 -0500 Subject: [PATCH] Log the hang watch's list of guest thread waits after the kernel lock is released, not while it is held. The review of the hang watch found that kernel.c kern_wait_report called rt_log for up to 16 lines while it held the kernel lock G. When the log queue is full and the log thread is stuck holding its write lock, one of the stalls the watch reports, the put that drains the queue waits there with G held, which turns a log stall into a freeze of every guest thread. wait_watch (NX2NAVI_WAIT_WATCH_S, off by default) had the same pattern. wait_pass now formats its lines into a buffer of the caller's (WAIT_LINE_CAP bytes a line, room for the 16 or 24 lines asked for), and kern_wait_report and wait_watch log them with the new wait_lines_log after unlock. A line that finds no room ends the pass unmarked, so wait_watch logs it at its next pass. The lines read as before. Not reproduced before the change (it needs a stalled log thread beside a report). tests/hang_watch_check.py checks statically that wait_pass logs nothing and that both callers log only after unlock; the check fails on the code before this change and passes after it, and the program's cases pass. The compile check of kernel.c passes with no -Wall warnings. Co-Authored-By: Claude Opus 5.5 --- runtime/kernel.c | 36 +++++++++++++++++++++++++++--------- tests/hang_watch_check.py | 39 +++++++++++++++++++++++++++++++++++++-- 2 files changed, 64 insertions(+), 11 deletions(-) diff --git a/runtime/kernel.c b/runtime/kernel.c index 5556fef4..0a8fe933 100644 --- a/runtime/kernel.c +++ b/runtime/kernel.c @@ -970,33 +970,47 @@ static void wait_watch_holder(char *out, size_t cap, const RtThread *h) { // 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) { +// (kern_wait_report) lists every such wait as it stands. The lines go into out, each ending in a newline, and the +// caller logs them once G is released (wait_lines_log): a log call can wait for room in the log queue (logq.c), and a +// log thread stuck in a write, one of the stalls the hang watch reports, would then hold G and every guest thread with +// it. Returns the lines written. +#define WAIT_LINE_CAP 384 // a line: its fixed words, two numbers and wait_watch_holder's 160 bytes +static int wait_pass(uint64_t limit, int max, int mark, char *out, size_t cap) { int lines = 0; + size_t used = 0; uint64_t now = kern_now_ns(); + out[0] = 0; 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]; + char who[160], line[WAIT_LINE_CAP]; + int n; 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); + n = snprintf(line, sizeof line, "kernel: thread %#x (priority %d) has waited %.0f s for the lock at %#llx held " + "by %s\n", 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); + n = snprintf(line, sizeof line, "kernel: thread %#x (priority %d) has waited %.0f s for the end of %s\n", + t->handle, t->prio, (now - t->blk_since) / 1e9, who); } else { continue; } + if (n <= 0 || (size_t)n >= sizeof line || used + (size_t)n >= cap) break; // no room: a later pass has it + memcpy(out + used, line, (size_t)n + 1); + used += (size_t)n; if (mark) t->blk_told = 1; lines++; } return lines; } +static void wait_lines_log(const char *p) { // wait_pass's lines, G released + for (const char *e; *p && (e = strchr(p, '\n')); p = e + 1) rt_log("%.*s", (int)(e - p), p); +} + static void wait_watch(void *arg) { (void)arg; uint64_t limit = (uint64_t)atoi(cfg_value("NX2NAVI_WAIT_WATCH_S")) * 1000000000ull; @@ -1004,9 +1018,11 @@ static void wait_watch(void *arg) { int lines = 0; while (lines < WAIT_WATCH_LINES) { plat_wait_ns(2000000000ull); + char out[WAIT_WATCH_LINES * WAIT_LINE_CAP]; lock(); - lines += wait_pass(limit, WAIT_WATCH_LINES - lines, 1); + lines += wait_pass(limit, WAIT_WATCH_LINES - lines, 1, out, sizeof out); unlock(); + wait_lines_log(out); } rt_log("kernel: %d long waits logged: no more", lines); } @@ -1020,8 +1036,10 @@ void kern_wait_report(void) { 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); + char out[16 * WAIT_LINE_CAP]; + int lines = wait_pass(0, 16, 0, out, sizeof out); unlock(); + wait_lines_log(out); if (!lines) rt_log("kernel: no guest thread waits for a lock or for another thread's end"); } diff --git a/tests/hang_watch_check.py b/tests/hang_watch_check.py index 305ed30e..8bfca83d 100644 --- a/tests/hang_watch_check.py +++ b/tests/hang_watch_check.py @@ -2,11 +2,14 @@ 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. +never with logq_sync, which would turn the log thread off. Also checks statically that runtime/kernel.c logs the guest +threads' waits (kern_wait_report, wait_watch) only after it released the kernel lock: a log call can wait for room in +the log queue, and a stalled log thread would then hold every guest thread. No game files, no GPU. Usage: hang_watch_check.py """ import os +import re import shutil import subprocess import sys @@ -30,7 +33,36 @@ def compiler(): return shutil.which('clang') or 'clang' +def function(source, signature): + start = source.index(signature) + brace = source.index('{', start) + depth, end = 1, brace + 1 + while depth: + depth += (source[end] == '{') - (source[end] == '}') + end += 1 + return source[start:end] + + +def static_checks(): + """kernel.c: no log call while G is held in the wait report's walk and its two callers.""" + kernel = re.sub(r'//[^\n]*', '', (ROOT / 'runtime' / 'kernel.c').read_text(encoding='utf-8')) + bad = 0 + walk = function(kernel, 'static int wait_pass(') + ok = 'rt_log' not in walk + print(f'static: kernel.c wait_pass formats its lines and logs none: {"ok" if ok else "FAIL"}', flush=True) + bad += not ok + for sig in ('void kern_wait_report(void)', 'static void wait_watch(void *arg)'): + body = function(kernel, sig) + held = body[body.index('wait_pass('):body.index('unlock()')] + ok = 'rt_log' not in held and 'wait_lines_log(' in body[body.index('unlock()'):] + print(f'static: kernel.c {sig.split("(")[0].split()[-1]} logs the waits after unlock: {"ok" if ok else "FAIL"}', + flush=True) + bad += not ok + return bad + + def main(): + bad = static_checks() work = ROOT / 'build' / 'test' / 'hang_watch' work.mkdir(parents=True, exist_ok=True) (work / 'layout.h').write_text(LAYOUT) @@ -46,7 +78,10 @@ def main(): 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 + rc = subprocess.run([str(exe)], env=env, timeout=120).returncode + if bad: + print('hang_watch_check: the static checks FAILED') + return 1 if bad or rc else 0 if __name__ == '__main__':