From e99625883a3e73a6fab25c96011cc30fa4dc4abc Mon Sep 17 00:00:00 2001 From: seedds Date: Tue, 10 Nov 2026 00:06:34 -0800 Subject: [PATCH] Keep automatic frame CPU budgets per frame and per thread --- .github/workflows/tests.yml | 2 + dm/games/0400486024DEC000/README.md | 1 + dm/gfx/nvn/hle_nvn.c | 17 +++--- dm/gfx/tests/Makefile | 7 +++ dm/gfx/tests/t_rt_comp.c | 94 +++++++++++++++++++++++++++++ docs/agents/symptoms.md | 1 + docs/reference/frame-rate.md | 8 +++ 7 files changed, 123 insertions(+), 7 deletions(-) create mode 100644 dm/gfx/tests/t_rt_comp.c diff --git a/.github/workflows/tests.yml b/.github/workflows/tests.yml index 5eaed49ff0..561d7cb088 100644 --- a/.github/workflows/tests.yml +++ b/.github/workflows/tests.yml @@ -70,6 +70,8 @@ jobs: if [ "$rc" != 0 ]; then echo "::error::$t failed"; failed=1; fi done exit $failed + - name: Automatic frame CPU budgets (no GPU) + run: make -C dm/gfx/tests GAME="$GAME" check_t_rt_comp 2>&1 | tee logs/rt-comp.log - name: Direct OpenGL imports and EGL lookup (no GPU) run: make -C dm/gfx/tests GAME="$GAME" gl-imports 2>&1 | tee logs/gl-imports.log - uses: actions/upload-artifact@cf430e030ddbb5b0abf93d22962f4752f3646cd9 # v7.0.2 diff --git a/dm/games/0400486024DEC000/README.md b/dm/games/0400486024DEC000/README.md index a001444dbb..63c9c421d7 100644 --- a/dm/games/0400486024DEC000/README.md +++ b/dm/games/0400486024DEC000/README.md @@ -168,6 +168,7 @@ From an empty save: at about 45 s `A` (title), `A` (New Game), then the movie. F - [HMMA rounds its f16 accumulator once per 8 products](../../../docs/reference/shaders.md#hmma-rounds-its-f16-accumulator-once-per-8-products): resolved, its NDSR upscaler and NDVE movie network were a few f16 steps off the console in about half of each HMMA's outputs (nothing visible). - [The NDVE movie network by the host](../../../docs/reference/shaders.md#the-ndve-movie-network-by-the-host): the title and movies' network as the host's kernels, bound to nn::ndve's model (on by default; `DM_NDVE_ENGINE=check` compares it with the game's in the run). - [LDSM reads rows other lanes stored](../../../docs/reference/shaders.md#ldsm-reads-rows-other-lanes-stored): white blotches over Kokiri Forest through agl's upscaler on an M4 Pro. +- [A time-constraint budget sampled per acquire or across threads](../../../docs/reference/frame-rate.md#a-time-constraint-budget-sampled-per-acquire-or-across-threads): two scheduler defects reproduced and fixed without game files during investigation of issue #1985. Whether either explains Castle Town's slowdown is still open. - [A shader that writes a whole frame through raw global memory](../../../docs/reference/frame-rate.md#a-shader-that-writes-a-whole-frame-through-raw-global-memory) - [Stage memory byte stores through a compare-and-swap loop](../../../docs/reference/shaders.md#stage-memory-byte-stores-through-a-compare-and-swap-loop): 515 shaders, the foliage mesh shaders among them; pull request #1503 measured the foliage pass at 8.3-8.6 ms on an M3 Pro with the loop, while on an M6 the loop, the store and AND / OR measure the same. - [Memory pools nothing gave an address to stay out of the raw pool table](../../../docs/reference/memory.md#memory-pools-nothing-gave-an-address-to-stay-out-of-the-raw-pool-table) diff --git a/dm/gfx/nvn/hle_nvn.c b/dm/gfx/nvn/hle_nvn.c index f2d2950dc3..382de3c666 100644 --- a/dm/gfx/nvn/hle_nvn.c +++ b/dm/gfx/nvn/hle_nvn.c @@ -1511,8 +1511,8 @@ NVN(nvnWindowGetCrop, void, const NVNwindow *w, NVNrectangle *r) { // Bayonett static void trow(uint64_t f, const char *name, double v); static void set_time_constraint(uint64_t period_ns); static void rt_comp_tick(uint64_t period_ns); -static double g_rt_comp_ms; // Currently declared real-time computation amount (ms; 0 = not declared) -static double g_rt_period_ms; +static _Thread_local double g_rt_comp_ms; // This thread's declared real-time computation amount (ms; 0 = not declared) +static _Thread_local double g_rt_period_ms; static void sleep_until_ns(uint64_t dl); static uint64_t present_period(const win_t *o); static uint64_t rt_period_ns(const win_t *o, uint64_t period); @@ -1538,7 +1538,7 @@ NVN(nvnWindowAcquireTexture, NVNwindowAcquireTextureResult, NVNwindow *w, NVNsyn // Vsync blocks here (real-device NVN: when all textures in the swapchain are waiting for display, wait for the next one to be released), not in present -- the game often calls present while holding a lock uint64_t at = *idx < 4 ? o->avail[*idx] : 0, now = dm_detclock_enabled() ? guest_ns() : now_ns(), wait = at > now ? at - now : 0, pace_ns = 0; if (!dm_detclock_enabled()) { // Register the acquire thread as a time-constraint thread (no longer registered only when it "arrived early": it must also declare itself when it is constantly behind in the hot state) - static uint64_t rt_period; uint64_t period = present_period(o), rtp = rt_period_ns(o, period); + static _Thread_local uint64_t rt_period; uint64_t period = present_period(o), rtp = rt_period_ns(o, period); if (rtp && rt_period != rtp) { rt_period = rtp; set_time_constraint(rtp); } rt_comp_tick(rtp); uint64_t p0 = now_ns(); int snap = mtl_snap_on(); @@ -1791,7 +1791,7 @@ static void slow_emit(uint64_t f) { static int rt_on(void) { static int v = -1; if (v < 0) { const char *e = getenv("DM_RT"); v = !(e && !strcmp(e, "0")); if (!v) LOG("[nvn] DM_RT=0: the present thread gets no time-constraint policy (QoS only)"); } return v; } static void set_time_constraint_comp(uint64_t period_ns, uint64_t comp_ns) { if (!rt_on()) return; - static mach_timebase_info_data_t tb; if (!tb.denom) mach_timebase_info(&tb); + static _Thread_local mach_timebase_info_data_t tb; if (!tb.denom) mach_timebase_info(&tb); if (comp_ns < 1000000ull) comp_ns = 1000000ull; if (comp_ns > period_ns * 9 / 10) comp_ns = period_ns * 9 / 10; thread_time_constraint_policy_data_t p = { .period = (uint32_t)(period_ns * tb.denom / tb.numer), .computation = (uint32_t)(comp_ns * tb.denom / tb.numer), @@ -1803,11 +1803,14 @@ static void set_time_constraint_comp(uint64_t period_ns, uint64_t comp_ns) { static int rt_comp_fixed_ms(void) { static int v = -2; if (v == -2) { const char *e = getenv("DM_RT_COMP"); v = e && *e && strcmp(e, "auto") ? atoi(e) : -1; } return v; } // −1 = auto // The fixed value, or in auto mode the computation declared so far (auto's starting value of 2 ms only the first time): a reset to 2 ms at each period change under-declared the thread until the next p90 static void set_time_constraint(uint64_t period_ns) { int f = rt_comp_fixed_ms(); set_time_constraint_comp(period_ns, f > 0 ? (uint64_t)f * 1000000ull : g_rt_comp_ms > 0 ? (uint64_t)(g_rt_comp_ms * 1e6) : 2000000ull); } -// Called every frame at acquire: records this thread's CPU time since the last call; in auto mode re-declares based on p90 +// Sample only the first acquire after a present: several acquires can divide one frame's work, but the declaration must cover the whole frame. +// A CPU clock and a Mach policy both belong to one thread; switching acquire threads must neither subtract their clocks nor reuse another thread's declaration. static void rt_comp_tick(uint64_t period_ns) { if (rt_comp_fixed_ms() > 0 || !period_ns || !g_rt_comp_ms) return; - static uint64_t last; static double win[120]; static int n; - uint64_t c = clock_gettime_nsec_np(CLOCK_THREAD_CPUTIME_ID); if (!last) { last = c; return; } + static _Thread_local uint64_t last, frame; static _Thread_local double win[120]; static _Thread_local int n, sampled; + uint64_t f = atomic_load(&g_frame); if (sampled && frame == f) return; + uint64_t c = clock_gettime_nsec_np(CLOCK_THREAD_CPUTIME_ID); frame = f; + if (!sampled) { sampled = 1; last = c; return; } win[n++] = (double)(c - last) / 1e6; last = c; if (n < 120) return; double v[120]; memcpy(v, win, sizeof v); qsort(v, 120, sizeof *v, dcmp); n = 0; diff --git a/dm/gfx/tests/Makefile b/dm/gfx/tests/Makefile index ab3866826f..c327a6845c 100644 --- a/dm/gfx/tests/Makefile +++ b/dm/gfx/tests/Makefile @@ -51,6 +51,13 @@ t_gfx_suspend: t_gfx_suspend.c ../nvn/hle_nvn.c ../../host/crash.c ../../host/hl clang $(CFLAGS) -fobjc-arc -o $@ t_gfx_suspend.c ../../host/crash.c ../../host/hle_bigstack.c t_host_stubs.c $(GFX) $(FW) t_nvn: t_nvn.c ../nvn/hle_nvn.c ../../host/crash.c ../../host/hle_bigstack.c t_host_stubs.c $(GFX) $(GFX_H) clang $(CFLAGS) -fobjc-arc -o $@ t_nvn.c ../../host/crash.c ../../host/hle_bigstack.c t_host_stubs.c $(GFX) $(FW) +t_rt_comp: t_rt_comp.c ../nvn/hle_nvn.c ../../host/crash.c ../../host/hle_bigstack.c t_host_stubs.c $(GFX) $(GFX_H) + clang $(CFLAGS) -fobjc-arc -o $@ t_rt_comp.c ../../host/crash.c ../../host/hle_bigstack.c t_host_stubs.c $(GFX) $(FW) +.PHONY: check_t_rt_comp +check_t_rt_comp: t_rt_comp + ./t_rt_comp + ./t_rt_comp fixed + ./t_rt_comp off t_dirty_slots: t_dirty_slots.c ../nvn/nvn_dirty.c ../../host/crash.c ../nvn/nvn_dirty.h $(GAME_H) clang $(CFLAGS) -o $@ t_dirty_slots.c ../../host/crash.c ../nvn/nvn_dirty.c t_dirty_race: t_dirty_race.c ../nvn/nvn_dirty.c ../../host/crash.c ../nvn/nvn_dirty.h $(GAME_H) diff --git a/dm/gfx/tests/t_rt_comp.c b/dm/gfx/tests/t_rt_comp.c new file mode 100644 index 0000000000..0269e98e34 --- /dev/null +++ b/dm/gfx/tests/t_rt_comp.c @@ -0,0 +1,94 @@ +// Exercise the actual acquire path without giving the test a real-time policy. +// Only the OS CPU clock and policy submission are replaced. The supplied CPU +// intervals are work done by this thread, independently of wall-clock pacing. +#include +#include +#include +#include +static _Thread_local uint64_t test_cpu; +static _Thread_local unsigned test_policy_calls; +static _Thread_local thread_time_constraint_policy_data_t test_policy; +static uint64_t test_clock_gettime_nsec_np(clockid_t clock) { + return clock == CLOCK_THREAD_CPUTIME_ID ? test_cpu : clock_gettime_nsec_np(clock); +} +static kern_return_t test_thread_policy_set(thread_act_t thread, thread_policy_flavor_t flavor, thread_policy_t policy, mach_msg_type_number_t count) { + if (thread != pthread_mach_thread_np(pthread_self()) || flavor != THREAD_TIME_CONSTRAINT_POLICY || count != THREAD_TIME_CONSTRAINT_POLICY_COUNT) return KERN_INVALID_ARGUMENT; + test_policy = *(thread_time_constraint_policy_data_t *)policy; + test_policy_calls++; + return KERN_SUCCESS; +} +#define clock_gettime_nsec_np test_clock_gettime_nsec_np +#define thread_policy_set test_thread_policy_set +#include "../nvn/hle_nvn.c" +#undef thread_policy_set +#undef clock_gettime_nsec_np +void *front_metal_layer(void) { return NULL; } +module_t *module_of(const void *p) { (void)p; return NULL; } +module_t *g_mod; int g_nmod; +void svc_thread_dump(void) {} +uint64_t now_ns(void) { return clock_gettime_nsec_np(CLOCK_UPTIME_RAW); } +static int checks, failed; +#define CHECK(c, label) do { checks++; if (!(c)) { failed++; fprintf(stderr, "FAIL: %s\n", label); } } while (0) +static double declared_ms(void) { + mach_timebase_info_data_t tb; mach_timebase_info(&tb); + return (double)test_policy.computation * tb.numer / tb.denom / 1e6; +} +static void acquire(win_t *w) { + int idx; + CHECK(h_nvnWindowAcquireTexture((NVNwindow *)w, NULL, &idx) == NVN_WINDOW_ACQUIRE_TEXTURE_RESULT_SUCCESS, "synthetic window acquire succeeds"); +} +static void frame(win_t *w, int acquires, uint64_t cpu_per_acquire) { + for (int i = 0; i < acquires; i++) { + test_cpu += cpu_per_acquire; + if (i + 1 == acquires) g_frame++; + acquire(w); + } +} +static void *other_thread(void *unused) { + (void)unused; + win_t w = {.interval = 1}; + test_cpu = 0; // a fresh thread's clock is below the first thread's (zero is a valid first sample) + acquire(&w); + CHECK(test_policy_calls == 1, "a new acquire thread receives its own initial policy"); + CHECK(fabs(declared_ms() - 2.0) < 0.001, "a new thread does not inherit another thread's CPU budget"); + for (int i = 0; i < 120; i++) frame(&w, 1, 1000000); + CHECK(fabs(declared_ms() - 1.25) < 0.001, "a thread's CPU samples do not subtract another thread's clock"); + return NULL; +} +int main(int argc, char **argv) { + int off = argc > 1 && !strcmp(argv[1], "off"), fixed = argc > 1 && !strcmp(argv[1], "fixed"); + setenv("DM_RT", off ? "0" : "1", 1); setenv("DM_RT_COMP", fixed ? "4" : "auto", 1); + setenv("DM_FPS_TARGET", "0", 1); setenv("DM_PRESENT_SNAP", "0", 1); + nvn_present_config(60, 1); + win_t w = {.interval = 1}; + test_cpu = 1000000000; + acquire(&w); + if (off || fixed) { + for (int i = 0; i < 120; i++) frame(&w, 2, 10000000); + CHECK(test_policy_calls == (off ? 0 : 1), "disabled and fixed modes do not auto-retune"); + CHECK(fabs(declared_ms() - (off ? 0 : 4.0)) < 0.001, "disabled and fixed modes retain their requested budget"); + printf("t_rt_comp %s: %d checks, %d failed\n", argv[1], checks, failed); + return failed != 0; + } + CHECK(test_policy_calls == 1, "first acquire declares a policy"); + for (int i = 0; i < 119; i++) frame(&w, 2, 3000000); + CHECK(test_policy_calls == 1, "repeated acquires do not complete the 120-frame sample window early"); + frame(&w, 2, 3000000); + printf("6 ms CPU per frame in two acquires: declared %.3f ms\n", declared_ms()); + CHECK(fabs(declared_ms() - 7.5) < 0.001, "the budget covers the full frame, not each acquire interval"); + pthread_t t; + CHECK(!pthread_create(&t, NULL, other_thread, NULL), "create a replacement acquire thread"); + pthread_join(t, NULL); + CHECK(fabs(declared_ms() - 7.5) < 0.001, "another thread's policy does not overwrite this thread's policy"); + // Returning to this thread must also retain its sampling baseline and budget. + for (int i = 0; i < 120; i++) frame(&w, 2, 3000000); + CHECK(fabs(declared_ms() - 7.5) < 0.001, "returning to an acquire thread preserves its CPU history"); + unsigned before = test_policy_calls; + nvn_present_config(30, 1); acquire(&w); + CHECK(test_policy_calls == before + 1 && fabs(declared_ms() - 7.5) < 0.001, "a period change retains this thread's learned CPU budget"); + nvn_present_config(60, 1); acquire(&w); + for (int i = 0; i < 120; i++) frame(&w, 1, 20000000); + CHECK(fabs(declared_ms() - 15.0) < 0.001, "the full-frame estimate still respects the period's 90 percent cap"); + printf("t_rt_comp: %d checks, %d failed\n", checks, failed); + return failed != 0; +} diff --git a/docs/agents/symptoms.md b/docs/agents/symptoms.md index 96bf7c4243..20d522ca2c 100644 --- a/docs/agents/symptoms.md +++ b/docs/agents/symptoms.md @@ -519,6 +519,7 @@ One line per symptom in the [subsystem references](../reference/): what you see - the submit thread's CPU samples dominated by `mtl_addr` / `mtl_gpu_addr` (vertex buffers in `draw`, uniform buffers in `encode_args`). → [Address to memory pool lookups by binary search](../reference/frame-rate.md#address-to-memory-pool-lookups-by-binary-search) - gameplay has low CPU clocks, large render submission wall time compared with thread CPU time, and default QoS (`0x15`) on the main guest thread while workers report user-interactive (`0x21`). → [Main guest thread keeps inherited default QoS](../reference/frame-rate.md#main-guest-thread-keeps-inherited-default-qos) - stalls of 30–60 ms about once a second, at 30 fps and at 60 (99th percentile 63–127 ms); the main thread waits 20–34 ms for the render thread once a second. → [Time-constraint computation declared below the thread's peaks](../reference/frame-rate.md#time-constraint-computation-declared-below-the-threads-peaks) +- the automatic CPU budget underestimates a frame with several texture acquires. Changing acquire threads can omit the new thread's initial policy or inflate its estimate to the cap. → [A time-constraint budget sampled per acquire or across threads](../reference/frame-rate.md#a-time-constraint-budget-sampled-per-acquire-or-across-threads) - a movie or full-screen compute pass far slower than the same work should be, nearly all of it GPU time: `GPU p50` near the frame time with `submit+present` under 1 ms. `[RED] raw global memory: a write log ran out of slots` on older chains. With `DM_NVN_GPUPROF` a relaxed timestamp can put the time before the compute encoder's reported start, so the encoder itself looks short and the gap before it is what is long. → [A shader that writes a whole frame through raw global memory](../reference/frame-rate.md#a-shader-that-writes-a-whole-frame-through-raw-global-memory) - a game with dynamic resolution stays at its full size while the GPU runs far over budget: `GPU p50` above the frame time target, frame times locked to 2 vsyncs, and the same pass sizes frame after frame in `DM_NVN_GPUPROF`. → [Dynamic resolution that never moves, and draw passes that wait for each other](../reference/frame-rate.md#dynamic-resolution-that-never-moves-and-draw-passes-that-wait-for-each-other) - after a loading screen the game's resolution stays at its lowest (Ocarina of Time: 683x384) for minutes while it holds 60 fps with GPU time well under the frame, and climbs back only slowly or not at all. → [Dynamic resolution at its floor while the GPU has time to spare](../reference/frame-rate.md#dynamic-resolution-at-its-floor-while-the-gpu-has-time-to-spare) diff --git a/docs/reference/frame-rate.md b/docs/reference/frame-rate.md index 33115a33b0..8221b86378 100644 --- a/docs/reference/frame-rate.md +++ b/docs/reference/frame-rate.md @@ -516,6 +516,14 @@ Frame pacing: the host's frame step, engine frame limiters, present intervals an - **Fix:** the declaration also covers 1.1 × the window's peak (`rt_comp_tick` in `hle_nvn.c`): 5.6 ms here, 60.0 fps, 99th percentile 21 ms. - **Found on:** [DARK SOULS: REMASTERED](../../dm/games/01004AB00A260000/README.md), in the Asylum cell. +### A time-constraint budget sampled per acquire or across threads + +- **Symptom:** the automatic CPU budget underestimates a frame with several texture acquires. Changing acquire threads can omit the new thread's initial policy or inflate its estimate to the cap. +- **Cause:** `rt_comp_tick` treated every acquire as a frame and shared its CPU-clock baseline and sample window across threads. The declared budget and period cache were shared too, although Mach policies and `CLOCK_THREAD_CPUTIME_ID` belong to individual threads. +- **Fix:** sample the first acquire after the frame counter advances, keeping the whole frame's CPU interval, and keep declarations, period tracking and CPU history per thread. The existing margins, 120-frame window, fixed and disabled modes, and 90-percent cap stay in effect. +- **Found on:** synthetic production-path tests while investigating [Ocarina of Time](../../dm/games/0400486024DEC000/README.md) [issue #1985](https://github.com/seedds/nxnative/issues/1985). The report does not establish multiple acquires or thread changes, so its Castle Town slowdown and fountain pacing remain unverified; no game files were used. +- **Check:** `t_rt_comp` gives the actual acquire path 6 ms of CPU work per frame split across two acquires. Before the fix it declares 3.750 ms, afterward 7.500 ms. A new thread independently learns 1.250 ms from 1 ms frames instead of inheriting the first thread's state or subtracting its clock. Fixed/disabled modes, period changes and the cap are covered too. + ### A shader that writes a whole frame through raw global memory - **Symptom:** a movie or full-screen compute pass far slower than the same work should be, nearly all of it GPU time: `GPU p50` near the frame time with `submit+present` under 1 ms. `[RED] raw global memory: a write log ran out of slots` on older chains. With `DM_NVN_GPUPROF` a relaxed timestamp can put the time before the compute encoder's reported start, so the encoder itself looks short and the gap before it is what is long.