From 5ca35baff2ee4d5ad72d2f310d128888908fe4da Mon Sep 17 00:00:00 2001 From: Paolo Moretti Date: Sun, 1 Nov 2026 15:20:13 +0700 Subject: [PATCH 1/5] Host profiler: the GPU clock, its limits and the process role in each frame's timing rows, and a report of one session With DM_NVN_TSV set (off by default), dm/host/sysprof.m samples every 100 ms, without root, what the system did with the game's GPU and process (IOReport through dlopen; Mac only): the GPU clock and the share of time it was powered (@gpu_mhz, @gpu_on; powered is not busy), its power (@gpu_w), the clock state the boost controller asked for (@gpu_boost), the share of time a thermal or voltage-droop limit applied (@gpu_cltm, @gpu_droop), the process role (@role), the thermal state and Low Power Mode. With DM_AB, @ab gives the switches on in the frame's phase. A change of role is logged. dm/tools/perf_report.py turns one session into a timeline per second and gives each drop below the cap a verdict (cpu, gpu-clock, gpu-limit, gpu, role, pacing); with DM_AB it compares the switch sets over the same session, so one run answers what several runs used to. Also: @late_ms no longer underflows when a display-link tick returns before the texture's slot time. Documented in docs/development.md (Why a frame rate fell: one session's profile). --- dm/gfx/nvn/hle_nvn.c | 14 +++- dm/gfx/nvn/nvn_mtl.m | 1 + dm/host/Makefile | 2 +- dm/host/sysprof.h | 15 ++++ dm/host/sysprof.m | 148 ++++++++++++++++++++++++++++++++++++++++ dm/tools/impact_map.tsv | 2 + dm/tools/perf_report.py | 140 +++++++++++++++++++++++++++++++++++++ docs/development.md | 4 ++ 8 files changed, 324 insertions(+), 2 deletions(-) create mode 100644 dm/host/sysprof.h create mode 100644 dm/host/sysprof.m create mode 100644 dm/tools/perf_report.py diff --git a/dm/gfx/nvn/hle_nvn.c b/dm/gfx/nvn/hle_nvn.c index a8b29fcc38..4402762606 100644 --- a/dm/gfx/nvn/hle_nvn.c +++ b/dm/gfx/nvn/hle_nvn.c @@ -18,6 +18,7 @@ #include "nvn_fstep.h" #include "nvn_timestamp.h" #include "../../host/front.h" +#include "../../host/sysprof.h" #include "nvn_dirty.h" #include #include @@ -1415,7 +1416,7 @@ NVN(nvnWindowAcquireTexture, NVNwindowAcquireTextureResult, NVNwindow *w, NVNsyn if (pace) { if (last && now_ns() < last + step) sleep_until_ns(last + step); last = now_ns(); } } pace_ns += mtl_snap_acquire_wait(); // ring capacity is waited for at acquire, where the game does not hold its present lock - g_acq_wait_ns += wait; trow(g_frame, "@late_ms", wait ? (now_ns() - at) / 1e6 : 0); + g_acq_wait_ns += wait; { uint64_t n_ = now_ns(); trow(g_frame, "@late_ms", wait && n_ > at ? (n_ - at) / 1e6 : 0); } // past the texture's slot time (a display-link tick can return before it: 0) // The previous present of this texture has not yet been processed by the present thread (display cannot keep up, a whole swapchain round behind): wait for it to be returned, then hand it to the game to draw uint64_t tk = *idx < 4 ? o->ticket[*idx] : 0; if (tk) { uint64_t w0 = now_ns(); mtl_present_wait(tk); g_pq_wait_ns += now_ns() - w0; } @@ -1438,6 +1439,7 @@ static void dump_frame(void) { const char *e = getenv("DM_NVN_FRAMES"); if (e) nframes = atoi(e); const char *c = getenv("DM_NVN_TSV_CALLS"); if (c) calls = atoi(c); // 0 = write only the @ timing rows (pulling files from a real device has a size limit, and the call-count rows take about 2/3) const char *t = getenv("DM_NVN_TSV"); if (t && !(g_tsv = fopen(t, "w"))) LOG("[RED] cannot open %s", t); + if (g_tsv) dm_sysprof_start(); // the system's side of each frame (sysprof.m): GPU clock, power, limits, the process role if (g_tsv) fprintf(g_tsv, "# kind: nvn-per-frame value = call count when name is an NVN function name; names starting with @ are timing probes (ms / count)\nframe\tname\tvalue\n"); } uint64_t total = 0; unsigned nfn = 0; @@ -1949,6 +1951,16 @@ NVN(nvnQueuePresentTexture, void, NVNqueue *q, NVNwindow *w, int idx) { uint64_t pc = (uint64_t)(ru.ru_utime.tv_sec + ru.ru_stime.tv_sec) * 1000000000ull + (uint64_t)(ru.ru_utime.tv_usec + ru.ru_stime.tv_usec) * 1000ull; if (pproc) trow(f, "@proc_cpu_ms", (pc - pproc) / 1e6); pproc = pc; trow(f, "@call_ms", (t0 - g_t0_ns) / 1e6); + dm_sysprof sp; // the latest 100 ms system sample (sysprof.m) + if (dm_sysprof_get(&sp)) { + if (sp.gpu_mhz >= 0) { trow(f, "@gpu_mhz", sp.gpu_mhz); trow(f, "@gpu_on", sp.gpu_on); } + if (sp.gpu_w >= 0) trow(f, "@gpu_w", sp.gpu_w); + if (sp.boost >= 0) trow(f, "@gpu_boost", sp.boost); + if (sp.cltm >= 0) trow(f, "@gpu_cltm", sp.cltm); + if (sp.droop >= 0) trow(f, "@gpu_droop", sp.droop); + trow(f, "@role", sp.role); trow(f, "@thermal", sp.thermal); trow(f, "@low_power", sp.low_power); + } + if (getenv("DM_AB")) trow(f, "@ab", mtl_ab_mask()); // which DM_AB switches were on for this frame, so a report compares them over one session (perf_report.py) } trow(f, "@passes", (double)(ps - prev_pass)); trow(f, "@draws", (double)(dr - prev_draw)); static uint64_t pl, pst, pf, pudc; uint64_t l, st, fu; mtl_bw(&l, &st, &fu); diff --git a/dm/gfx/nvn/nvn_mtl.m b/dm/gfx/nvn/nvn_mtl.m index 86b8eff036..228b35da6e 100644 --- a/dm/gfx/nvn/nvn_mtl.m +++ b/dm/gfx/nvn/nvn_mtl.m @@ -3094,6 +3094,7 @@ static int sw_mode(const char *name, int dflt) { return m; } static inline int sw_on(int m) { return sw_on_at(m, atomic_load_explicit(&g_ab_phase, memory_order_relaxed)); } +int mtl_ab_mask(void) { int m = 0; for (int i = 0; i < g_sw_n; i++) if (g_sw_mode[i] >= 2 && sw_on(g_sw_mode[i])) m |= 1 << i; return m; } // the frame rows' @ab: bit i = the i-th ab switch (sw_mode order) on in this phase // Each phase is reported once its frames' GPU times have arrived (8 frames late) as an [ab] line: the switches on in it, GPU time and whole frame time (p50 / p90 / mean over the phase // without its first quarter, while the GPU clock and the frame step settle), and attachment traffic and render passes per frame (the bandwidth ledger) enum { AB_MAXF = 4096 }; diff --git a/dm/host/Makefile b/dm/host/Makefile index 54afe1a93a..3604cecb3e 100644 --- a/dm/host/Makefile +++ b/dm/host/Makefile @@ -17,7 +17,7 @@ GAME_H = gen/$(GAME)/game_profile.h include ../mac/min_os.mk CFLAGS=-O1 -g -Wall -Wno-unused-function -mmacosx-version-min=$(MACOS_MIN) # Service-layer takeover hle_*.c files are included by wildcard: adding a file does not touch this line (avoids merge conflicts) -SRC=main.c loader.c hle.c crash.c probe.c thread.c save_sync.c memstat.m haptics_apple.m $(sort $(wildcard hle_*.c)) front_mac.m entry.S +SRC=main.c loader.c hle.c crash.c probe.c thread.c save_sync.c memstat.m sysprof.m haptics_apple.m $(sort $(wildcard hle_*.c)) front_mac.m entry.S # NVN null device + nn::vi + the Vulkan layer (dm/gfx/) # Sources under dm/gfx, dm/gfx/nvn, dm/gfx/tex, dm/gfx/vk and dm/gfx/gl are included by wildcard (tests/ and metal/ do not go into the host): adding a file does not touch this line GFX=$(sort $(wildcard ../gfx/*.c ../gfx/nvn/*.c ../gfx/nvn/*.m ../gfx/nvn/*.S ../gfx/tex/*.c ../gfx/tex/*.m ../gfx/vk/*.m ../gfx/gl/*.m)) diff --git a/dm/host/sysprof.h b/dm/host/sysprof.h new file mode 100644 index 0000000000..17d94ddb09 --- /dev/null +++ b/dm/host/sysprof.h @@ -0,0 +1,15 @@ +// System profile for the per-frame timing rows (sysprof.m): the latest 100 ms sample of what the system did with the GPU and the process. −1 = not measured +#pragma once +typedef struct { + double gpu_mhz; // mean clock of the GPU's powered states + double gpu_on; // % of the interval the GPU was powered (not OFF): not the same as busy + double gpu_w; // GPU power, watts + double boost; // the boost controller's requested state, mean P index (1 = lowest) + double cltm; // % of the interval a thermal limit applied to the GPU + double droop; // % of the interval a voltage droop limit applied + int role; // task_policy_get TASK_CATEGORY_POLICY role (1 foreground app, 2 background app, ...) + int thermal; // NSProcessInfo thermalState (0 nominal … 3 critical) + int low_power; // Low Power Mode +} dm_sysprof; +void dm_sysprof_start(void); // starts the sampler thread once (Mac; nothing elsewhere) +int dm_sysprof_get(dm_sysprof *out); // the latest sample; 0 when there is none diff --git a/dm/host/sysprof.m b/dm/host/sysprof.m new file mode 100644 index 0000000000..62e17cfdf6 --- /dev/null +++ b/dm/host/sysprof.m @@ -0,0 +1,148 @@ +// System profile for the per-frame timing rows (DM_NVN_TSV, Mac): what the system did with the game's GPU and process while the frames ran, so one session shows why a frame rate +// fell. A thread samples every 100 ms (dm_sysprof_start) and hle_nvn.c writes the latest sample into each frame's rows (@gpu_mhz and the rest, dm_sysprof_get): +// GPU clock and powered time: IOReport "GPU Stats" / "GPU Performance States" (GPUPH): residency of each performance state over the interval; the clock is the mean frequency of the +// powered states (pmgr's voltage-states9 table), the powered share is the time not OFF. Powered is not busy: the GPU stays powered between closely spaced submissions +// GPU power: IOReport "Energy Model" / "GPU Energy" over the interval +// What chose the clock: the boost controller's requested state (BSTGPUPH, mean P index), the share of time a thermal limit applied (GPU_CLTM other than NO_CLTM) and a voltage +// droop limit applied (GPUDVDH other than 100%) +// The process's role (task_policy_get TASK_CATEGORY_POLICY: 1 foreground app, 2 background app, ...) and the system's thermal state and Low Power Mode +// IOReport is a private library the system tools use (powermetrics, Activity Monitor); it needs no root. It is loaded with dlopen, so a system without it only leaves the GPU columns out. +// A change of role is logged as it happens: macOS sets the performance controller's targets by it +#import +#include +#include "sysprof.h" +#if TARGET_OS_OSX +#include +#include +#include +#include +#include +#include +#include "dm.h" + +typedef struct IOReportSubscription *IOReportSubscriptionRef; +static CFMutableDictionaryRef (*ir_channels)(CFStringRef, CFStringRef, uint64_t, uint64_t, uint64_t); +static void (*ir_merge)(CFDictionaryRef, CFDictionaryRef, CFTypeRef); +static IOReportSubscriptionRef (*ir_subscribe)(void *, CFMutableDictionaryRef, CFMutableDictionaryRef *, uint64_t, CFTypeRef); +static CFDictionaryRef (*ir_samples)(IOReportSubscriptionRef, CFMutableDictionaryRef, CFTypeRef); +static CFDictionaryRef (*ir_delta)(CFDictionaryRef, CFDictionaryRef, CFTypeRef); +static CFStringRef (*ir_name)(CFDictionaryRef), (*ir_unit)(CFDictionaryRef); +static int (*ir_format)(CFDictionaryRef), (*ir_nstates)(CFDictionaryRef); +static CFStringRef (*ir_state_name)(CFDictionaryRef, int); +static int64_t (*ir_residency)(CFDictionaryRef, int), (*ir_value)(CFDictionaryRef, int32_t); + +static pthread_mutex_t g_mu = PTHREAD_MUTEX_INITIALIZER; +static dm_sysprof g_last = {.gpu_mhz = -1, .gpu_on = -1, .gpu_w = -1, .boost = -1, .cltm = -1, .droop = -1, .role = -1, .thermal = -1, .low_power = -1}; +static double g_freq[32]; static int g_nfreq; + +static int load_ioreport(void) { + void *h = dlopen("/usr/lib/libIOReport.dylib", RTLD_LAZY); + if (!h) return 0; + ir_channels = dlsym(h, "IOReportCopyChannelsInGroup"); ir_merge = dlsym(h, "IOReportMergeChannels"); ir_subscribe = dlsym(h, "IOReportCreateSubscription"); + ir_samples = dlsym(h, "IOReportCreateSamples"); ir_delta = dlsym(h, "IOReportCreateSamplesDelta"); ir_name = dlsym(h, "IOReportChannelGetChannelName"); + ir_unit = dlsym(h, "IOReportChannelGetUnitLabel"); ir_format = dlsym(h, "IOReportChannelGetFormat"); ir_nstates = dlsym(h, "IOReportStateGetCount"); + ir_state_name = dlsym(h, "IOReportStateGetNameForIndex"); ir_residency = dlsym(h, "IOReportStateGetResidency"); ir_value = dlsym(h, "IOReportSimpleGetIntegerValue"); + return ir_channels && ir_merge && ir_subscribe && ir_samples && ir_delta && ir_name && ir_unit && ir_format && ir_nstates && ir_state_name && ir_residency && ir_value; +} + +static void load_freqs(void) { // the GPU's frequencies, lowest first: pmgr's voltage-states9, (frequency, voltage) pairs of 32-bit words + io_iterator_t it; + if (IOServiceGetMatchingServices(kIOMainPortDefault, IOServiceNameMatching("pmgr"), &it)) return; + for (io_object_t o; (o = IOIteratorNext(it));) { + CFDataRef d = IORegistryEntryCreateCFProperty(o, CFSTR("voltage-states9"), NULL, 0); + if (d) { + const uint32_t *p = (const uint32_t *)CFDataGetBytePtr(d); int n = (int)(CFDataGetLength(d) / 8); + for (int i = 0; i < n && g_nfreq < 32; i++) if (p[2 * i]) g_freq[g_nfreq++] = p[2 * i] / (p[2 * i] > 100000000u ? 1e6 : 1e3); // Hz on newer chips, kHz on older ones + CFRelease(d); + } + IOObjectRelease(o); + if (g_nfreq) break; + } + IOObjectRelease(it); +} + +static int str_is(CFStringRef s, const char *c) { char b[64] = ""; if (s) CFStringGetCString(s, b, sizeof b, kCFStringEncodingUTF8); return !strcmp(b, c); } + +static int task_role(void) { + task_category_policy_data_t p = {0}; mach_msg_type_number_t n = TASK_CATEGORY_POLICY_COUNT; boolean_t dflt = FALSE; + return task_policy_get(mach_task_self(), TASK_CATEGORY_POLICY, (task_policy_t)&p, &n, &dflt) == KERN_SUCCESS ? (int)p.role : -1; +} +static const char *role_name(int r) { + switch (r) { + case TASK_UNSPECIFIED: return "unspecified"; case TASK_FOREGROUND_APPLICATION: return "foreground app"; case TASK_BACKGROUND_APPLICATION: return "background app"; + case TASK_CONTROL_APPLICATION: return "control app"; case TASK_GRAPHICS_SERVER: return "graphics server"; case TASK_THROTTLE_APPLICATION: return "throttled app"; + case TASK_NONUI_APPLICATION: return "non-UI app"; case TASK_DEFAULT_APPLICATION: return "default app"; case TASK_DARWINBG_APPLICATION: return "darwin background app"; + default: return "unknown"; + } +} + +// One interval's channels: the GPU's state residencies and its energy +static void read_delta(CFDictionaryRef d, double secs, dm_sysprof *s) { + CFArrayRef a = CFDictionaryGetValue(d, CFSTR("IOReportChannels")); + for (CFIndex i = 0; a && i < CFArrayGetCount(a); i++) { + CFDictionaryRef c = CFArrayGetValueAtIndex(a, i); CFStringRef name = ir_name(c); + if (ir_format(c) == 1) { // a simple value: energy since the previous sample + if (!str_is(name, "GPU Energy")) continue; + double v = (double)ir_value(c, 0), scale = str_is(ir_unit(c), "nJ") ? 1e-9 : str_is(ir_unit(c), "uJ") ? 1e-6 : str_is(ir_unit(c), "mJ") ? 1e-3 : 0; + if (scale && secs > 0) s->gpu_w = v * scale / secs; + continue; + } + int n = ir_nstates(c); if (n <= 0) continue; + double tot = 0, on = 0, mhz = 0, pw = 0, limited = 0; int p = 0; + int gpuph = str_is(name, "GPUPH"), boost = str_is(name, "BSTGPUPH"), cltm = str_is(name, "GPU_CLTM"), droop = str_is(name, "GPUDVDH"); + if (!gpuph && !boost && !cltm && !droop) continue; + for (int k = 0; k < n; k++) { + double r = (double)ir_residency(c, k); CFStringRef sn = ir_state_name(c, k); tot += r; + if (gpuph || boost) { + if (str_is(sn, "OFF") || str_is(sn, "IDLE") || str_is(sn, "DOWN")) continue; + on += r; pw += r * ++p; if (gpuph && p - 1 < g_nfreq) mhz += r * g_freq[p - 1]; + } else if (cltm ? !str_is(sn, "NO_CLTM") : !str_is(sn, "100%")) limited += r; + } + if (tot <= 0) continue; + if (gpuph) { s->gpu_on = 100 * on / tot; s->gpu_mhz = on > 0 ? mhz / on : 0; } + else if (boost) s->boost = on > 0 ? pw / on : 0; + else if (cltm) s->cltm = 100 * limited / tot; + else s->droop = 100 * limited / tot; + } +} + +static void *sampler(void *arg) { + (void)arg; pthread_setname_np("dm-sysprof"); pthread_set_qos_class_self_np(QOS_CLASS_UTILITY, 0); + IOReportSubscriptionRef sub = NULL; CFMutableDictionaryRef sc = NULL; CFDictionaryRef prev = NULL; uint64_t tprev = 0; + if (load_ioreport()) { + load_freqs(); + CFMutableDictionaryRef ch = ir_channels(CFSTR("GPU Stats"), NULL, 0, 0, 0), em = ir_channels(CFSTR("Energy Model"), NULL, 0, 0, 0); + if (ch && em) ir_merge(ch, em, NULL); + if (ch) sub = ir_subscribe(NULL, ch, &sc, 0, NULL); + if (sub) { prev = ir_samples(sub, sc, NULL); tprev = clock_gettime_nsec_np(CLOCK_UPTIME_RAW); } + } + char fr[160] = ""; int w = 0; + for (int i = 0; i < g_nfreq && w < (int)sizeof fr - 8; i++) w += snprintf(fr + w, sizeof fr - w, "%s%.0f", i ? " " : "", g_freq[i]); + if (!sub) LOG("[RED] [sysprof] no IOReport subscription: the GPU clock, power and limit columns are left out of the frame rows"); + LOG("[sysprof] every 100 ms into the frame rows: %s; GPU frequencies %s MHz; process role %s", sub ? "GPU clock, powered time, power, boost state and limits (IOReport)" : "process role only", + g_nfreq ? fr : "unknown", role_name(task_role())); + int role0 = task_role(); + for (;;) { + usleep(100000); + dm_sysprof s = {.gpu_mhz = -1, .gpu_on = -1, .gpu_w = -1, .boost = -1, .cltm = -1, .droop = -1}; + if (sub) { + CFDictionaryRef cur = ir_samples(sub, sc, NULL); uint64_t t = clock_gettime_nsec_np(CLOCK_UPTIME_RAW); + if (cur && prev) { CFDictionaryRef d = ir_delta(prev, cur, NULL); if (d) { read_delta(d, (t - tprev) / 1e9, &s); CFRelease(d); } } + if (prev) CFRelease(prev); + prev = cur; tprev = t; + } + s.role = task_role(); + NSProcessInfo *pi = NSProcessInfo.processInfo; s.thermal = (int)pi.thermalState; s.low_power = pi.lowPowerModeEnabled; + if (s.role != role0) { LOG("[sysprof] process role %s → %s", role_name(role0), role_name(s.role)); role0 = s.role; } + pthread_mutex_lock(&g_mu); g_last = s; pthread_mutex_unlock(&g_mu); + } + return NULL; +} + +static void start_once(void) { pthread_t t; if (!pthread_create(&t, NULL, sampler, NULL)) pthread_detach(t); } +void dm_sysprof_start(void) { static pthread_once_t once = PTHREAD_ONCE_INIT; pthread_once(&once, start_once); } +int dm_sysprof_get(dm_sysprof *out) { pthread_mutex_lock(&g_mu); *out = g_last; pthread_mutex_unlock(&g_mu); return out->role >= 0; } +#else +void dm_sysprof_start(void) {} +int dm_sysprof_get(dm_sysprof *out) { (void)out; return 0; } +#endif diff --git a/dm/tools/impact_map.tsv b/dm/tools/impact_map.tsv index 96ef450bd0..2501c84843 100644 --- a/dm/tools/impact_map.tsv +++ b/dm/tools/impact_map.tsv @@ -27,6 +27,7 @@ scripts/push_romfs.sh *:* RomFS transfer: every game's iOS build scripts/regress.py - the regression harness dm/tools/usage.py - the usage manifests dm/tools/il2cpp_sym.py - read-only IL2CPP address analysis; not part of a game build or the host +dm/tools/perf_report.py - the report of a DM_NVN_TSV profile; not part of a game build or the host dm/tools/impact_map.tsv - this map dm/tools/lint_python_baseline.tsv - the lint baseline dm/gfx/hle_nv.c hle:_ZN2nv* graphics-library lifecycle and memory-query exports @@ -126,6 +127,7 @@ dm/host/main.c *:* the host's start dm/host/loader.c *:* module loading dm/host/hle.c hle:* the HLE tables dm/host/front_mac.m present:* the Mac front end +dm/host/sysprof.* - the host profiler: started only with DM_NVN_TSV (off by default), it writes timing rows and changes no game's run dm/host/dm_input.h hle:*hid* the shared input interface dm/host/motion_apple.h hle:*SixAxisSensor* controller motion supplied by GameController dm/host/pad_apple.h hle:*hid* controller face buttons from GameController diff --git a/dm/tools/perf_report.py b/dm/tools/perf_report.py new file mode 100644 index 0000000000..09d44f3340 --- /dev/null +++ b/dm/tools/perf_report.py @@ -0,0 +1,140 @@ +#!/usr/bin/env python3 +# One session's frame-rate report from the host's per-frame timing rows (DM_NVN_TSV): a timeline per second and every drop below the cap with what limited the frames there. +# Usage: python3 dm/tools/perf_report.py [--every S] [--all] +# Per second: fps, frame / CPU / GPU time (p50 and p95, ms), the hold (@itv), draws and passes, and, from the system profile (dm/host/sysprof.m, Mac): the GPU clock, the share +# of time the GPU was powered, its power, the boost controller's state, thermal and voltage-droop limits, the process role, thermal state and Low Power Mode. +# Drops: runs of seconds below 0.9 of the cap, each with the second before it, and a verdict from those columns: +# cpu the frame's CPU time (the present thread, @cpu_ms) alone does not fit the frame +# gpu-limit the GPU time does not fit and a thermal or droop limit applied, or the thermal state was serious or Low Power Mode on +# gpu-clock the GPU time does not fit at a clock in the lower third of its range with no limit applied: the performance controller chose the clock +# gpu the GPU time does not fit at a high clock: the work itself is too much for this GPU +# role the process was not the foreground app (role other than 1) during the drop +# pacing neither CPU nor GPU time explains the frame time (waits, presentation) +# A/B: with DM_AB= and switches set to ab, frames carry @ab (the switches on in their phase, bit i = the i-th ab switch the log names): each set is compared over the same +# session, without the first 300 frames after each switch +# --every S: seconds per timeline row (default 1); --all: print every row, not only the minute around each drop +import argparse, statistics, sys +from collections import defaultdict + +ROLES = {0: 'unspecified', 1: 'foreground', 2: 'background', 3: 'control', 4: 'graphics server', 5: 'throttled', 6: 'non-UI', 7: 'default', 8: 'darwin bg', -1: '?'} +COLS = ['@frame_ms', '@cpu_ms', '@gpu_ms', '@itv', '@draws', '@passes', '@gpu_mhz', '@gpu_on', '@gpu_w', '@gpu_boost', '@gpu_cltm', '@gpu_droop', '@role', '@thermal', '@low_power', '@call_ms', '@ab'] + + +def load(path): + rows = defaultdict(dict) + with open(path) as f: + for line in f: + p = line.rstrip('\n').split('\t') + if len(p) != 3 or p[1] not in COLS: continue + try: rows[int(p[0])][p[1]] = float(p[2]) + except ValueError: continue + return [dict(v, frame=k) for k, v in sorted(rows.items()) if '@call_ms' in v and '@frame_ms' in v] + + +def q(v, p): + if not v: return None + v = sorted(v); return v[min(len(v) - 1, int(p * len(v)))] + + +def bucket(frames, every): + out = []; t0 = frames[0]['@call_ms'] / 1000 + by = defaultdict(list) + for r in frames: by[int((r['@call_ms'] / 1000 - t0) // every)].append(r) + for k in sorted(by): + fr = by[k]; col = lambda c, fr=fr: [r[c] for r in fr if c in r and r[c] >= 0] + b = {'t': k * every, 'n': len(fr), 'fps': len(fr) / every, 'first': fr[0]['frame']} + for c in ('@frame_ms', '@cpu_ms', '@gpu_ms'): b[c] = (q(col(c), .5), q(col(c), .95)) + for c in ('@itv', '@draws', '@passes', '@gpu_mhz', '@gpu_on', '@gpu_w', '@gpu_boost', '@gpu_cltm', '@gpu_droop', '@thermal', '@low_power'): + v = col(c); b[c] = statistics.mean(v) if v else None + roles = col('@role'); b['@role'] = statistics.mode(roles) if roles else None + out.append(b) + return out + + +def fmt(x, d=0): + return '-' if x is None else f'{x:.{d}f}' + + +def verdict(b, budget, fmin, fmax): + if b['@role'] is not None and b['@role'] != 1: return 'role' + cpu, gpu = b['@cpu_ms'][0], b['@gpu_ms'][0] + if cpu is not None and cpu > budget: return 'cpu' + if gpu is not None and gpu > budget * 0.95: + if (b['@gpu_cltm'] or 0) > 1 or (b['@gpu_droop'] or 0) > 1 or (b['@thermal'] or 0) >= 2 or (b['@low_power'] or 0) > 0.5: return 'gpu-limit' + mhz = b['@gpu_mhz'] + if mhz is not None and fmax > fmin and mhz < fmin + (fmax - fmin) / 3: return 'gpu-clock' + return 'gpu' + return 'pacing' + + +def main(): + ap = argparse.ArgumentParser(description='Frame-rate report of one session from DM_NVN_TSV rows') + ap.add_argument('tsv'); ap.add_argument('--every', type=float, default=1.0); ap.add_argument('--all', action='store_true') + a = ap.parse_args() + frames = load(a.tsv) + if not frames: sys.exit('no frame rows with @call_ms (DM_NVN_TSV from this host?)') + bs = bucket(frames, a.every) + cap = max(round(statistics.median(b['fps'] for b in bs) / 30) * 30, 30) if bs else 60 + budget = 1000 / cap + mhz = [b['@gpu_mhz'] for b in bs if b['@gpu_mhz']] + fmin, fmax = (min(mhz), max(mhz)) if mhz else (0, 0) + has_sys = bool(mhz) + print(f'{len(frames)} frames over {bs[-1]["t"] + a.every:.0f} s; cap {cap} fps (budget {budget:.1f} ms); GPU clock seen {fmt(fmin)}–{fmt(fmax)} MHz' + + ('' if has_sys else ' (no system profile in this file: a host without dm/host/sysprof.m)')) + hdr = f'{"t s":>6} {"fps":>5} {"frame p50/95":>13} {"cpu p50/95":>11} {"gpu p50/95":>11} {"hold":>4} {"draws":>5} {"pass":>4} {"MHz":>5} {"on%":>4} {"W":>5} {"boost":>5} {"cltm":>4} {"droop":>5} {"role":>10} {"th":>2} {"lpm":>3} verdict' + drops, cur = [], None + for i, b in enumerate(bs): + low = b['fps'] < 0.9 * cap + if low: + if cur is None: cur = [i, i] + else: cur[1] = i + elif cur is not None: drops.append(cur); cur = None + if cur is not None: drops.append(cur) + show = set(range(len(bs))) if a.all else {j for s, e in drops for j in range(max(0, s - 30), min(len(bs), e + 10))} + + def row(b): + low = b['fps'] < 0.9 * cap + return (f'{b["t"]:6.0f} {b["fps"]:5.1f} {fmt(b["@frame_ms"][0],1):>6}/{fmt(b["@frame_ms"][1],1):<6} {fmt(b["@cpu_ms"][0],1):>5}/{fmt(b["@cpu_ms"][1],1):<5} {fmt(b["@gpu_ms"][0],1):>5}/{fmt(b["@gpu_ms"][1],1):<5}' + f' {fmt(b["@itv"],1):>4} {fmt(b["@draws"]):>5} {fmt(b["@passes"]):>4} {fmt(b["@gpu_mhz"]):>5} {fmt(b["@gpu_on"]):>4} {fmt(b["@gpu_w"],2):>5} {fmt(b["@gpu_boost"],1):>5}' + f' {fmt(b["@gpu_cltm"]):>4} {fmt(b["@gpu_droop"]):>5} {ROLES.get(b["@role"], str(b["@role"])) if b["@role"] is not None else "-":>10} {fmt(b["@thermal"]):>2} {fmt(b["@low_power"]):>3}' + + (f' {verdict(b, budget, fmin, fmax)}' if low else '')) + print('\nTimeline' + ('' if a.all else ' (around the drops; --all for every second)')); print(hdr) + last = -2 + for i, b in enumerate(bs): + if i not in show: continue + if i != last + 1 and last >= 0: print(' ...') + print(row(b)); last = i + print(f'\nDrops below {0.9 * cap:.0f} fps: {len(drops)}') + tally = defaultdict(float) + for s, e in drops: + seg = bs[s:e + 1]; vs = [verdict(b, budget, fmin, fmax) for b in seg] + for v in vs: tally[v] += a.every + before = bs[s - 1] if s > 0 else None + print(f' {seg[0]["t"]:.0f}–{seg[-1]["t"] + a.every:.0f} s (frame {seg[0]["first"]}): {min(b["fps"] for b in seg):.0f}–{max(b["fps"] for b in seg):.0f} fps; verdict {"/".join(sorted(set(vs)))}' + + (f'; the second before: GPU {fmt(before["@gpu_ms"][0],1)} ms at {fmt(before["@gpu_mhz"])} MHz, CPU {fmt(before["@cpu_ms"][0],1)} ms' if before else '')) + if tally: print('Seconds below the cap by verdict: ' + ', '.join(f'{k} {v:.0f} s' for k, v in sorted(tally.items(), key=lambda x: -x[1]))) + ab(frames, cap) + if has_sys: + at60 = [b for b in bs if b['fps'] >= 0.95 * cap and b['@gpu_mhz']] + if at60: print(f'At the cap: GPU {fmt(statistics.median(b["@gpu_ms"][0] for b in at60 if b["@gpu_ms"][0]),1)} ms at {fmt(statistics.median(b["@gpu_mhz"] for b in at60))} MHz, powered {fmt(statistics.median(b["@gpu_on"] for b in at60))}% (median of seconds)') + + + +def ab(frames, cap, settle=300): # DM_AB: each set of switches over its frames, without the first frames after each switch + if len({r.get('@ab') for r in frames if '@ab' in r}) < 2: return + groups, prev, since = defaultdict(list), None, 0 + for r in frames: + m = r.get('@ab') + since = since + 1 if m == prev else 0; prev = m + if m is not None and since >= settle: groups[m].append(r) + print(f'\nA/B (DM_AB phases by the switches on, mask as in the log\'s order; each switch\'s first {settle} frames left out)') + print(f'{"mode":>10} {"frames":>7} {"fps":>5} {"late %":>6} {"frame p50/95":>13} {"gpu p50/95":>11} {"MHz p50":>7} {"on% p50":>7} {"W p50":>5}') + for m in sorted(groups): + g = groups[m]; col = lambda c, g=g: [r[c] for r in g if c in r and r[c] >= 0] + fr = col('@frame_ms'); secs = sum(fr) / 1000 or 1 + late = 100 * sum(1 for x in fr if x > 1.25 * 1000 / cap) / max(len(fr), 1) + med = lambda c, d=0, col=col: fmt(q(col(c), .5), d) + print(f'{"base" if not m else f"mask {int(m)}":>10} {len(g):7d} {len(fr) / secs:5.1f} {late:6.1f} {med("@frame_ms",1):>6}/{fmt(q(fr, .95),1):<6} {med("@gpu_ms",1):>5}/{fmt(q(col("@gpu_ms"), .95),1):<5} {med("@gpu_mhz"):>7} {med("@gpu_on"):>7} {med("@gpu_w",2):>5}') + + +if __name__ == '__main__': main() diff --git a/docs/development.md b/docs/development.md index 5fda1788f3..e673ce2994 100644 --- a/docs/development.md +++ b/docs/development.md @@ -491,6 +491,10 @@ Limits: the replay matches the recording read for read only while the game's rea The benchmark gives each frame's GPU time; these switches split it by pass, on the Mac or on an iPhone (`Documents/env.txt`), and are off by default: `DM_NVN_GPUPROF=every:` (each encoder's GPU time and attachment traffic in one frame of every n), `DM_NVN_PASSDUMP=every:`, `DM_AB=` (switches set to `ab` alternate in phases of one run) and `DM_GPU_CAPTURE` (Metal GPU traces for Xcode, written to `DM_GPU_CAPTURE_DIR`, by default `gpu_captures/` in the working directory, which keeps the newest `DM_GPU_CAPTURE_KEEP`; an IPA built with `DM_METAL_CAPTURE=1`, or `MTL_CAPTURE_ENABLED=1` on the Mac). `dm/tools/gpuprof.py` reads their log lines. How to use them: [05, GPU time on the device](agents/05-debugging.md#gpu-time-on-the-device). +### Why a frame rate fell: one session's profile + +On the Mac, `DM_NVN_TSV=` (in the app's `env.txt` too; off by default) writes each frame's timing rows, and with them what the system did with the GPU and the process (`dm/host/sysprof.m`, sampled every 100 ms without root through IOReport): the GPU clock and the share of time it was powered (`@gpu_mhz`, `@gpu_on`; powered is not busy), its power (`@gpu_w`), the clock state the boost controller asked for (`@gpu_boost`), the share of time a thermal or voltage-droop limit applied (`@gpu_cltm`, `@gpu_droop`), the process role macOS gave the game (`@role`, 1 = foreground app), the thermal state and Low Power Mode; with `DM_AB` also `@ab`, the switches on in the frame's phase. `python3 dm/tools/perf_report.py ` turns one session into a timeline per second (fps, frame / CPU / GPU time, hold, draws, passes and those columns) and gives every drop below the cap a verdict: `cpu`, `gpu-clock` (the GPU's time does not fit at a clock the performance controller chose low, no limit applied), `gpu-limit`, `gpu`, `role` or `pacing`; with `DM_AB` it compares the switch sets over the same session. A change of role is logged as `[sysprof] process role …`. + ### Frame capture and replay `DM_NVN_CAPTURE=:1:` (an NVN game, Mac host) writes one frame to one file, at the boundary between recording and replay: from the frame's first `nvnQueueSubmitCommands` to its present (frames counted as `DM_NVN_SHOT` counts them). `dm/gfx/tests/nvn_replay` replays it against the replay layer of the tree it is built from (`nvn_mtl.m` and everything under it) and compares the presented frame with the live one: From 0f44aaca28cd865ac09c478a1279720e39179b6f Mon Sep 17 00:00:00 2001 From: Paolo Moretti Date: Sun, 1 Nov 2026 15:20:13 +0700 Subject: [PATCH 2/5] Frame step: a probe's grace lasts while its frames keep getting cheaper MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit On the Mac the GPU's performance controller raises the clock for a shorter deadline by about 100 MHz a second. A probe back to hold 1 had 30 grace frames: Breath of the Wild on an M5 Pro saw the clock rise 338 → 432 MHz and the GPU time fall 24.8 → 18.5 ms over a probe, which then failed, and the game stayed at 30 or 20 fps for minutes until a menu. A grace window whose second half costs at most 95% of its first (FSTEP_RAMP) and had a late frame now starts another, up to 180 frames in all (FSTEP_PROBE_MAX); a flat cost ends the probe as before. General, in the pure controller (nvn_fstep.h); DM_FSTEP_PROBE_RAMP=0 turns it off, ab compares it in one run. One 470 s run with the rule switched every 30 s: after the first 80 s every probe held, 11 in a row, each within about a second; the failures were in a phase with the rule off. t_fstep: a falling cost holds with the rule and fails without it, a flat cost lasts 33 frames as before, a cost that stalls ends one window later, one that never fits ends at FSTEP_PROBE_MAX. --- dm/games/01007EF00011E000/README.md | 2 ++ dm/gfx/nvn/hle_nvn.c | 7 ++++++ dm/gfx/nvn/nvn_fstep.h | 18 ++++++++++--- dm/gfx/nvn/nvn_mtl.m | 3 +++ dm/gfx/tests/t_fstep.c | 39 +++++++++++++++++++++++++++++ docs/agents/symptoms.md | 1 + docs/env_switches.tsv | 1 + docs/reference/frame-rate.md | 10 ++++++++ 8 files changed, 78 insertions(+), 3 deletions(-) diff --git a/dm/games/01007EF00011E000/README.md b/dm/games/01007EF00011E000/README.md index 1e08685b59..312e096549 100644 --- a/dm/games/01007EF00011E000/README.md +++ b/dm/games/01007EF00011E000/README.md @@ -29,6 +29,7 @@ No `tex_flush_upload` (a minute's boot saw it flush 32 CPU-filled textures with - The stubs: `setWaitVsyncInterval` (`main+0x11269b8`, called once a frame at `main+0x11267c0`; the framework keeps the interval at fw+0x244, getter vtable +0x138, read by both callers of `VFR::updateInterval` and directly in 43 places, and passes it to `nvnWindowSetPresentInterval`) takes the host's step unless the VFR override (+0x29 flag, +0x2c interval) is set. `ksys::VFR::updateInterval` (`main+0x151d3d0`, x0 = the VFR at `[main+0x1e93890]`, called from `GameScene::calc` and the per-frame delegate `main+0x1280f80`) takes the framework's interval in the next frame (ratio = step / 2, base interval 2, and the int interval 16 pieces of logic read); its stub publishes the override at state +0x24 so the host holds frames that long. The step is not written into the VFR call itself, because the game presents on its own thread and the step can change between the two VFR calls of a frame. - Mac (M4 Pro), from the title into the save's scene: 1.000 of real time at 60; with 12 ms added to every frame (`DM_TEST_PRESENT_LAG=1,12`) it drops to 30 and stays at 1.000. `DM_FPS_TARGET=30` holds 30 (saves power, also from `Documents/env.txt`); `0` runs the game's own interval controller. - **Frame-step probes (iPhone).** The GPU clock follows the hold: on an iPhone the game went from 14.4 to about 25 ms of GPU time a frame at 30 fps with the same 4,900 draws, its CPU still on the performance cores, and never tried 60 again; a GPU time at the longer hold of at least 1.3 times its time at 60 that alone does not fit 60 (`nvn_fstep_gpu_slowed`) now allows probes. Stepped up by pipeline compiles after a cutscene, it took 12.8–15.2 ms of GPU time a frame at 30 fps (p50) where 60 had held for minutes, and stayed at 30 for 36 and 46 s until the player switched out and back (the same 4,900 draws took 5.8 ms right after a trip to the background and 13.5 ms half a minute later); a step up after 8 s or more at 60 now keeps that run's cost, and a cost at the longer hold of at most 1.1 times it allows a probe (`nvn_fstep_same`). Log lines: `frame step: hold 2 → 1 … (probe, …)`, `the probe held / failed`, `hold 1 held at 0.86`. Details: [development.md, Power](../../../docs/development.md#power). +- **Frame-step probes on the Mac (resolved, 2026-11-01).** An M5 Pro, fullscreen, present snapshots on, encode thread off, the host's profiler (`dm/host/sysprof.m`, `@gpu_mhz` / `@gpu_on`): at 60 fps macOS lowered the GPU clock from about 1,200 to 400 MHz over 4 s whenever the frame fit, until the frame's GPU work was about 11.7 of 16.6 ms (GPU powered 98%, occupied 70%: the game's own work after its fence wait, the first cut and segments drained faster than encoded leave 2–5 ms a frame without GPU work). A heavier scene (4,200–4,700 draws, GPU 20–27 ms at 400 MHz, 8 ms at 1,200) stepped the hold to 2 or 3 within three frames, where the GPU is occupied 55–75% and the clock fell to its floor (338 MHz); each probe back to hold 1 saw the clock rise 338 → 432 MHz and the GPU time fall 24.8 → 18.5 ms over its 33 frames, then failed, and hold 2 stayed for minutes. The probe's grace now lasts while its frames keep getting cheaper: [A probe's grace lasts while its frames keep getting cheaper](../../../docs/reference/frame-rate.md#a-probes-grace-lasts-while-its-frames-keep-getting-cheaper). The game waits on the fence of the frame it just submitted (`@sync_ms` 9.7 ms ≈ the GPU's end after the present at 400 MHz, 0 at 1,200), as on the Switch; the host's fence is the last commit's and wakes on the GPU's signal. Holding back the first segment (`DM_NVN_CUT_FIRST=ab`) only moved the GPU's start 4 ms later and lost 7 fps. With the fix (a 470 s run, `DM_FSTEP_PROBE_RAMP=ab`, encode thread on) every probe after the first 80 s held, 11 in a row, each within about a second; the probes that failed (presents 3834, 3929, 4083) were in a phase with the rule off. - **Screens whose rate is not a multiple of 60 (from PR #27).** A cheap 50 ms frame shows 54.5 ms at 165 Hz; counted as late it kept the game at 20 fps for good, so the frame step lets a frame on time show one refresh longer than its hold (`shown_slack`, `nvn_fstep.h`). - **Resolved: menu repeat twice as fast at 60 fps (2026-10-26).** `sead::ControllerBase::updateDerivativeParams_` (`main+0xeb0ef0`) adds a constant 1.0 (`main+0xeb0f78`..`88`) to each held button's count and repeats when `fmod(count - delay, pulse)` falls below that step, so delays and pulses were counted in frames: holding Down in the System menu for 0.3 s went 5 entries at 60 and 2 at 30 (found by MacNativeGames, `866beb9`). A `FRAME_STEP` stub at `main+0xeb0f88` takes the VFR's ratio (`+0x3c`, interval / 2) instead, keeping 1.0 when there is no VFR or the ratio is not positive. Mac, 60 fps: 0.2 / 0.3 / 0.4 s now move 1 / 2 / 3 entries, as the game does at 30. The pause menu's fast-repeat countdown (`main+0xe67d00`) already reads the VFR's delta. - `DM_NVN_CUT` growing segments (64, 128, 256 … draws) were tried for fewer commits: the game fell from 60 to 30 fps in the same scene (GPU idle while the long last segments were encoded). @@ -199,6 +200,7 @@ Before publishing, the fixes were integrated with main's pipeline archive and GP - **Open, a SIGSEGV in `nn::util::RelocationTable::Relocate` at one cutscene ([issue #810](https://github.com/seedds/nxnative/issues/810)):** not a host bug as far as the reporter's files show. Their `Event/Demo154_2.sbeventpack` has our length (1,196,295 bytes) but another SHA-256 (`e74e7826…`, ours `b822e8a2…`), from a base NSP that fails the hash check, extracted with `--allow-damaged`; the model's relocation table is inside that file, so heap placement is not the cause. Open until the scene loads after their extraction from a clean NSP. Led to [Extraction of a damaged NSP ends in "The LinkedList is empty"](../../../docs/reference/packing.md#extraction-of-a-damaged-nsp-ends-in-the-linkedlist-is-empty) and [A crash from a damaged NSP's file looks like a host bug](../../../docs/reference/packing.md#a-crash-from-a-damaged-nsps-file-looks-like-a-host-bug). - **Resolved, parallel rewriting (2026-10-31):** [Parallel scans preserve rewrite output](../../../docs/reference/rewriter.md#parallel-scans-preserve-rewrite-output). All 21 binary and TSV outputs of the three modules of v1114112 are byte-identical to the sequential rewriter. The full regression against `635e8008` passed: zero red diagnostics, matching screenshots, and no frame-time or memory regression (M4 Pro, Xcode 27.2 with the per-run compiler override on both revisions). - [Benchmark captures perturb the measured frame pacing](../../../docs/reference/frame-rate.md#benchmark-captures-perturb-the-measured-frame-pacing). +- **Resolved, the Mac's GPU clock at its floor at 30 fps in heavy scenes:** [A probe's grace lasts while its frames keep getting cheaper](../../../docs/reference/frame-rate.md#a-probes-grace-lasts-while-its-frames-keep-getting-cheaper). - **Resolved, two stale chain folders held 4.4 GB:** [Old shader library folders grew a game's build folder with each chain change](../../../docs/reference/shaders.md#old-shader-library-folders-grew-a-games-build-folder-with-each-chain-change). - **Resolved: 1.6.0 (v786432) crashed 10-60 s into the first scene (issue #251)** in `h_nvnBufferGetAddress` (`main+0x14ef6e0`, reader `main+0x14ef440`) and in other places (`main+0x12970dc`, `+0x13615f4`, `+0x1445d48`, `+0x1db5cb8`, `+0x1472470`): the game's job queue (`main+0x13a0730`) takes its lock with a bare `ldxr` (no acquire), so on Apple cores two workers popped the same job, and two threads built draw lists into one view and arena (`main+0x14e8884` begin, commit `main+0x14ee3c0`). [Lock acquire without acquire ordering runs a queue item twice](../../../docs/reference/threads.md#lock-acquire-without-acquire-ordering-runs-a-queue-item-twice). - **Resolved build guard and cache isolation; rendering cause open:** [Tested tools and compiler-specific shader caches](../../../docs/reference/shaders.md#tested-tools-and-compiler-specific-shader-caches). diff --git a/dm/gfx/nvn/hle_nvn.c b/dm/gfx/nvn/hle_nvn.c index 4402762606..691c20cba2 100644 --- a/dm/gfx/nvn/hle_nvn.c +++ b/dm/gfx/nvn/hle_nvn.c @@ -1383,6 +1383,10 @@ static int present_itv(const win_t *o); static int link_wait(const win_t *o, uint64_t timeout_ns); __attribute__((weak)) void dm_main_yield_stats(uint64_t *n, uint64_t *ns) { *n = 0; *ns = 0; } // The host's hle_thread.c provides the ground truth; 0 in graphics unit tests __attribute__((weak)) uint32_t dm_guest_work_qos(unsigned *count) { if (count) *count = 0; return QOS_CLASS_UNSPECIFIED; } +int mtl_ab_mask(void); // nvn_mtl.m: the DM_AB switches on in this frame's phase +int mtl_probe_ramp_on(void); // nvn_mtl.m: DM_FSTEP_PROBE_RAMP (default on; ab with DM_AB) +__attribute__((weak)) void dm_sysprof_start(void) {} // sysprof.m (the host); none in graphics unit tests +__attribute__((weak)) int dm_sysprof_get(dm_sysprof *out) { (void)out; return 0; } __attribute__((weak)) void dm_yield_top(char *out, size_t n) { if (n) snprintf(out, n, "-"); } // hle_thread.c: the threads that yielded most since the last call; none in graphics unit tests __attribute__((weak)) void dm_thread_cpu(char *out, size_t n, double secs) { (void)secs; if (n) snprintf(out, n, "-"); } // hle_thread.c: guest-thread CPU by Switch priority band since the last call void mtl_res_stats(char *out, size_t n); @@ -1845,6 +1849,9 @@ static void fstep_tick(const win_t *o, int c) { slow_bits = (uint16_t)(slow_bits << 1 | (shown > k + FSTEP_LATE)); if (__builtin_popcount(slow_bits) >= 12) g_fs.screen = 2; } + // A probe's grace lasts while its frames keep getting cheaper (nvn_fstep.h FSTEP_RAMP): macOS raises the GPU clock for the shorter deadline over seconds, not the iPhone's 30 frames + // (Breath of the Wild on an M5 Pro: the probe's 33 frames took the clock 338 → 432 MHz and its GPU time 24.8 → 18.5 ms, then it failed at 22 ms frames; hold 1 needed about 560 MHz) + g_fs.ramp = mtl_probe_ramp_on(); int n = nvn_fstep_next(&g_fs, shown, cost, kmin, kmax, fixed, cslow || gslow); __atomic_store_n((uint32_t *)(dm_fps_state + 0x20), (uint32_t)n, __ATOMIC_RELAXED); atomic_store(&g_fs_k, g_fs.k); held[g_fs.k]++; if (fixed) fixed_sum += (uint64_t)n; // the stubs count only the host's steps diff --git a/dm/gfx/nvn/nvn_fstep.h b/dm/gfx/nvn/nvn_fstep.h index 9f80c4e601..bdb391bab2 100644 --- a/dm/gfx/nvn/nvn_fstep.h +++ b/dm/gfx/nvn/nvn_fstep.h @@ -31,6 +31,12 @@ #define FSTEP_HOLD_MAX 480.0 #define FSTEP_GRACE 30 // a probe's first frames, whose lateness neither fails it nor counts toward a step up (the controller lowered the clock within 10 frames of a step to 30) #define FSTEP_SAME 1.1 // the cost at the longer hold against the cost that held kmin: at most this much is the same scene (BotW at hold 2: 1.0–1.07 times its hold-1 GPU time) +// The grace is renewed (nvn_fstep.ramp) while the probe's frames keep getting cheaper: a controller that raises the clock slowly is still raising it. macOS raises the GPU clock +// of a game that misses its deadline at 85–100% GPU occupancy by about 100 MHz a second (Breath of the Wild on an M5 Pro: 338 → 432 MHz over a 33-frame probe, GPU 24.8 → 18.5 ms, +// then the probe failed at 22 ms frames; hold 1 needs about 560 MHz there), where the iPhone's controller settles within the 30 frames. A window of FSTEP_GRACE frames whose +// second half cost at most 1 − FSTEP_RAMP of its first half, and had a late frame (a window on time is judged as a trial), starts another, up to FSTEP_PROBE_MAX frames in all +#define FSTEP_RAMP 0.05 // the fall in cost from one half of a grace window to the next that shows the clock still rising (the per-frame noise of a 25 ms frame is 4%, of 15 frames 1%) +#define FSTEP_PROBE_MAX 180 // grace frames a probe may take in all (3 s at 60 fps): a clock that keeps rising without reaching the hold is not waited for longer typedef struct { int k, step; // vsyncs each frame stays on screen; the step handed to the game for the next frame (k, or k + 1 while paying back) @@ -38,6 +44,8 @@ typedef struct { double debt; // real time the game is behind, in vsyncs int late_run, fit_run, trial; // late frames in a row; frames in a row whose cost fits k − 1; frames left of a trial at k − 1 (0 = none) int probe, grace; // 1: the trial in progress is a probe; 2: a probe held and its run at kmin has not ended yet; frames left of the probe's grace + int ramp; // set by the caller (kept): 1 = a probe's grace is renewed while its frames keep getting cheaper (FSTEP_RAMP; the host's DM_FSTEP_PROBE_RAMP) + double pa, pb; int plate, ptotal; // the current grace window: the cost of its first and second halves (sums), its late frames; grace frames this probe has taken in all double hold, since; // vsyncs a trial waits for after a step up; vsyncs since the last step up double shown_slack; // vsyncs a frame on time may show longer than k (set by the caller): one refresh on screens whose rate is not a multiple of 60; the cost keeps FSTEP_LATE int screen; // set by the caller before each call, then cleared: 0 = judge lateness by shown and cost; 1 = the screen showed a recent frame on time, 2 = late. With present @@ -76,13 +84,17 @@ static inline int nvn_fstep_next(nvn_fstep *s, double shown, double cost, int km s->since += shown; int cap_probe = kmin < s->kmin && s->kmin <= FSTEP_MAX && s->k > kmin; if (cap_probe) { // the cap rose: a probe at once, whose grace covers the clocks still set for the longer hold - s->k = kmin; s->probes++; s->trial = FSTEP_RUN; s->probe = 1; s->grace = FSTEP_GRACE; s->fit_run = s->late_run = 0; + s->k = kmin; s->probes++; s->trial = FSTEP_RUN; s->probe = 1; s->grace = FSTEP_GRACE; s->fit_run = s->late_run = 0; s->pa = s->pb = 0; s->plate = s->ptotal = 0; } else if (kmin < s->kmin || s->k < kmin) s->k = kmin; // the game's own step ended, or the cap fell if (s->k > kmax) s->k = kmax; s->kmin = kmin; int scr = s->screen; s->screen = 0; int late = scr ? scr == 2 : shown > held + FSTEP_LATE + s->shown_slack || cost > held + FSTEP_LATE, grace = s->grace > 0; - if (grace && !cap_probe) s->grace--; // the completed frame at the old cap does not consume the new hold's grace + if (grace && !cap_probe) { // the completed frame at the old cap does not consume the new hold's grace + if (s->grace > FSTEP_GRACE / 2) s->pa += cost; else s->pb += cost; + s->plate += late; s->ptotal++; + if (!--s->grace && s->ramp && s->plate && s->ptotal + FSTEP_GRACE <= FSTEP_PROBE_MAX && s->pb <= (1 - FSTEP_RAMP) * s->pa) { s->grace = FSTEP_GRACE; s->pa = s->pb = 0; s->plate = 0; } // still getting cheaper: another window + } if (late) { s->late++; s->late_run = grace ? 0 : s->late_run + 1; s->fit_run = 0; } else s->late_run = 0; // The cost of the frames on time (a hitch is not what the scene costs): at kmin, and at the longer hold if (kmin != s->ckmin) { // another cap: its run starts over, and what held it before comes back @@ -113,7 +125,7 @@ static inline int nvn_fstep_next(nvn_fstep *s, double shown, double cost, int km if (!late) s->fit_run = s->k > kmin && cost <= FSTEP_FIT * (s->k - 1) ? s->fit_run + 1 : 0; if (s->fit_run >= FSTEP_RUN && s->since >= s->hold && !s->trial) { s->k--; s->downs++; s->trial = FSTEP_RUN; s->fit_run = 0; } else if ((slow || nvn_fstep_same(s)) && s->k > kmin && s->since >= s->hold && !s->trial) { // probe: straight to kmin, so the controller sees the whole deadline - s->k = kmin; s->downs++; s->probes++; s->trial = FSTEP_RUN; s->probe = 1; s->grace = FSTEP_GRACE; s->fit_run = s->late_run = 0; + s->k = kmin; s->downs++; s->probes++; s->trial = FSTEP_RUN; s->probe = 1; s->grace = FSTEP_GRACE; s->fit_run = s->late_run = 0; s->pa = s->pb = 0; s->plate = s->ptotal = 0; } s->step = s->k + (s->debt >= 1 && s->k < FSTEP_MAX); s->paid += s->step > s->k; diff --git a/dm/gfx/nvn/nvn_mtl.m b/dm/gfx/nvn/nvn_mtl.m index 228b35da6e..c7d0683b21 100644 --- a/dm/gfx/nvn/nvn_mtl.m +++ b/dm/gfx/nvn/nvn_mtl.m @@ -10751,6 +10751,9 @@ static void clear_tex(const p_clear_tex *c) { // copy only at its end, so the subtitle band's gradient (BC3, 32x512) came out as the next texture's blocks. Committed at the first pass boundary, the copies run while the host encodes the rest static int cut_draws(void) { static int v = -1; if (v < 0) { const char *e = getenv("DM_NVN_CUT"); v = e ? atoi(e) : 64; MLOG("segmented submission: a segment is submitted between passes every %d draws (DM_NVN_CUT, 0 = off)", v); } return v; } static uint64_t g_cut_draw0, g_cut_sub, g_cuts, g_copy_cuts; +// DM_FSTEP_PROBE_RAMP=1 (default) / 0 / ab: a frame-step probe's grace is renewed while its frames keep getting cheaper (nvn_fstep.h FSTEP_RAMP), the time macOS's GPU clock takes to rise for the shorter deadline +static int probe_ramp_mode(void) { static int m = -1; if (m < 0) m = sw_mode("DM_FSTEP_PROBE_RAMP", 1); return m; } +int mtl_probe_ramp_on(void) { return sw_on(probe_ramp_mode()); } static void sub_cut(void) { int n = cut_draws(); if (!g_cb || g_enc) return; diff --git a/dm/gfx/tests/t_fstep.c b/dm/gfx/tests/t_fstep.c index be0678f9a9..7c06b13247 100644 --- a/dm/gfx/tests/t_fstep.c +++ b/dm/gfx/tests/t_fstep.c @@ -309,6 +309,45 @@ int main(void) { sim m = {0}; m.s.shown_slack = 60.0 / 165; run(&m, 60, 0.5, 1, 3, 0); run(&m, 300, 1.32, 1, 3, 0); check(m.s.k == 2, " the slack does not hide work: 22 ms frames still step to hold 2"); } + { // A controller that raises the clock slowly (the Mac): the probe's frames at hold 1 start at 1.5 vsyncs and get 0.6% cheaper each frame, so they fit only after about 52 frames. + // Without the ramp rule the probe fails after its 30 grace frames and 3 late ones; with it (nvn_fstep.ramp) the grace is renewed while the frames keep getting cheaper and the probe holds + for (int ramp = 0; ramp <= 1; ramp++) { + sim m = {0}; run(&m, 60, 0.5, 1, 3, 0); run(&m, 300, 1.3, 1, 3, 0); m.slow = 1; m.s.ramp = ramp; + int at1 = 0, first_len = -1; + for (int i = 0; i < 400; i++) { + double w = m.s.k == 1 ? fmax(0.6, 1.5 * pow(0.994, at1)) : 1.2; + run(&m, 1, w, 1, 3, 0); + if (m.s.k == 1) at1++; else if (at1 && first_len < 0) first_len = at1; + } + if (!ramp) { + snprintf(b, sizeof b, "slowed, the clock rises slowly: without the ramp rule the probe fails after grace + 3 frames (%d frames at hold 1, failed %llu)", first_len, (unsigned long long)m.s.failed); + check(first_len == FSTEP_GRACE + 3 && m.s.failed >= 1, b); + } else { + snprintf(b, sizeof b, " with it the grace is renewed twice and the probe holds (k %d, probes %llu, failed %llu, grace frames %d)", m.s.k, (unsigned long long)m.s.probes, (unsigned long long)m.s.failed, m.s.ptotal); + check(m.s.k == 1 && m.s.probes == 1 && m.s.failed == 0 && m.s.probe == 2 && m.s.trial == 0 && m.s.ptotal == 3 * FSTEP_GRACE && first_len < 0, b); + snprintf(b, sizeof b, " its late frames are paid back: game time %.0f against real time %.2f (debt %.2f)", m.game, m.real, m.s.debt); + check(m.real - m.game - m.s.debt > -1.01 && m.real - m.game - m.s.debt < 1.01 && m.s.dropped == 0, b); + } + } + } + { // The ramp rule with a cost that does not fall (1.5 flat), one that falls and then stops short of the hold (1.6 down to 1.3), and one that keeps falling but never reaches it (3.0 at 0.5% a frame): + // the probe lasts grace + 3, two windows + 3, and FSTEP_PROBE_MAX + 3 frames + static const char *const what[] = {"ramp rule, the cost does not fall: the probe lasts its grace + 3 late frames as before (%d frames at hold 1)", + " the cost falls, then holds at 1.3: one more window, then the probe fails (%d frames at hold 1)", + " the cost keeps falling without reaching the hold: the grace ends at FSTEP_PROBE_MAX (%d frames at hold 1, failed %llu)"}; + static const int want[] = {FSTEP_GRACE + 3, 2 * FSTEP_GRACE + 3, FSTEP_PROBE_MAX + 3}; + for (int c = 0; c < 3; c++) { + sim m = {0}; run(&m, 60, 0.5, 1, 3, 0); run(&m, 300, 1.3, 1, 3, 0); m.slow = 1; m.s.ramp = 1; + int at1 = 0, first_len = -1; + for (int i = 0; i < 600 && first_len < 0; i++) { + double w = m.s.k != 1 ? 1.2 : c == 0 ? 1.5 : c == 1 ? fmax(1.3, 1.6 * pow(0.99, at1)) : 3.0 * pow(0.995, at1); + run(&m, 1, w, 1, 3, 0); + if (m.s.k == 1) at1++; else if (at1 && first_len < 0) first_len = at1; + } + snprintf(b, sizeof b, what[c], first_len, (unsigned long long)m.s.failed); + check(first_len == want[c] && m.s.k == 2 && m.s.failed == 1, b); + } + } printf("== %d checks, %d failed ==\n", checks, fail); return fail != 0; } diff --git a/docs/agents/symptoms.md b/docs/agents/symptoms.md index 63211de695..774d6d5873 100644 --- a/docs/agents/symptoms.md +++ b/docs/agents/symptoms.md @@ -328,6 +328,7 @@ One line per symptom in the [subsystem references](../reference/): what you see - on an iPhone, a game with the frame step at 60 fps drops a frame in most windows after a few minutes, and its GPU time per frame roughly doubles to triples (17-26 ms for the same scenes). → [A thermally serious iPhone holds 30 fps](../reference/frame-rate.md#a-thermally-serious-iphone-holds-30-fps) - in a game the host steps at 60 fps (`FRAME_STEP`), a prerendered movie plays at twice its speed, its sound falls behind, and the frame counter shows 60 during it. The log has `[movie]` lines with pictures 33 ms apart (`time 0 / 33000 / 67000 µs`) and no `frame step cap 60 → 30` at the movie. → [Movies hold 30 fps under the frame step](../reference/frame-rate.md#movies-hold-30-fps-under-the-frame-step) - after a 30 fps cap ends (a prerendered movie, the thermal cap), a GPU-bound game stays at 30 fps in a scene that held 60 before the cap; the log shows `frame step cap 30 → 60 fps` and a few frames later `frame step: hold 1 → 2 vsyncs at present … (3 late frames; …)`, with no probe after it. → [The frame step after a 30 fps cap ends](../reference/frame-rate.md#the-frame-step-after-a-30-fps-cap-ends) +- on a Mac, a GPU-bound game at 60 fps falls to 30 or 20 fps when the scene gets heavier and stays there until a menu or a lighter scene, while the GPU clock sits at its floor (338–400 MHz on an M5 Pro) and the GPU is powered 60–75% of the time; the log shows probes back to hold 1 that fail after about 33 frames (`frame step: hold 2 → 1 vsyncs … (probe, GPU 1.67× its time at hold 1)` then `the probe failed`), and the host's profiler (`@gpu_mhz`) shows the clock rising during each probe and falling back after it. → [A probe's grace lasts while its frames keep getting cheaper](../reference/frame-rate.md#a-probes-grace-lasts-while-its-frames-keep-getting-cheaper) - a game whose profile has a frame step (`FRAME_STEP` in its `patches.py`) runs at double speed when packed from another update; the log has no `frame step in whole vsyncs` line, and the frame counter shows 60. → [A derived profile drops the frame step its build lacks](../reference/frame-rate.md#a-derived-profile-drops-the-frame-step-its-build-lacks) - a fixed-step game runs at double speed (or slow motion at 30) after `DM_FPS_TARGET` is set, in `Documents/env.txt` or the launcher, on a build its profile's frame step stubs and limiter rows do not know. → [A present cap applies only with a frame step or an engine limit the host writes](../reference/frame-rate.md#a-present-cap-applies-only-with-a-frame-step-or-an-engine-limit-the-host-writes) - selecting 30 FPS changes the engine's interval field, but the screen and frame loop still run near 60 FPS. → [Engine-native frame caps also govern presentation](../reference/frame-rate.md#engine-native-frame-caps-also-govern-presentation) diff --git a/docs/env_switches.tsv b/docs/env_switches.tsv index fd7da19454..9591f941b1 100644 --- a/docs/env_switches.tsv +++ b/docs/env_switches.tsv @@ -40,6 +40,7 @@ DM_FPS_TARGET player Frame-rate cap: `30` or `60`, or `0` for the game's own lim DM_FS diagnostic When set, logs file opens, paths not found or not mounted, and a read summary every 64 MiB or 1000 reads DM_FSLOG diagnostic `=` writes one TSV line per ReadFile: seconds since boot, guest path, offset, length and guest buffer address DM_FSLOG_HASH diagnostic With `DM_FSLOG`, adds a column with the FNV-1a 64 hash of the bytes read +DM_FSTEP_PROBE_RAMP switch `0` ends a frame-step probe's grace after its 30 frames as before; by default the grace is renewed while the probe's frames keep getting cheaper (macOS raises the GPU clock for the shorter deadline over seconds); `ab` alternates with `DM_AB` DM_FULLSCREEN player `1` (any value but `0`) starts the Mac window in fullscreen; `0` or unset, a window. The Mac settings window's Display mode DM_GAME switch Selects the game profile (a title ID under `dm/games` or `DM_GAMES_DIR`) for the Python tools and the rewriter; there is no default DM_GAMES_DIR path Profile folders outside the repository, separated by `:`, searched after `dm/games`; the NSP script points it at a provisional or derived profile diff --git a/docs/reference/frame-rate.md b/docs/reference/frame-rate.md index fc69884ed2..8187908f7c 100644 --- a/docs/reference/frame-rate.md +++ b/docs/reference/frame-rate.md @@ -53,6 +53,16 @@ Frame pacing: the host's frame step, engine frame limiters, present intervals an - **Found on:** reading the code; modelled in `t_fstep` with the 30 fps movie cap ([Movies hold 30 fps under the frame step](#movies-hold-30-fps-under-the-frame-step)) and [The Legend of Zelda: Breath of the Wild](../../dm/games/01007EF00011E000/README.md)'s iPhone GPU times (0.86 vsyncs at hold 1, 1.5 at hold 2). Not yet seen on these paths in a device log; first seen on a Mac with a 30 fps mode in a downstream fork. - **Check:** `make -C dm/gfx/tests GAME=010015100B514000 t_fstep && dm/gfx/tests/t_fstep`: movie and thermal recovery, the first movie without a prior hitch, repeated caps after short and sustained runs, all 30 grace frames, failed-probe backoff and game-time debt. The original recovery cases fail on main before [PR #253](https://github.com/seedds/nxnative/pull/253); its initial fix still failed the first-movie, repeated-cap and full-grace regressions. All pass with the corrections above. +### A probe's grace lasts while its frames keep getting cheaper + +- **Symptom:** on a Mac, a GPU-bound game at 60 fps falls to 30 or 20 fps when the scene gets heavier and stays there until a menu or a lighter scene, while the GPU clock sits at its floor (338–400 MHz on an M5 Pro) and the GPU is powered 60–75% of the time; the log shows probes back to hold 1 that fail after about 33 frames (`frame step: hold 2 → 1 vsyncs … (probe, GPU 1.67× its time at hold 1)` then `the probe failed`), and the host's profiler (`@gpu_mhz`) shows the clock rising during each probe and falling back after it. +- **Cause:** macOS lowers the GPU clock while a vsync-paced game meets its deadline (to the point where the frame's GPU work is about 70% of the frame), and raises it for a late game at 85–100% GPU occupancy slowly, about 100 MHz a second. A heavier scene at that clock makes three late frames, so the frame step steps up within 50 ms, long before the clock could rise; at hold 2 or 3 the GPU idles between frames, the clock falls to its floor, and a probe back to hold 1 (`FSTEP_GRACE` 30 frames, the iPhone controller's settling time) sees the clock rise 338 → 432 MHz and the GPU time fall 24.8 → 18.5 ms, then fails at 22 ms frames; hold 1 needs about 560 MHz there. The GPU's occupancy stays below 100% because the game waits for the fence of the frame it just submitted (as on the Switch; `nvnQueueFenceSync` takes the fence of the last commit and the GPU's own signal wakes the wait), so between the GPU's end and the next frame's first segment the GPU has nothing: the game's own work (about 1 ms), the translation up to the first cut (`DM_NVN_CUT` 64 draws, 0.5 ms) and the segments the GPU drains faster than the host encodes them (1–4 ms a frame). +- **Fix:** `nvn_fstep.h` renews a probe's grace while the probe's frames keep getting cheaper (`nvn_fstep.ramp`, set by `fstep_tick` from `DM_FSTEP_PROBE_RAMP`, on by default; `0` turns it off, `ab` alternates with `DM_AB`): a grace window whose second half cost at most 95% of its first (`FSTEP_RAMP`) and had a late frame starts another, up to `FSTEP_PROBE_MAX` (180) grace frames in all. A cost that does not fall, or falls and stops short of the hold, fails the probe as before; a window with no late frame ends the grace and the probe is judged as a trial. The probe's late frames are paid back as any other. +- **Check:** `make -C dm/gfx/tests GAME=010015100B514000 t_fstep && dm/gfx/tests/t_fstep`: a cost falling 0.6% a frame fails the probe without the rule and holds with it (three windows); a flat cost, a cost that stops at 1.3 and a cost that falls without reaching the hold last 33, 63 and 183 frames. +- **Found on:** [The Legend of Zelda: Breath of the Wild](../../dm/games/01007EF00011E000/README.md#the-frame-step-current) (Mac M5 Pro, fullscreen, present snapshots, the host's profiler); resolved there: in a 470 s run with the rule switched every 30 s, every probe with it held (11 in a row). +- **Note:** what shortens the serial chain itself, so the GPU's occupancy at a GPU-bound hold is higher and the clock rises faster: Metal encoding on its own thread (`DM_NVN_ENC_THREAD=1`, the profile's `enc_thread on`; the submit thread's translation 6.5 → about 4 ms a frame, measured on an M4 Pro and for Need for Speed), and a smaller first segment. Neither can start the GPU before the game's own work after its wait, and neither was measured on this symptom yet. + + ### A derived profile drops the frame step its build lacks - **Symptom:** a game whose profile has a frame step (`FRAME_STEP` in its `patches.py`) runs at double speed when packed from another update; the log has no `frame step in whole vsyncs` line, and the frame counter shows 60. From 6549dc6aef5a5e035d2f76ad2355d1ec9fe85923 Mon Sep 17 00:00:00 2001 From: Paolo Moretti Date: Sun, 1 Nov 2026 15:20:13 +0700 Subject: [PATCH 3/5] Breath of the Wild: Metal encoding on its own thread on the Mac; the encode thread records texture-to-buffer copies with blit options MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The game waits on the fence of the frame it just submitted, so the submit thread's translation is part of its frame. With the profile's enc_thread on, an M5 Pro run (470 s outdoors) took the present thread's CPU from 5.9 to 3.4–4.4 ms a frame and the submit from 6.6 to 5.0 ms; iOS has it on already. With it, the graphics tests built for this profile reached a copy the deferred encoder had no stand-in for: copyFromTexture:…toBuffer:…options: (one plane of a combined depth / stencil texture), and the host stopped with "FATAL deferred encoding" (t_rt_range and t_unwritten_store under DM_NVN_UNWRITTEN_DC=0). nvn_rec.h records it now (RO_C_COPY_TB_OPT); both tests pass. --- dm/games/01007EF00011E000/game.tsv | 3 +++ dm/gfx/nvn/nvn_rec.h | 8 +++++++- dm/tools/tests/test_launcher_settings.py | 6 +++--- docs/agents/game-patches.md | 4 ++-- 4 files changed, 15 insertions(+), 6 deletions(-) diff --git a/dm/games/01007EF00011E000/game.tsv b/dm/games/01007EF00011E000/game.tsv index 5462e229bb..80d4c18484 100644 --- a/dm/games/01007EF00011E000/game.tsv +++ b/dm/games/01007EF00011E000/game.tsv @@ -29,6 +29,9 @@ fps_target 60 # pipeline archive, the prepare step and the hybrid pipelines on the iPhone too (5,100 prewarm lines prepared in 0.28 s at start instead of compiling on first use) present_snap on pso_mtl4 on +# Metal encoding on its own thread on the Mac too (nvn_rec.h): the game waits on the fence of the frame it just submitted, so the submit thread's translation is in its frame. +# M5 Pro (2026-11-01, 470 s outdoors): present-thread CPU 5.9 → 3.4–4.4 ms a frame, the submit 6.6 → 5.0 ms; M4 Pro 4.30 → 3.16 ms (PR #62); on by default on iOS already +enc_thread on # ---- Versions ---- # only the merged 1.9.0 copy is extracted; the base game's own build IDs are added when needed diff --git a/dm/gfx/nvn/nvn_rec.h b/dm/gfx/nvn/nvn_rec.h index c584ab2b69..7eef5196e3 100644 --- a/dm/gfx/nvn/nvn_rec.h +++ b/dm/gfx/nvn/nvn_rec.h @@ -65,7 +65,7 @@ enum { RO_BAR_QUEUE, RO_BAR_AFTER_STAGES, RO_BAR_ENCODER, RO_R_TABLE, RO_R_PSO, RO_R_DSS, RO_R_VIEWPORT, RO_R_SCISSOR, RO_R_CULL, RO_R_WINDING, RO_R_FILL, RO_R_BIAS, RO_R_CLIP, RO_R_SREF, RO_R_BLEND, RO_R_VIS, RO_R_AMP, RO_R_DRAW, RO_R_DRAW_INST, RO_R_DRAW_IND, RO_R_DRAW_IDX, RO_R_DRAW_IDX_IND, RO_R_MESH, RO_R_STORE_C, RO_R_STORE_D, RO_R_STORE_S, - RO_C_TABLE, RO_C_PSO, RO_C_DISPATCH, RO_C_DISPATCH_IND, RO_C_COPY_BB, RO_C_COPY_BT, RO_C_COPY_TB, RO_C_COPY_TT, RO_C_FILL, + RO_C_TABLE, RO_C_PSO, RO_C_DISPATCH, RO_C_DISPATCH_IND, RO_C_COPY_BB, RO_C_COPY_BT, RO_C_COPY_TB, RO_C_COPY_TB_OPT, RO_C_COPY_TT, RO_C_FILL, RO_T_ADDR, RO_T_TEX, RO_T_SAMP, RO_LABEL, RO_R_TS, RO_C_TS, // diagnostics: DM_NVN_ENC_LABEL, DM_NVN_GPUPROF RO_NOTE, // a[0] an _Atomic uint64_t, a[1] a value: the encode thread has made every call before this one (rec_note_wait) @@ -159,6 +159,8 @@ static void rec_exec(const rec_t *r) { toTexture:rec_id(a[1]) destinationSlice:a[8] destinationLevel:a[9] destinationOrigin:MTLOriginMake(a[10], a[11], a[12])]; break; case RO_C_COPY_TB: [(id)e copyFromTexture:rec_id(a[0]) sourceSlice:a[2] sourceLevel:a[3] sourceOrigin:MTLOriginMake(a[4], a[5], a[6]) sourceSize:MTLSizeMake(a[7], a[8], a[9]) toBuffer:rec_id(a[1]) destinationOffset:a[10] destinationBytesPerRow:a[11] destinationBytesPerImage:a[12]]; break; + case RO_C_COPY_TB_OPT: [(id)e copyFromTexture:rec_id(a[0]) sourceSlice:a[2] sourceLevel:a[3] sourceOrigin:MTLOriginMake(a[4], a[5], a[6]) sourceSize:MTLSizeMake(a[7], a[8], a[9]) + toBuffer:rec_id(a[1]) destinationOffset:a[10] destinationBytesPerRow:a[11] destinationBytesPerImage:a[12] options:(MTLBlitOption)a[13]]; break; case RO_C_COPY_TT: [(id)e copyFromTexture:rec_id(a[0]) sourceSlice:a[2] sourceLevel:a[3] sourceOrigin:MTLOriginMake(a[4], a[5], a[6]) sourceSize:MTLSizeMake(a[7], a[8], a[9]) toTexture:rec_id(a[1]) destinationSlice:a[10] destinationLevel:a[11] destinationOrigin:MTLOriginMake(a[12], a[13], a[14])]; break; case RO_C_FILL: [(id)e fillBuffer:rec_id(a[0]) range:NSMakeRange(a[1], a[2]) value:(uint8_t)a[3]]; break; @@ -297,6 +299,10 @@ static inline id rec_table_real(id t) { return [t isKindOfClass:[DmRecTable clas - (void)copyFromTexture:(id)s sourceSlice:(NSUInteger)sl sourceLevel:(NSUInteger)lv sourceOrigin:(MTLOrigin)o sourceSize:(MTLSize)z toBuffer:(id)d destinationOffset:(NSUInteger)doff destinationBytesPerRow:(NSUInteger)row destinationBytesPerImage:(NSUInteger)img { rec_t *r = rec_put(RO_C_COPY_TB, 2); r->a[0] = rec_obj(s); r->a[1] = rec_obj(d); r->a[2] = sl; r->a[3] = lv; r->a[4] = o.x; r->a[5] = o.y; r->a[6] = o.z; r->a[7] = z.width; r->a[8] = z.height; r->a[9] = z.depth; r->a[10] = doff; r->a[11] = row; r->a[12] = img; } +// With blit options: one plane of a combined depth / stencil texture (nvn_mtl.m enc_b_copy_texture_buffer_opt); without this stand-in the encode thread stopped there (t_rt_range, t_unwritten_store) +- (void)copyFromTexture:(id)s sourceSlice:(NSUInteger)sl sourceLevel:(NSUInteger)lv sourceOrigin:(MTLOrigin)o sourceSize:(MTLSize)z toBuffer:(id)d destinationOffset:(NSUInteger)doff destinationBytesPerRow:(NSUInteger)row destinationBytesPerImage:(NSUInteger)img options:(MTLBlitOption)opt { + rec_t *r = rec_put(RO_C_COPY_TB_OPT, 2); r->a[0] = rec_obj(s); r->a[1] = rec_obj(d); r->a[2] = sl; r->a[3] = lv; r->a[4] = o.x; r->a[5] = o.y; r->a[6] = o.z; r->a[7] = z.width; r->a[8] = z.height; r->a[9] = z.depth; + r->a[10] = doff; r->a[11] = row; r->a[12] = img; r->a[13] = opt; } - (void)copyFromTexture:(id)s sourceSlice:(NSUInteger)sl sourceLevel:(NSUInteger)lv sourceOrigin:(MTLOrigin)o sourceSize:(MTLSize)z toTexture:(id)d destinationSlice:(NSUInteger)dsl destinationLevel:(NSUInteger)dlv destinationOrigin:(MTLOrigin)dorg { rec_t *r = rec_put(RO_C_COPY_TT, 2); r->a[0] = rec_obj(s); r->a[1] = rec_obj(d); r->a[2] = sl; r->a[3] = lv; r->a[4] = o.x; r->a[5] = o.y; r->a[6] = o.z; r->a[7] = z.width; r->a[8] = z.height; r->a[9] = z.depth; r->a[10] = dsl; r->a[11] = dlv; r->a[12] = dorg.x; r->a[13] = dorg.y; r->a[14] = dorg.z; } diff --git a/dm/tools/tests/test_launcher_settings.py b/dm/tools/tests/test_launcher_settings.py index cd43d2d710..1d25b64ea1 100644 --- a/dm/tools/tests/test_launcher_settings.py +++ b/dm/tools/tests/test_launcher_settings.py @@ -69,12 +69,12 @@ def test_iphone_switches_only_on_the_iphone(self): # the frame-rate counter an self.assertEqual((s['kind'], s['default'], s['options'], s['level']), ('choice', '0', [['0', 'Window'], ['1', 'Fullscreen']], 'basic')) def test_defaults_follow_each_platform_host(self): - # nvn_mtl.m pso4_on: Mac defaults on, iOS follows the profile. nvn_rec.h rec_on: iOS on, Mac off. - for gid, ios_pso in ((BOTW, '1'), (WONDER, '0')): + # nvn_mtl.m pso4_on: Mac defaults on, iOS follows the profile. nvn_rec.h rec_on: iOS on, Mac the profile's enc_thread (Breath of the Wild on, Wonder off). + for gid, ios_pso, mac_enc in ((BOTW, '1', '1'), (WONDER, '0', '0')): with self.subTest(game=gid): ios, mac = build(gid, 'nvn', 'ios'), build(gid, 'nvn', 'mac') self.assertEqual((ios['DM_PSO_MTL4']['default'], ios['DM_NVN_ENC_THREAD']['default']), (ios_pso, '1')) - self.assertEqual((mac['DM_PSO_MTL4']['default'], mac['DM_NVN_ENC_THREAD']['default']), ('1', '0')) + self.assertEqual((mac['DM_PSO_MTL4']['default'], mac['DM_NVN_ENC_THREAD']['default']), ('1', mac_enc)) def test_unknown_platform_is_rejected(self): with self.assertRaisesRegex(SystemExit, 'SETTINGS_PLATFORM must be ios or mac'): diff --git a/docs/agents/game-patches.md b/docs/agents/game-patches.md index 4179a72733..6202edc724 100644 --- a/docs/agents/game-patches.md +++ b/docs/agents/game-patches.md @@ -32,12 +32,12 @@ Every patch bound tighter than it could be: the open gaps, then the blocked, kep | `game` → `host` | MapPhysicalMemory limited to the application pool | memory | gap | judgement | 4 | `mem_map_limit`: [Pokémon Legends: Z-A](../../dm/games/0100F43008C44000/README.md), [Pokémon Scarlet](../../dm/games/0100A3D008C5C000/README.md), [Pokémon Violet](../../dm/games/01008F6008C5E000/README.md), [Xenoblade Chronicles 3](../../dm/games/010074F013262000/README.md) | Horizon's limit; off by default because Ace Attorney Investigations Collection maps a little more than its profile's 1 GB pool, which is the thing to fix | | `game` → `host` | buffer-texture handles indexed through c2's tables | shaders | gap | judgement | 3 | `tex_dyn_slots`: [FINAL FANTASY RESONANCE](../../dm/games/0100606026F12000/README.md), [FINAL FANTASY RESONANCE (Asian release)](../../dm/games/0100B8A026F14000/README.md), [OCTOPATH TRAVELER 0](../../dm/games/01005270232F2000/README.md) | right only where the handle comes from c2's tables: the translator could prove that per shader | | `game` → `host` | timestamp reports per segment | rendering | gap | judgement | 3 | `gpu_timestamps`: [NieR:Automata The End of YoRHa Edition (010056B015FE8000)](../../dm/games/010056B015FE8000/README.md), [NieR:Automata The End of YoRHa Edition (0100B8E016F76000)](../../dm/games/0100B8E016F76000/README.md), [The Legend of Zelda: Breath of the Wild](../../dm/games/01007EF00011E000/README.md) | what hardware records: a default for every game after `regress.py check` on the games | +| `game` → `host` | Metal encoding on its own thread on the Mac | frame rate | gap | judgement | 2 | `enc_thread`: [Need For Speed™ Hot Pursuit Remastered](../../dm/games/010029B0118E8000/README.md), [The Legend of Zelda: Breath of the Wild](../../dm/games/01007EF00011E000/README.md) | what iOS does for every game: a default for every game after `regress.py check` on the games | | `build` → `game` | 60 fps intervals and dynamic-resolution constants | frame rate | gap | checked: both releases' mains, where the host's rows for them were found | 2 | [NieR:Automata The End of YoRHa Edition (010056B015FE8000)](../../dm/games/010056B015FE8000/README.md); [NieR:Automata The End of YoRHa Edition (0100B8E016F76000)](../../dm/games/0100B8E016F76000/README.md) | the game's own constants; the Asian release's function is the global one's 0x13c0 further on, so one function-matched rule could serve both releases | | `build` → `game` | NieR's frame interval and dynamic-resolution floor at fixed addresses | frame rate | gap | checked: both releases' mains, where these rows were found | 2 | [NieR:Automata The End of YoRHa Edition (010056B015FE8000)](../../dm/games/010056B015FE8000/README.md); [NieR:Automata The End of YoRHa Edition (0100B8E016F76000)](../../dm/games/0100B8E016F76000/README.md) | the game's own display object; the Asian release's function is the global one's 0x13c0 further on, so the rewriter's function match could give the host both releases' addresses | | `build` → `game` | Snowdrop three-pool allocator: 12 GB of ranges → 3 GB | address space | gap | checked: both games' functions compared by fingerprint and disassembly, 2026-10-29 | 2 | [Mario + Rabbids Kingdom Battle](../../dm/games/010067300059A000/README.md); [Mario + Rabbids® Sparks of Hope](../../dm/games/0100317013770000/README.md) | Mario + Rabbids Kingdom Battle and Sparks of Hope build the same source routine differently: 44% of the instructions alike, fields 8 bytes apart, every callee different, other cut offsets and bytes (checked 2026-10-29), so no Snowdrop rule; a function-matched rule could carry it over the game's updates. The cause, an iPhone's address space, is a platform limit | | `build` → `host` | frame limiter wait: yield → sleep | power | gap | checked: Mac runs with the cut undone, 2026-10-26 (the game note) | 1 | [Fire Emblem: Three Houses](../../dm/games/010055D009F78000/README.md) | without it the host's yield back-off (thr_yield) holds 59.7 to 59.8 fps, at 0.9 to 1.2 W of CPU against 0.14 to 0.42 W (2026-10-26): a back-off that reaches a yield-and-tick loop's deadline sooner would make the cut unnecessary for every game | | `game` → `host` | CPU vertex conversion over the vertices a draw reads | power | gap | judgement | 1 | `vconv_range`: [Hyrule Warriors: Age of Calamity](../../dm/games/01002B00111A2000/README.md) | the same vertices as the whole range, for less work; DM_NVN_VCONV_CHECK checks it: a default for every game after `regress.py check` on the games | -| `game` → `host` | Metal encoding on its own thread on the Mac | frame rate | gap | judgement | 1 | `enc_thread`: [Need For Speed™ Hot Pursuit Remastered](../../dm/games/010029B0118E8000/README.md) | what iOS does for every game: a default for every game after `regress.py check` on the games | | `game` → `host` | MTL4Compiler pipelines on iOS | rendering | gap | judgement | 1 | `pso_mtl4`: [The Legend of Zelda: Breath of the Wild](../../dm/games/01007EF00011E000/README.md) | a setting the game was tested with on an iPhone: a default for every game after `regress.py check` on the games | | `game` → `host` | one vertex shader's visibility counter (VertexCounterLowering) | shaders | gap | judgement | — | [Program.cs:229](../../dm/gfx/tools/dmsh_xlate/Program.cs#L229) | a general lowering of subgroup ballots in vertex shaders would cover any shader that counts that way | | `game` → `host` | present snapshots | rendering | gap | judgement | 1 | `present_snap`: [The Legend of Zelda: Breath of the Wild](../../dm/games/01007EF00011E000/README.md) | a setting the game was tested with: a default for every game after `regress.py check` on the games | @@ -619,7 +619,6 @@ Profile keys (`game.tsv`) whose value changes what the host does, set away from | Key and value | Games | Binding | Why | |---|---|---|---| -| `enc_thread on` | [Need For Speed™ Hot Pursuit Remastered](../../dm/games/010029B0118E8000/README.md) | `game` → `host`, gap | what iOS does for every game: a default for every game after `regress.py check` on the games | | `game_env DOTNET_GCRegionRange=60000000` | [Absolum](../../dm/games/0100A83022A22000/README.md) | `game`, at goal | measured for the game's regions | | `present_snap on` | [The Legend of Zelda: Breath of the Wild](../../dm/games/01007EF00011E000/README.md) | `game` → `host`, gap | a setting the game was tested with: a default for every game after `regress.py check` on the games | | `pso_mtl4 on` | [The Legend of Zelda: Breath of the Wild](../../dm/games/01007EF00011E000/README.md) | `game` → `host`, gap | a setting the game was tested with on an iPhone: a default for every game after `regress.py check` on the games | @@ -629,6 +628,7 @@ Profile keys (`game.tsv`) whose value changes what the host does, set away from | `ue_fps_cvar Project.FrameRateLimit` | [SHIN MEGAMI TENSEI V: Vengeance](../../dm/games/010069C01AB82000/README.md) | `game`, at goal | the game's own variable, which its settings apply to t.MaxFPS; the rewriter finds it by name (ue_cvar.py) | | `ue_texture_pool 1000` | [DRAGON QUEST VII Reimagined](../../dm/games/0100A9D01C446000/README.md) | `game`, at goal | the game's own budget, raised to its Windows value | | `vconv_range on` | [Hyrule Warriors: Age of Calamity](../../dm/games/01002B00111A2000/README.md) | `game` → `host`, gap | the same vertices as the whole range, for less work; DM_NVN_VCONV_CHECK checks it: a default for every game after `regress.py check` on the games | +| `enc_thread on` | [Need For Speed™ Hot Pursuit Remastered](../../dm/games/010029B0118E8000/README.md), [The Legend of Zelda: Breath of the Wild](../../dm/games/01007EF00011E000/README.md) | `game` → `host`, gap | what iOS does for every game: a default for every game after `regress.py check` on the games | | `fps_hold off` | [Hyrule Warriors: Age of Calamity](../../dm/games/01002B00111A2000/README.md), [Paper Mario: The Thousand-Year Door](../../dm/games/0100ECD018EBE000/README.md) | `game`, at goal | the game's pacing | | `perf_mode boost` | [Big Brain Academy: Brain vs. Brain](../../dm/games/0100620012D6E000/README.md), [Rhythm Heaven Groove](../../dm/games/0100D9F01D474000/README.md) | `game`, at goal | a combination a Switch 1 never reports: a choice per game | | `gpu_timestamps segment` | [NieR:Automata The End of YoRHa Edition (010056B015FE8000)](../../dm/games/010056B015FE8000/README.md), [NieR:Automata The End of YoRHa Edition (0100B8E016F76000)](../../dm/games/0100B8E016F76000/README.md), [The Legend of Zelda: Breath of the Wild](../../dm/games/01007EF00011E000/README.md) | `game` → `host`, gap | what hardware records: a default for every game after `regress.py check` on the games | From 4c381fcbb37c043d1a4e8236124c2b432d6f6638 Mon Sep 17 00:00:00 2001 From: Paolo Moretti Date: Sun, 1 Nov 2026 15:20:13 +0700 Subject: [PATCH 4/5] Present: MetalFX scales the picture at the snapshot, so the present on the game's queue only draws it MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The present command buffer ran the MetalFX spatial scaler (1920x1080 → the fullscreen canvas) on the game's queue at each display-link tick, inside or right after the frame's segments: about 2.6 ms of GPU time a frame at the low clock macOS keeps for Breath of the Wild, which took frames from about 15 to 17–18 ms (48–56 fps). With present snapshots, snap_take now scales the presented rectangle into an upscaled texture of the slot, in the snapshot's command buffer right after the frame's last segment, and the present draws it 1:1 (0.3–0.5 ms). A canvas size or format change remakes the scaler and the slot's texture (the old one stays resident until the slot's next use), and any mismatch takes the old path for that frame. DM_PRESENT_FX_AT_SNAP=0 restores it, ab compares both; DM_PRESENT_UPSCALE takes ab too. @present_gpu_ms and @snap_gpu_ms give both command buffers' GPU time per frame. M5 Pro run, the two placements switched every 30 s: the present 2.58–2.66 → 0.34–0.52 ms; the user reports a cleaner picture. t_present_snap fxsnap (both encode modes, Metal validation): exact scaled pictures, a refused resized or reformatted canvas, a canvas change remaking the scaler, residency of the replaced textures. --- dm/games/01007EF00011E000/README.md | 2 + dm/gfx/nvn/hle_nvn.c | 2 + dm/gfx/nvn/nvn_mtl.m | 239 +++++++++++++++++++++------- dm/gfx/tests/Makefile | 2 + dm/gfx/tests/t_present_snap.m | 82 ++++++++-- dm/tools/lint_c_baseline.tsv | 1 - docs/agents/symptoms.md | 1 + docs/env_switches.tsv | 3 +- docs/reference/frame-rate.md | 7 + 9 files changed, 265 insertions(+), 74 deletions(-) diff --git a/dm/games/01007EF00011E000/README.md b/dm/games/01007EF00011E000/README.md index 312e096549..048d655583 100644 --- a/dm/games/01007EF00011E000/README.md +++ b/dm/games/01007EF00011E000/README.md @@ -69,6 +69,7 @@ Used at `DM_FPS_TARGET=0` and for the interval the framework keeps while the VFR - Same-pass feedback: over a thousand draws a frame sample the G-buffer of their own pass (`4d3d5a4408c2e8d9`, `753d0169ae3ce4f0` and others on the 1600×900 G-buffer), and outdoors about 460 of them also write the target they sample (decals reading and blending the normals). A fresh snapshot for each (`DM_NVN_FB_SNAP=all`) takes the Mac's GPU time from about 4 to 28 ms a frame; none has shown magenta blocks on the iPhone so far. The host now snapshots only draws that write what they sample and reuses a snapshot until the game's next barrier: about ten snapshots a frame, each reused by about 50 draws, GPU time within the runs' noise of no snapshots (3.7–4.5 against 3.5–4.1 ms p50, four runs each on the Apple M6). See [Same-pass feedback read through a snapshot](../../../docs/reference/rendering.md#same-pass-feedback-read-through-a-snapshot). - **Shrines at 20–27 fps (GitHub issues #534 and #598; current, the fix not yet seen in a shrine).** The reporters' shrines (Oman Au on a MacBook Air M2; every shrine on an M3) run at 20–27 fps where the open world holds 60. In the #598 log the slow stretches have about 1,000 draws a frame, as the fast ones, but a GPU time of about 36 ms against 9–13 ms. They have about 240 `passes ended to land them for a read` a frame, all `refused … other GPU writes`, and 280–330 `load-all store-all passes` against about 100. The probe on the Shrine of Resurrection save found the one write behind that refusal there: the GPU particle dispatch `9f8116baffddaf81` binds its three outputs with size 0, which counted as a write anywhere ([A storage buffer bound with size 0 counted as a write anywhere](../../../docs/reference/rendering.md#a-storage-buffer-bound-with-size-0-counted-as-a-write-anywhere)). With the fix, that save's world-load burst (1,200 refusals) is gone. Opening Oman Au's final gate ends the slowdown even out of view (#534): an emitter that stops with the gate would fit, but no shrine save was here to show it. +- **The MetalFX present inside the frame (resolved, 2026-11-01; M5 Pro, fullscreen, snapshots, encode thread).** With the probe fix every probe held (11 in a row), but 320–460 s of the 470 s run ran at 48–56 fps at hold 1: frames 17–19 ms, the frame's own GPU 12.5–13.5 ms (14.7–16 on the cube-map frames every tenth), clock 340–380 MHz, GPU powered 97–99%, `@sync_ms` 0 or 9–12 ms by turns (the game reaches its fence wait before or after the GPU's end), the GPU idle 2.7–5.6 ms between frames and 1–4 ms inside the frame's span. The idle inside the span is the present: MetalFX's 1920x1080 → 3456x1944 scaler costs 2.6 ms a present at the floor clock (1 ms at 850 MHz) on the game's queue, so GPU 13 + present 2.6 + the chain's own idle about 2 ms = 17.8 ms: [The MetalFX present runs on the game's queue, inside its frame](../../../docs/reference/frame-rate.md#the-metalfx-present-runs-on-the-games-queue-inside-its-frame). The game's dynamic resolution does not react: it scales down only above 175% of a 60 Hz frame (29 ms) and back up below 150%, thresholds of its 30 fps design; at the host's step 1 a 13–16 ms GPU time never reaches them (and on the Mac the GPU time did not change with the scale: the frame is pass-bound). Each 30 fps spike was a step up after three frames late on screen at cost 0.83, then a probe that held after 35 frames. The earlier 60–80 s drop (probes 3834/3929/4083 failed) was in a DM_AB phase with the probe rule off. Encode thread on: present-thread CPU 5.9 → 3.4–4.4 ms, the submit 6.6 → 5.0 ms; now the profile's default (`enc_thread on`). The scaler now runs at the snapshot, in the gap after the frame's last segment (`DM_PRESENT_FX_AT_SNAP`, the reference entry). A 560 s run with `DM_AB=1800 DM_PRESENT_FX_AT_SNAP=ab` (2026-11-01): the present command buffer 2.6 → 0.34–0.52 ms and the snapshot's 0.11 → 2.35 ms per frame (`@present_gpu_ms` / `@snap_gpu_ms`), the GPU idle inside the frame's span 0 in both; at 60 fps with the frame fitting (phases 1–9, GPU 5–11 ms) frame p50 16.67–16.71 / p90 17.1–17.5 ms in both placements, and the heavy phases (GPU 12 ms, 3,400–3,650 draws) came after 320 s, when that run lost one frame in 5.5 to the display link in both placements (the next bullet), so the placement's frame-time gain in a GPU-bound scene is still to be seen (open). The user judged the picture better too. - **Present snapshots (Mac).** The game's two swapchain textures held its CPU work to display ticks and the GPU at 444 MHz on an M2 Max ([present snapshots](../../../docs/reference/frame-rate.md#present-snapshots-the-games-swapchain-texture-free-at-once)). Judged by cost, the frame step stepped to 30 at a GPU time of 0.75 vsyncs. Zora's Domain from a Cemu save (120 Hz), frames on screen longer than 1/60 s by a quarter: 64 of 8,684 with neither, 41 with the GPU filler alone, 4 of 10,800 with snapshots alone (no step to 30 in 3 minutes, at 444 MHz throughout). ## Rendering @@ -201,6 +202,7 @@ Before publishing, the fixes were integrated with main's pipeline archive and GP - **Resolved, parallel rewriting (2026-10-31):** [Parallel scans preserve rewrite output](../../../docs/reference/rewriter.md#parallel-scans-preserve-rewrite-output). All 21 binary and TSV outputs of the three modules of v1114112 are byte-identical to the sequential rewriter. The full regression against `635e8008` passed: zero red diagnostics, matching screenshots, and no frame-time or memory regression (M4 Pro, Xcode 27.2 with the per-run compiler override on both revisions). - [Benchmark captures perturb the measured frame pacing](../../../docs/reference/frame-rate.md#benchmark-captures-perturb-the-measured-frame-pacing). - **Resolved, the Mac's GPU clock at its floor at 30 fps in heavy scenes:** [A probe's grace lasts while its frames keep getting cheaper](../../../docs/reference/frame-rate.md#a-probes-grace-lasts-while-its-frames-keep-getting-cheaper). +- **Resolved, MetalFX's present cost inside the frame:** [The MetalFX present runs on the game's queue, inside its frame](../../../docs/reference/frame-rate.md#the-metalfx-present-runs-on-the-games-queue-inside-its-frame). - **Resolved, two stale chain folders held 4.4 GB:** [Old shader library folders grew a game's build folder with each chain change](../../../docs/reference/shaders.md#old-shader-library-folders-grew-a-games-build-folder-with-each-chain-change). - **Resolved: 1.6.0 (v786432) crashed 10-60 s into the first scene (issue #251)** in `h_nvnBufferGetAddress` (`main+0x14ef6e0`, reader `main+0x14ef440`) and in other places (`main+0x12970dc`, `+0x13615f4`, `+0x1445d48`, `+0x1db5cb8`, `+0x1472470`): the game's job queue (`main+0x13a0730`) takes its lock with a bare `ldxr` (no acquire), so on Apple cores two workers popped the same job, and two threads built draw lists into one view and arena (`main+0x14e8884` begin, commit `main+0x14ee3c0`). [Lock acquire without acquire ordering runs a queue item twice](../../../docs/reference/threads.md#lock-acquire-without-acquire-ordering-runs-a-queue-item-twice). - **Resolved build guard and cache isolation; rendering cause open:** [Tested tools and compiler-specific shader caches](../../../docs/reference/shaders.md#tested-tools-and-compiler-specific-shader-caches). diff --git a/dm/gfx/nvn/hle_nvn.c b/dm/gfx/nvn/hle_nvn.c index 691c20cba2..3ad101e494 100644 --- a/dm/gfx/nvn/hle_nvn.c +++ b/dm/gfx/nvn/hle_nvn.c @@ -2028,6 +2028,8 @@ NVN(nvnQueuePresentTexture, void, NVNqueue *q, NVNwindow *w, int idx) { // Actual presentation interval (windowed mode): taken 8 presents late (the presented callback has arrived by then), as the difference between the n-th and the (n−1)-th; −1 = discarded if (o->presents > 9) { uint64_t n = o->presents - 8; double a_ = mtl_presented_time(n), b_ = mtl_presented_time(n - 1); if (a_ < 0) trow(f - 8, "@presented_ms", -1); else if (a_ > 0 && b_ > 0) trow(f - 8, "@presented_ms", (a_ - b_) * 1e3); + { double mtl_present_gpu_ms(uint64_t), mtl_snap_gpu_ms(uint64_t); double pg = mtl_present_gpu_ms(n), sg = mtl_snap_gpu_ms(n); // the present command buffer's GPU time (MetalFX and the present pass) and the snapshot's (the copy and, at the snapshot, the scaler): both on the game's queue + if (pg > 0) trow(f - 8, "@present_gpu_ms", pg); if (sg > 0) trow(f - 8, "@snap_gpu_ms", sg); } g_pres_exp[g_presn % TWIN] = g_pres_exp_last = pres_expect_ms(n); g_pres_iv[g_presn++ % TWIN] = a_ < 0 ? -1 : (a_ > 0 && b_ > 0 ? (a_ - b_) * 1e3 : 0); { double iv_ = a_ < 0 ? -1 : (a_ > 0 && b_ > 0 ? (a_ - b_) * 1e3 : 0); mtl_ub_present(iv_); } // same-process alternating measurement (DM_NVN_UB) tallies on-screen present intervals per phase; when off it is just one atomic read diff --git a/dm/gfx/nvn/nvn_mtl.m b/dm/gfx/nvn/nvn_mtl.m index c7d0683b21..86e90dfb86 100644 --- a/dm/gfx/nvn/nvn_mtl.m +++ b/dm/gfx/nvn/nvn_mtl.m @@ -11131,7 +11131,8 @@ void mtl_res_counts(uint32_t tick, const char *why) { static struct { uint64_t frame; char path[1024]; } g_shotq[SHOTQ_MAX]; static int g_nshotq; static pthread_mutex_t g_shotq_mu = PTHREAD_MUTEX_INITIALIZER; static int present_encode(id cb, id src, id dst, const int crop[4]); -enum { PRESENT_FAILED, PRESENT_STANDARD, PRESENT_METALFX }; +enum { PRESENT_FAILED, PRESENT_STANDARD, PRESENT_METALFX, PRESENT_METALFX_SNAP }; // METALFX_SNAP: the picture was scaled at the snapshot (snap_take) and the present drew it 1:1 +static int present_draw_m4(id cb, id tex, const NSUInteger r[4], MTLViewport vp, id dst, id uvb, int full); static int present_offscreen_m4(id src, const int crop[4], id out, void (^done)(int)); static int present_offscreen_wait(id src, const int crop[4], id out); // Game picture needed by the whole-window screenshot (front end window_shot; no longer does drawViewHierarchy on a Metal layer with the display link attached): at the next present, the present thread draws the same frame @@ -11514,66 +11515,97 @@ static int present_encode(id cb, id src, id sc; id in, out; uint64_t made_at; int made; NSUInteger refused[6]; } fx_state; +typedef struct { id sc; id in, out; NSUInteger ow, oh; MTLPixelFormat out_pf; uint64_t made_at; int made; NSUInteger refused[6]; } fx_state; // ow, oh, out_pf: the scaler's output size and format (out is nil for the snapshot scaler) static fx_state g_fx_present; // only the present thread encodes or replaces the scaler +static fx_state g_fx_snap; // the scaler of the snapshot path (snap_take, DM_PRESENT_FX_AT_SNAP): only the thread taking snapshots (the game's presenting thread) encodes or replaces it static id g_fx_comp; -static int g_fx_mode = -1; // 1 = metalfx, 0 = off +// The present through MetalFX costs GPU time on the game's queue, in order with its segments (present_now: 1920x1080 → 3456x1944 took 2.6 ms a present at an M5 Pro's 338 MHz +// floor clock, 1 ms at 850 MHz; Breath of the Wild's 13 ms frames then took 17–19 ms, docs/reference/frame-rate.md). DM_PRESENT_UPSCALE=ab (with DM_AB) alternates it with the +// bilinear pass per phase, so one run shows the cost (sw_mode; the [ab] line names PRESENT_UPSCALE). The decision is read per present (fx_on), on the display-link thread +static int g_fx_mode = -1; // 1 = metalfx, 0 = off, 2 + ... = ab (sw_mode) static int fx_mode(void) { if (g_fx_mode >= 0) return g_fx_mode; const char *e = getenv("DM_PRESENT_UPSCALE"); int v = 0; - if (e && (!strcmp(e, "metalfx") || !strcmp(e, "1"))) v = 1; + if (e && !strncmp(e, "ab", 2)) v = sw_mode("DM_PRESENT_UPSCALE", 0); + else if (e && (!strcmp(e, "metalfx") || !strcmp(e, "1"))) v = 1; else if (e && (!strcmp(e, "off") || !strcmp(e, "0"))) v = 0; - else if (e && *e) MLOG("[RED] DM_PRESENT_UPSCALE=%s: metalfx or off; keeping %s", e, v ? "metalfx" : "off"); + else if (e && *e) MLOG("[RED] DM_PRESENT_UPSCALE=%s: metalfx, off or ab; keeping %s", e, v ? "metalfx" : "off"); if (v && !(g_q4 && [MTLFXSpatialScalerDescriptor supportsMetal4FX:g_dev])) { MLOG("present upscaling: this GPU has no Metal 4 MetalFX spatial scaler; the present scales bilinearly"); v = 0; } - MLOG("present upscaling (DM_PRESENT_UPSCALE): %s", v ? "metalfx, MetalFX's spatial scaler where the picture is shown larger than the game renders it" : "off, bilinear"); + MLOG("present upscaling (DM_PRESENT_UPSCALE): %s", v == 1 ? "metalfx, MetalFX's spatial scaler where the picture is shown larger than the game renders it" : v ? "metalfx in the DM_AB phases that have it on, bilinear in the others" : "off, bilinear"); return g_fx_mode = v; } +static int fx_on(void) { return sw_on(fx_mode()); } +// The present command buffer's GPU time by the game's present number (hle_nvn.c @present_gpu_ms, 8 presents late like @presented_ms); written in the commit feedback under g_pq_mu +typedef struct { uint64_t n; float ms; } pres_gpu_ent; +static pres_gpu_ent g_pres_gpu[PRING]; +double mtl_present_gpu_ms(uint64_t n) { pthread_mutex_lock(&g_pq_mu); pres_gpu_ent e = g_pres_gpu[n % PRING]; pthread_mutex_unlock(&g_pq_mu); return e.n == n ? e.ms : 0; } // MetalFX scales the content (cw x ch) to its rectangle on the canvas (vp) when the rectangle is at least as large in both directions and larger in one static int fx_wanted(MTLViewport vp, NSUInteger cw, NSUInteger ch) { NSUInteger w = (NSUInteger)vp.width, h = (NSUInteger)vp.height; return cw && ch && w >= cw && h >= ch && (w > cw || h > ch); } // Encodes the upscale of the rectangle r of raw into cb (see above); returns the scaled picture, which the present pass draws 1:1 into vp, or nil (the bilinear pass). -// remake_wait: fx is the present thread's, whose textures presents still on the GPU may read: a new scaler waits for them and for FX_REMAKE_PRESENTS presents since the last -static id fx_encode(fx_state *fx, id cb, id raw, const NSUInteger r[4], MTLViewport vp, MTLPixelFormat out_pf, int remake_wait) { - NSUInteger cw = r[2], ch = r[3], ow = (NSUInteger)vp.width, oh = (NSUInteger)vp.height; - if (fx_mode() != 1 || !fx_wanted(vp, cw, ch)) return nil; - if (!fx->sc || fx->in.width != cw || fx->in.height != ch || fx->in.pixelFormat != raw.pixelFormat || fx->out.width != ow || fx->out.height != oh || fx->out.pixelFormat != out_pf) { - NSUInteger key[6] = {cw, ch, raw.pixelFormat, ow, oh, out_pf}; - if (!memcmp(key, fx->refused, sizeof key)) return nil; - if (remake_wait && fx->made && g_present_n < fx->made_at + FX_REMAKE_PRESENTS) return nil; - if (remake_wait) { pthread_mutex_lock(&g_pq_mu); while (g_pq_inflight) pthread_cond_wait(&g_pq_cv, &g_pq_mu); pthread_mutex_unlock(&g_pq_mu); } - res_remove(fx->in); res_remove(fx->out); fx->sc = nil; fx->in = fx->out = nil; - uint64_t t0 = now_ns(); NSError *e = nil; - if (!g_fx_comp) g_fx_comp = [g_dev newCompilerWithDescriptor:[MTL4CompilerDescriptor new] error:&e]; - MTLFXSpatialScalerDescriptor *d = [MTLFXSpatialScalerDescriptor new]; - d.colorTextureFormat = raw.pixelFormat; d.outputTextureFormat = out_pf; d.inputWidth = cw; d.inputHeight = ch; d.outputWidth = ow; d.outputHeight = oh; - d.colorProcessingMode = MTLFXSpatialScalerColorProcessingModePerceptual; - id sc = g_fx_comp ? [d newSpatialScalerWithDevice:g_dev compiler:g_fx_comp] : nil; - fx->made_at = g_present_n; fx->made++; - if (!sc) { memcpy(fx->refused, key, sizeof key); - MLOG("present upscaling: MetalFX makes no spatial scaler for %lux%lu format %lu → %lux%lu format %lu%s; this size is scaled bilinearly", (unsigned long)cw, (unsigned long)ch, (unsigned long)raw.pixelFormat, - (unsigned long)ow, (unsigned long)oh, (unsigned long)out_pf, g_fx_comp ? "" : " (no Metal 4 compiler)"); return nil; } - MTLTextureDescriptor *td = [MTLTextureDescriptor texture2DDescriptorWithPixelFormat:raw.pixelFormat width:cw height:ch mipmapped:NO]; - td.storageMode = MTLStorageModePrivate; td.usage = sc.colorTextureUsage | MTLTextureUsageShaderRead; - id in = [g_dev newTextureWithDescriptor:td]; +// The scaler for cw x ch (in_pf) → ow x oh (out_pf), made or remade as needed; returns whether fx->sc can be used. own_out: the state keeps an output texture of its own (the present's +// scaler; the snapshot scaler writes into each ring slot's texture, fx_run's out). The present's state (fx == &g_fx_present) remakes only after FX_REMAKE_PRESENTS presents and +// once no present is in flight (its textures may be read by queued presents); the snapshot state (g_fx_snap) once every snapshot command buffer committed so far has run +static int snap_drain_try(uint64_t ms); +static int fx_prepare(fx_state *fx, NSUInteger cw, NSUInteger ch, MTLPixelFormat in_pf, NSUInteger ow, NSUInteger oh, MTLPixelFormat out_pf, int own_out) { + int present = fx == &g_fx_present; + if (fx->sc && fx->in.width == cw && fx->in.height == ch && fx->in.pixelFormat == in_pf && fx->ow == ow && fx->oh == oh && fx->out_pf == out_pf) return 1; + NSUInteger key[6] = {cw, ch, in_pf, ow, oh, out_pf}; + if (!memcmp(key, fx->refused, sizeof key)) return 0; + if (present && fx->made && g_present_n < fx->made_at + FX_REMAKE_PRESENTS) return 0; + if (present) { pthread_mutex_lock(&g_pq_mu); while (g_pq_inflight) pthread_cond_wait(&g_pq_cv, &g_pq_mu); pthread_mutex_unlock(&g_pq_mu); } + else if (fx->sc && !snap_drain_try(200)) return 0; // snapshot command buffers queued so far read fx->in; a queue that does not run them within 200 ms (a present waiting for a drawable ahead of them) keeps the scaler and this snapshot takes the old path. This blocks the game's presenting thread up to 200 ms, only when the canvas or output size changes + res_remove(fx->in); res_remove(fx->out); fx->sc = nil; fx->in = fx->out = nil; + uint64_t t0 = now_ns(); NSError *e = nil; + if (!g_fx_comp) g_fx_comp = [g_dev newCompilerWithDescriptor:[MTL4CompilerDescriptor new] error:&e]; + MTLFXSpatialScalerDescriptor *d = [MTLFXSpatialScalerDescriptor new]; + d.colorTextureFormat = in_pf; d.outputTextureFormat = out_pf; d.inputWidth = cw; d.inputHeight = ch; d.outputWidth = ow; d.outputHeight = oh; + d.colorProcessingMode = MTLFXSpatialScalerColorProcessingModePerceptual; + id sc = g_fx_comp ? [d newSpatialScalerWithDevice:g_dev compiler:g_fx_comp] : nil; + fx->made_at = g_present_n; fx->made++; + if (!sc) { memcpy(fx->refused, key, sizeof key); + MLOG("present upscaling: MetalFX makes no spatial scaler for %lux%lu format %lu → %lux%lu format %lu%s; this size is scaled bilinearly", (unsigned long)cw, (unsigned long)ch, (unsigned long)in_pf, + (unsigned long)ow, (unsigned long)oh, (unsigned long)out_pf, g_fx_comp ? "" : " (no Metal 4 compiler)"); return 0; } + MTLTextureDescriptor *td = [MTLTextureDescriptor texture2DDescriptorWithPixelFormat:in_pf width:cw height:ch mipmapped:NO]; + td.storageMode = MTLStorageModePrivate; td.usage = sc.colorTextureUsage | MTLTextureUsageShaderRead; + id in = [g_dev newTextureWithDescriptor:td], out = nil; + if (own_out) { td = [MTLTextureDescriptor texture2DDescriptorWithPixelFormat:out_pf width:ow height:oh mipmapped:NO]; td.storageMode = MTLStorageModePrivate; td.usage = sc.outputTextureUsage | MTLTextureUsageShaderRead; - id out = [g_dev newTextureWithDescriptor:td]; - if (!in || !out) { memcpy(fx->refused, key, sizeof key); MLOG("[RED] present upscaling: cannot create the scaler's textures (%lux%lu, %lux%lu)", (unsigned long)cw, (unsigned long)ch, (unsigned long)ow, (unsigned long)oh); return nil; } - in.label = @"present upscale input"; out.label = @"present upscale output"; - res_add(in); res_add(out); res_commit(); - fx->sc = sc; fx->in = in; fx->out = out; - MLOG("present upscaling: MetalFX spatial scaler %lux%lu → %lux%lu (format %lu → %lu, scaler #%d, made in %.1f ms)", (unsigned long)cw, (unsigned long)ch, (unsigned long)ow, (unsigned long)oh, - (unsigned long)raw.pixelFormat, (unsigned long)out_pf, fx->made, (now_ns() - t0) / 1e6); - } + out = [g_dev newTextureWithDescriptor:td]; + } + if (!in || (own_out && !out)) { memcpy(fx->refused, key, sizeof key); MLOG("[RED] present upscaling: cannot create the scaler's textures (%lux%lu, %lux%lu)", (unsigned long)cw, (unsigned long)ch, (unsigned long)ow, (unsigned long)oh); return 0; } + in.label = present ? @"present upscale input" : @"snapshot upscale input"; out.label = @"present upscale output"; + res_add(in); if (out) res_add(out); res_commit(); + fx->sc = sc; fx->in = in; fx->out = out; fx->ow = ow; fx->oh = oh; fx->out_pf = out_pf; + MLOG("present upscaling: MetalFX spatial scaler %lux%lu → %lux%lu (format %lu → %lu, %s scaler #%d, made in %.1f ms)", (unsigned long)cw, (unsigned long)ch, (unsigned long)ow, (unsigned long)oh, + (unsigned long)in_pf, (unsigned long)out_pf, present ? "present" : "snapshot", fx->made, (now_ns() - t0) / 1e6); + return 1; +} +// The texture a ring slot's scaled picture takes (the snapshot scaler's output: its usage), ow x oh of out_pf +static id fx_out_texture(const fx_state *fx, NSUInteger ow, NSUInteger oh, MTLPixelFormat out_pf) { + MTLTextureDescriptor *td = [MTLTextureDescriptor texture2DDescriptorWithPixelFormat:out_pf width:ow height:oh mipmapped:NO]; + td.storageMode = MTLStorageModePrivate; td.usage = fx->sc.outputTextureUsage | MTLTextureUsageShaderRead; + return [g_dev newTextureWithDescriptor:td]; +} +// Encodes the scaler: raw's rectangle r copied into the scaler's input, scaled into out (nil = the state's own) +static void fx_run(fx_state *fx, id cb, id raw, const NSUInteger r[4], id out) { + NSUInteger cw = r[2], ch = r[3]; id ce = [cb computeCommandEncoder]; [ce barrierAfterQueueStages:MTLStageAll beforeStages:MTLStageBlit visibilityOptions:resource_vis()]; // after the frame's work [ce copyFromTexture:raw sourceSlice:0 sourceLevel:0 sourceOrigin:MTLOriginMake(r[0], r[1], 0) sourceSize:MTLSizeMake(cw, ch, 1) toTexture:fx->in destinationSlice:0 destinationLevel:0 destinationOrigin:MTLOriginMake(0, 0, 0)]; [ce barrierAfterStages:MTLStageBlit beforeQueueStages:MTLStageAll visibilityOptions:resource_vis()]; // the scaler's encoders come after the copy [ce endEncoding]; - fx->sc.colorTexture = fx->in; fx->sc.inputContentWidth = cw; fx->sc.inputContentHeight = ch; fx->sc.outputTexture = fx->out; + fx->sc.colorTexture = fx->in; fx->sc.inputContentWidth = cw; fx->sc.inputContentHeight = ch; fx->sc.outputTexture = out ? out : fx->out; [fx->sc encodeToCommandBuffer:cb]; +} +static id fx_encode(fx_state *fx, id cb, id raw, const NSUInteger r[4], MTLViewport vp, MTLPixelFormat out_pf) { + NSUInteger cw = r[2], ch = r[3], ow = (NSUInteger)vp.width, oh = (NSUInteger)vp.height; + if (!fx_on() || !fx_wanted(vp, cw, ch)) return nil; + if (!fx_prepare(fx, cw, ch, raw.pixelFormat, ow, oh, out_pf, 1)) return nil; + fx_run(fx, cb, raw, r, nil); return fx->out; } // The present pass: src's valid rectangle drawn into dst (the drawable, or a screenshot's texture) as present_encode draws it, through MetalFX first where fx_encode takes it @@ -11584,8 +11616,13 @@ static int present_encode_m4(id cb, id src, id tex = present_raw_src(src), up = fx ? fx_encode(fx, cb, tex, r, vp, dst.pixelFormat, fx == &g_fx_present) : nil; + id tex = present_raw_src(src), up = fx ? fx_encode(fx, cb, tex, r, vp, dst.pixelFormat) : nil; if (up) { tex = up; r[0] = r[1] = 0; r[2] = up.width; r[3] = up.height; } // the scaled picture, the viewport's size: drawn 1:1 + if (!present_draw_m4(cb, tex, r, vp, dst, uvb, full)) return 0; + return up ? PRESENT_METALFX : PRESENT_STANDARD; +} +// The present pass itself: tex's rectangle r drawn into vp of dst (full: vp covers dst). A ring slot's picture scaled at the snapshot (snap_take) is drawn through this alone, 1:1 +static int present_draw_m4(id cb, id tex, const NSUInteger r[4], MTLViewport vp, id dst, id uvb, int full) { MTL4RenderPassDescriptor *rp = [MTL4RenderPassDescriptor new]; rp.colorAttachments[0].texture = dst; rp.colorAttachments[0].loadAction = full ? MTLLoadActionDontCare : MTLLoadActionClear; @@ -11600,12 +11637,12 @@ static int present_encode_m4(id cb, id src, id src, const int crop[4], id 0 && s < 1)) return; +static void present_gpu_note(double s, int fx) { // fx: 0 bilinear, 1 MetalFX in the present, 2 a snapshot scaled by MetalFX at snap_take, drawn 1:1 + static double v[3][600]; static int n[3]; + static const char *const how[3] = {"through the bilinear pass", "through MetalFX", "of a snapshot scaled by MetalFX at the snapshot"}; + if (!(s > 0 && s < 1) || fx < 0 || fx > 2) return; v[fx][n[fx]++] = s * 1e3; if (n[fx] < 600) return; double *a = v[fx]; for (int i = 1; i < 600; i++) { double x = a[i]; int j = i - 1; while (j >= 0 && a[j] > x) { a[j + 1] = a[j]; j--; } a[j + 1] = x; } - MLOG("present command buffer GPU time over 600 presents %s: p50 %.3f ms, p95 %.3f ms, max %.3f ms", fx ? "through MetalFX" : "through the bilinear pass", a[299], a[569], a[599]); + MLOG("present command buffer GPU time over 600 presents %s: p50 %.3f ms, p95 %.3f ms, max %.3f ms", how[fx], a[299], a[569], a[599]); n[fx] = 0; } static double g_link_it_tin; // Enqueue time of the frame the display-link callback is presenting (read and written only on the display-link thread) -static int present_now(const tex_t *t, double period, uint64_t frame, uint64_t ticket, const int crop[4], id supplied, double target_ts) { +static int snap_up_for(int slot, uint64_t gen, NSUInteger dw, NSUInteger dh, MTLPixelFormat pf, id *up, MTLViewport *vp); // the snapshot ring (below) +static void snap_up_stale(int slot, uint64_t gen); +static int present_now(const tex_t *t, double period, uint64_t frame, uint64_t ticket, const int crop[4], id supplied, double target_ts, int up_slot, uint64_t up_gen) { if (g_present_stall_ns) { struct timespec ts = {0, (long)g_present_stall_ns}; nanosleep(&ts, NULL); } g_present_n++; if (bootprof() && (g_present_n == 1 || g_present_n % 120 == 0)) { @@ -11723,15 +11763,24 @@ static int present_now(const tex_t *t, double period, uint64_t frame, uint64_t t [g_q4 waitForDrawable:dr]; id cb = g_present_cb[alloc_i]; [cb beginCommandBufferWithAllocator:g_present_alloc4[alloc_i]]; - int kind = present_encode_m4(cb, src, dr.texture, crop, g_present_uv[alloc_i], &g_fx_present); + int kind; id up = nil; MTLViewport upvp; + if (snap_up_for(up_slot, up_gen, dr.texture.width, dr.texture.height, dr.texture.pixelFormat, &up, &upvp)) { // scaled at the snapshot (snap_take): drawn 1:1, no scaler here + NSUInteger r[4] = {0, 0, up.width, up.height}; present_pipeline(dr.texture.pixelFormat); + int full = upvp.originX == 0 && upvp.originY == 0 && (NSUInteger)upvp.width == dr.texture.width && (NSUInteger)upvp.height == dr.texture.height; + kind = present_draw_m4(cb, up, r, upvp, dr.texture, g_present_uv[alloc_i], full) ? PRESENT_METALFX_SNAP : 0; + } else { + snap_up_stale(up_slot, up_gen); // counts a picture scaled for another canvas: the present's own scaler this frame + kind = present_encode_m4(cb, src, dr.texture, crop, g_present_uv[alloc_i], &g_fx_present); + } if (!kind) { [cb endCommandBuffer]; [g_q4 signalDrawable:dr]; return 0; } - int fx_kind = kind == PRESENT_METALFX; + int fx_kind = kind == PRESENT_METALFX ? 1 : kind == PRESENT_METALFX_SNAP ? 2 : 0; [cb endCommandBuffer]; MTL4CommitOptions *o = [MTL4CommitOptions new]; [o addFeedbackHandler:^(id f) { if (f.error) MLOG("[RED] display command buffer error: %s", f.error.description.UTF8String); pthread_mutex_lock(&g_pq_mu); if (ticket > g_pq_done) g_pq_done = ticket; if (ticket > g_present_alloc_done[alloc_i]) g_present_alloc_done[alloc_i] = ticket; g_pq_inflight--; pthread_cond_broadcast(&g_pq_cv); - present_gpu_note(f.GPUEndTime - f.GPUStartTime, fx_kind); pthread_mutex_unlock(&g_pq_mu); + double pg = f.GPUEndTime - f.GPUStartTime; g_pres_gpu[ticket % PRING] = (pres_gpu_ent){ticket, pg > 0 && pg < 1 ? (float)(pg * 1e3) : 0}; + present_gpu_note(pg, fx_kind); pthread_mutex_unlock(&g_pq_mu); }]; id buffers[] = {cb}; pthread_mutex_lock(&g_pq_mu); g_pq_inflight++; pthread_mutex_unlock(&g_pq_mu); @@ -11775,14 +11824,14 @@ static int present_now(const tex_t *t, double period, uint64_t frame, uint64_t t // Swapchain texture return: before AcquireTexture gets a texture it waits for the ticket of that texture's previous present to be processed (mtl_present_wait), after which the commands the game draws into it // are necessarily ordered after that blit on the GPU queue. #define PQ 8 -typedef struct { tex_t t; double period; uint64_t frame; int crop[4]; double t_in; uint64_t ev_val, snap_v; } pq_item; // snap_v: the snapshot copy this present shows (snap_commit_wait) // t_in: the time the game handed this frame into the present queue (CACurrentMediaTime); ev_val: see g_ext_ev +typedef struct { tex_t t; double period; uint64_t frame; int crop[4]; double t_in; uint64_t ev_val, snap_v; int up_slot; uint64_t up_gen; } pq_item; // up_slot, up_gen: the ring slot and its snapshot count whose scaled picture this present may draw (snap_up_for; −1 none) // snap_v: the snapshot copy this present shows (snap_commit_wait) // t_in: the time the game handed this frame into the present queue (CACurrentMediaTime); ev_val: see g_ext_ev // External producer (the Vulkan layer, dm/gfx/vk) renders on its own queue and signals this event when a frame's rendering is done: the present of that frame waits for the value on g_q4 static id g_ext_ev; static void ext_wait(uint64_t v) { if (v && g_ext_ev) [g_q4 waitForEvent:g_ext_ev value:v]; } static void snap_commit_wait(uint64_t v); static pq_item g_pq[PQ]; static uint64_t g_pq_in; -static int present_now(const tex_t *, double, uint64_t, uint64_t, const int[4], id, double); +static int present_now(const tex_t *, double, uint64_t, uint64_t, const int[4], id, double, int, uint64_t); static double g_link_vperiod, g_link_vhalf; // virtual ticks (link_range): seconds per counted tick (0 = every callback is a tick) and half a refresh of the screen @interface NvMetalDisplayLinkDelegate : NSObject @@ -11848,7 +11897,7 @@ - (void)metalDisplayLink:(CAMetalDisplayLink *)link needsUpdate:(CAMetalDisplayL pthread_mutex_unlock(&g_pq_mu); int submitted; ext_wait(it.ev_val); snap_commit_wait(it.snap_v); - @autoreleasepool { submitted = present_now(&it.t, it.period, it.frame, ticket, it.crop, update.drawable, update.targetPresentationTimestamp); } + @autoreleasepool { submitted = present_now(&it.t, it.period, it.frame, ticket, it.crop, update.drawable, update.targetPresentationTimestamp, it.up_slot, it.up_gen); } g_link_hold_until = submitted && it.period > 0.025 ? update.targetPresentationTimestamp + it.period : 0; if (!submitted) { pthread_mutex_lock(&g_pq_mu); @@ -11971,7 +12020,7 @@ static void present_drop_for_suspend(void) { pthread_mutex_unlock(&g_pq_mu); int submitted; ext_wait(it.ev_val); snap_commit_wait(it.snap_v); - @autoreleasepool { submitted = present_now(&it.t, it.period, it.frame, ticket, it.crop, nil, 0); } + @autoreleasepool { submitted = present_now(&it.t, it.period, it.frame, ticket, it.crop, nil, 0, it.up_slot, it.up_gen); } pthread_mutex_lock(&g_pq_mu); g_classic_busy = 0; pthread_cond_broadcast(&g_pq_cv); pthread_mutex_unlock(&g_pq_mu); if (!submitted) { pthread_mutex_lock(&g_pq_mu); @@ -12018,7 +12067,39 @@ uint64_t mtl_present_ext(uint64_t serial, double period, void *ev, uint64_t ev_v // The ring's length is the number of frames the game may run ahead of the screen: DM_PRESENT_SNAP= (2 to SNAP_MAX; 1 = 2). Off by default; the iOS launcher's Frame buffering toggle enables it. #define SNAP_MAX 4 // old: the slot's texture before the presented size or format last changed, resident until the slot's next use (snap_take) -static struct { id tex, old; uint64_t serial; _Atomic uint64_t ticket, ev; } g_snap[SNAP_MAX]; +// up: the slot's picture scaled by MetalFX at the snapshot (DM_PRESENT_FX_AT_SNAP, default on: the scaler runs in the snapshot's command buffer, right after the frame's last segment, in the +// gap the game's own work leaves before the next frame's first segment, instead of in the present command buffer between the next frame's segments; present_now draws it 1:1), ow x oh of +// up_pf at (up_vx, up_vy) of a canvas up_dw x up_dh. up_gen counts the slot's snapshots; up_valid says the latest one scaled into up (a present whose canvas differs falls back to the +// slot's raw copy and the present's own scaler for that frame). old_up follows the rule of old +static struct { id tex, old; uint64_t serial; _Atomic uint64_t ticket, ev; + id up, old_up; uint64_t up_gen; int up_valid; NSUInteger up_dw, up_dh; double up_vx, up_vy; MTLPixelFormat up_pf; } g_snap[SNAP_MAX]; +static NSUInteger g_snap_canvas_test[2]; static MTLPixelFormat g_snap_canvas_test_pf; // tests (t_present_snap.m): the canvas of a layer the test has none of +static uint64_t g_snap_fx_fallback; // presents whose snapshot was scaled for another canvas (a resize between the snapshot and the present): drawn through the present's own scaler +// DM_PRESENT_FX_AT_SNAP=1 / 0 / ab (with DM_AB, read per snapshot): the MetalFX scaler runs at the snapshot copy instead of in the present. On by default on the Mac, +// where it was measured (Breath of the Wild); off by default on iOS until it is measured there +static int fx_at_snap_mode(void) { static int m = -1; if (m < 0) m = sw_mode("DM_PRESENT_FX_AT_SNAP", TARGET_OS_OSX ? 1 : 0); return m; } +static int fx_at_snap_on(void) { return sw_on(fx_at_snap_mode()); } +// The canvas a snapshot would be scaled for: the layer's drawable size and pixel format (read off the game's thread; present_now reads the same properties on the display-link thread) +static int snap_canvas(NSUInteger *dw, NSUInteger *dh, MTLPixelFormat *pf) { + if (g_snap_canvas_test[0]) { *dw = g_snap_canvas_test[0]; *dh = g_snap_canvas_test[1]; *pf = g_snap_canvas_test_pf; return 1; } + CAMetalLayer *layer = (__bridge CAMetalLayer *)front_metal_layer(); if (!layer) return 0; + CGSize s = layer.drawableSize; if (!(s.width >= 1 && s.height >= 1)) return 0; + *dw = (NSUInteger)s.width; *dh = (NSUInteger)s.height; *pf = layer.pixelFormat; return 1; +} +// The snapshot command buffer's GPU time (the copy and, with DM_PRESENT_FX_AT_SNAP, the scaler) by the game's present number: hle_nvn.c @snap_gpu_ms, 8 presents late like @presented_ms. +// The feedback knows the snapshot's version v; present_enqueue maps the ticket to it. Both under g_pq_mu +static struct { uint64_t v; float ms; } g_snap_gpu[PRING]; static uint64_t g_snap_v_of[PRING]; // by v; by ticket +double mtl_snap_gpu_ms(uint64_t n) { + pthread_mutex_lock(&g_pq_mu); uint64_t v = g_snap_v_of[n % PRING]; double ms = v && g_snap_gpu[v % PRING].v == v ? g_snap_gpu[v % PRING].ms : 0; pthread_mutex_unlock(&g_pq_mu); return ms; +} +// What present_now draws for a ring slot's snapshot: its scaled picture when this present's snapshot scaled one for this canvas (1: up and vp set), else 0 (the raw copy, scaled in the present) +static int snap_up_for(int slot, uint64_t gen, NSUInteger dw, NSUInteger dh, MTLPixelFormat pf, id *up, MTLViewport *vp) { + if (slot < 0 || slot >= SNAP_MAX || !g_snap[slot].up_valid || g_snap[slot].up_gen != gen || !g_snap[slot].up) return 0; + if (g_snap[slot].up_dw != dw || g_snap[slot].up_dh != dh || g_snap[slot].up_pf != pf) return 0; // the canvas changed since the snapshot (a resize, fullscreen): the old path for this frame + *up = g_snap[slot].up; *vp = (MTLViewport){g_snap[slot].up_vx, g_snap[slot].up_vy, (double)g_snap[slot].up.width, (double)g_snap[slot].up.height, 0, 1}; + return 1; +} +static void snap_up_stale(int slot, uint64_t gen) { if (slot >= 0 && slot < SNAP_MAX && g_snap[slot].up_valid && g_snap[slot].up_gen == gen) g_snap_fx_fallback++; } static id g_snap_alloc[SNAP_MAX]; static id g_snap_cb[SNAP_MAX]; static id g_snap_res; static id g_snap_ev; static uint64_t g_snap_v; static _Atomic uint64_t g_snap_next, g_snap_cmt; // g_snap_cmt: the last copy the encode thread has committed (its g_snap_v) @@ -12038,6 +12119,12 @@ static void snap_drain(void) { snap_commit_wait(v); if (![g_snap_ev waitUntilSignaledValue:v timeoutMS:10000]) MDIE("present snapshots: GPU did not drain within 10 s"); } +// The same with a bound: whether every snapshot command buffer committed so far ran within ms (the snapshot scaler's remake, fx_prepare) +static int snap_drain_try(uint64_t ms) { + uint64_t v = g_snap_v; if (!v) return 1; + snap_commit_wait(v); + return [g_snap_ev waitUntilSignaledValue:v timeoutMS:ms] ? 1 : 0; +} uint64_t mtl_snap_acquire_wait(void) { if (!mtl_snap_on() || atomic_load(&g_present_discard)) return 0; int k = (int)(atomic_load(&g_snap_next) % (uint64_t)g_snap_n); @@ -12053,14 +12140,15 @@ uint64_t mtl_snap_acquire_wait(void) { return ws_t0() - w0; } // Copy the presented texture into the next ring slot; returns the slot's serial (0 = no snapshot: the game's texture is presented as before) -static uint64_t snap_take(const tex_t *t) { +static uint64_t snap_take(const tex_t *t, const int crop[4]) { int k = (int)(atomic_load(&g_snap_next) % (uint64_t)g_snap_n); pthread_mutex_lock(&g_pq_mu); int busy = atomic_load(&g_snap[k].ticket) > g_pq_done; pthread_mutex_unlock(&g_pq_mu); uint64_t ev = atomic_load(&g_snap[k].ev); if (busy || (ev && g_snap_ev.signaledValue < ev)) return 0; // The texture this slot held before it was last replaced: every present that read it had been committed when the replacing copy was (the busy check then), and the queue - // signals g_snap_ev only after all work committed before the signal, so those presents have run and it can leave the residency set + // signals g_snap_ev only after all work committed before the signal, so those presents have run and it can leave the residency set. The slot's scaled picture (up) the same if (g_snap[k].old) { [g_snap_res removeAllocation:g_snap[k].old]; [g_snap_res commit]; g_snap[k].old = nil; } + if (g_snap[k].old_up) { [g_snap_res removeAllocation:g_snap[k].old_up]; [g_snap_res commit]; g_snap[k].old_up = nil; } id src = tex_mtl(t); if (!src) return 0; // The copy reads the source before present_now runs, so it needs the same commit as present_now: a window texture presented before any submission has used it was made just // now and is outside the committed residency set. DRAGON QUEST XI S presents three times before its first submission; on an A17 Pro the copy faulted silently (its command buffer @@ -12096,17 +12184,45 @@ static uint64_t snap_take(const tex_t *t) { [ce barrierAfterQueueStages:MTLStageAll beforeStages:MTLStageBlit visibilityOptions:resource_vis()]; // after the frame's work and the slot's last blit to the screen [ce copyFromTexture:src sourceSlice:0 sourceLevel:0 sourceOrigin:MTLOriginMake(0, 0, 0) sourceSize:MTLSizeMake(src.width, src.height, 1) toTexture:dst destinationSlice:0 destinationLevel:0 destinationOrigin:MTLOriginMake(0, 0, 0)]; [ce barrierAfterStages:MTLStageBlit beforeQueueStages:MTLStageAll visibilityOptions:resource_vis()]; // the game's next writes to its texture come after the copy - [ce endEncoding]; [cb endCommandBuffer]; + [ce endEncoding]; + // The scaled picture (DM_PRESENT_FX_AT_SNAP): the presented rectangle of the game's texture scaled by MetalFX into the slot's up, the size of its rectangle on the canvas, in this command + // buffer, so it runs right after the frame's work. The present then draws up 1:1 (snap_up_for) and no scaler runs between the next frame's segments. The raw copy above stays: the + // present falls back to it when the canvas has changed by then, and screenshots and the readback take it + g_snap[k].up_gen++; g_snap[k].up_valid = 0; + NSUInteger dw, dh, r[4]; MTLPixelFormat pf; + if (fx_at_snap_on() && fx_on() && snap_canvas(&dw, &dh, &pf) && present_crop_rect(src, crop, r)) { + id raw = present_raw_src(src); MTLViewport vp = present_viewport(r[2], r[3], dw, dh); NSUInteger ow = (NSUInteger)vp.width, oh = (NSUInteger)vp.height; + if (fx_wanted(vp, r[2], r[3]) && fx_prepare(&g_fx_snap, r[2], r[3], raw.pixelFormat, ow, oh, pf, 0)) { + if (g_snap[k].up && (g_snap[k].up.width != ow || g_snap[k].up.height != oh || g_snap[k].up.pixelFormat != pf)) { g_snap[k].old_up = g_snap[k].up; g_snap[k].up = nil; } // kept resident until the slot's next use, as old + if (!g_snap[k].up) { + id up = fx_out_texture(&g_fx_snap, ow, oh, pf); + if (up) { up.label = @"snapshot upscale output"; [g_snap_res addAllocation:up]; [g_snap_res commit]; g_snap[k].up = up; + MLOG("present snapshots: ring slot %d scaled picture %lux%lu format %lu (canvas %lux%lu)", k, (unsigned long)ow, (unsigned long)oh, (unsigned long)pf, (unsigned long)dw, (unsigned long)dh); } + else RED_ONCE(113, "present snapshots: no texture for the scaled picture; the present scales"); + } + if (g_snap[k].up) { + fx_run(&g_fx_snap, cb, raw, r, g_snap[k].up); + g_snap[k].up_valid = 1; g_snap[k].up_dw = dw; g_snap[k].up_dh = dh; g_snap[k].up_pf = pf; g_snap[k].up_vx = vp.originX; g_snap[k].up_vy = vp.originY; + } + } + } + [cb endCommandBuffer]; uint64_t v = ++g_snap_v; + MTL4CommitOptions *o = [MTL4CommitOptions new]; // the GPU time of the copy and the scaler, by v (mtl_snap_gpu_ms) + [o addFeedbackHandler:^(id f) { + double s = f.GPUEndTime - f.GPUStartTime; + if (f.error) { static int n; if (n++ < 8) MLOG("[RED] snapshot command buffer error: %s", f.error.description.UTF8String); } + pthread_mutex_lock(&g_pq_mu); g_snap_gpu[v % PRING].v = v; g_snap_gpu[v % PRING].ms = s > 0 && s < 1 ? (float)(s * 1e3) : 0; pthread_mutex_unlock(&g_pq_mu); + }]; if (rec_on() && g_rb_started) { // a block of the encode thread's queue, behind the frame's work (see above) if (on_sub_thread()) rec_publish(); // what the submitting thread recorded outside a submission goes first rec_blk *b = rec_own_begin(); - rec_t *r = rec_own_put(b, RO_COMMIT_REAL, 2); r->a[0] = 0; r->a[1] = rec_obj(cb); + rec_t *r = rec_own_put(b, RO_COMMIT_REAL, 2); r->a[0] = rec_obj(o); r->a[1] = rec_obj(cb); r = rec_own_put(b, RO_SIGNAL, 1); r->a[0] = rec_obj(g_snap_ev); r->a[1] = v; r = rec_own_put(b, RO_NOTE, 0); r->a[0] = (uint64_t)(uintptr_t)&g_snap_cmt; r->a[1] = v; rec_own_push(b); } else { - pthread_mutex_lock(&g_res_mu); [g_q4 commit:&cb count:1]; [g_q4 signalEvent:g_snap_ev value:v]; pthread_mutex_unlock(&g_res_mu); + pthread_mutex_lock(&g_res_mu); [g_q4 commit:&cb count:1 options:o]; [g_q4 signalEvent:g_snap_ev value:v]; pthread_mutex_unlock(&g_res_mu); atomic_store(&g_snap_cmt, v); } g_snap[k].ev = v; @@ -12132,13 +12248,14 @@ static uint64_t present_enqueue(const tex_t *t, double period, const int crop[4] tex_t snap; uint64_t ss = 0; int slot = 0; if (t && !ev_val && mtl_snap_on()) { slot = (int)(atomic_load(&g_snap_next) % (uint64_t)g_snap_n); - if ((ss = snap_take(t))) { memset(&snap, 0, sizeof snap); snap.magic = MAGIC('T', 'E', 'X', 0); snap.serial = ss; t = &snap; } + if ((ss = snap_take(t, crop))) { memset(&snap, 0, sizeof snap); snap.magic = MAGIC('T', 'E', 'X', 0); snap.serial = ss; t = &snap; } } pthread_mutex_lock(&g_pq_mu); while (g_pq_in - g_pq_done >= PQ) pthread_cond_wait(&g_pq_cv, &g_pq_mu); // Wait only when the queue is full; normally AcquireTexture blocks first - pq_item *it = &g_pq[g_pq_in % PQ]; *it = (pq_item){*t, period, atomic_load(&g_cur_frame), {0}, CACurrentMediaTime(), ev_val, ss ? g_snap[slot].ev : 0}; + pq_item *it = &g_pq[g_pq_in % PQ]; *it = (pq_item){*t, period, atomic_load(&g_cur_frame), {0}, CACurrentMediaTime(), ev_val, ss ? g_snap[slot].ev : 0, ss ? slot : -1, ss ? g_snap[slot].up_gen : 0}; if (crop) memcpy(it->crop, crop, sizeof it->crop); // The current frame's state is enqueued with the ticket number, rather than reading the mutable window late on the present thread uint64_t tk = ++g_pq_in; + g_snap_v_of[tk % PRING] = ss ? g_snap[slot].ev : 0; // the snapshot this present shows, for @snap_gpu_ms if (ss) { g_snap[slot].ticket = tk; atomic_fetch_add(&g_snap_next, 1); } pthread_cond_broadcast(&g_pq_cv); pthread_mutex_unlock(&g_pq_mu); diff --git a/dm/gfx/tests/Makefile b/dm/gfx/tests/Makefile index ab23cdeeca..c0aa350885 100644 --- a/dm/gfx/tests/Makefile +++ b/dm/gfx/tests/Makefile @@ -179,6 +179,8 @@ check_t_present_snap: t_present_snap DM_NVN_ENC_THREAD=0 MTL_DEBUG_LAYER=1 ./t_present_snap pacing DM_NVN_ENC_THREAD=1 MTL_DEBUG_LAYER=1 ./t_present_snap resize DM_NVN_ENC_THREAD=0 MTL_DEBUG_LAYER=1 ./t_present_snap resize + DM_NVN_ENC_THREAD=1 MTL_DEBUG_LAYER=1 ./t_present_snap fxsnap + DM_NVN_ENC_THREAD=0 MTL_DEBUG_LAYER=1 ./t_present_snap fxsnap t_reorder_chain: t_reorder_chain.m $(MTL_T_DEP) clang $(CFLAGS) -fobjc-arc -o $@ t_reorder_chain.m $(MTL_T_SRC) $(FW) check_t_reorder_chain: RUN_ENV = MTL_DEBUG_LAYER=1 diff --git a/dm/gfx/tests/t_present_snap.m b/dm/gfx/tests/t_present_snap.m index c1f375266a..f6dbe82e22 100644 --- a/dm/gfx/tests/t_present_snap.m +++ b/dm/gfx/tests/t_present_snap.m @@ -12,23 +12,29 @@ void svc_thread_dump(void) {} uint64_t now_ns(void) { return bp_now(); } static int checks, failed; #define CHECK(name, ok) do { int pass = !!(ok); checks++; failed += !pass; printf("%s: %s\n", name, pass ? "PASS" : "FAIL"); } while (0) -static tex_t source_n(unsigned i, int n) { // n x n texels of 73 + i (n at most 16) +static tex_t source_tex(uint64_t serial, int n, int v) { // an n x n RGBA8 texture of texels v, registered under serial MTLTextureDescriptor *d = [MTLTextureDescriptor texture2DDescriptorWithPixelFormat:MTLPixelFormatRGBA8Unorm width:n height:n mipmapped:NO]; d.storageMode = MTLStorageModeShared; d.usage = MTLTextureUsageShaderRead; - id mt = [g_dev newTextureWithDescriptor:d]; uint8_t bytes[1024]; memset(bytes, 73 + i, sizeof bytes); - [mt replaceRegion:MTLRegionMake2D(0, 0, n, n) mipmapLevel:0 withBytes:bytes bytesPerRow:n * 4]; - tex_t t = {.magic=MAGIC('T','E','X',0), .serial=90001+i}; + id mt = [g_dev newTextureWithDescriptor:d]; uint8_t *bytes = malloc((size_t)n * n * 4); memset(bytes, v, (size_t)n * n * 4); + [mt replaceRegion:MTLRegionMake2D(0, 0, n, n) mipmapLevel:0 withBytes:bytes bytesPerRow:n * 4]; free(bytes); + tex_t t = {.magic=MAGIC('T','E','X',0), .serial=serial}; t.d.width = t.d.height = n; t.d.depth = t.d.levels = t.d.samples = 1; t.d.target = NVN_TEXTURE_TARGET_2D; t.d.format = NVN_FORMAT_RGBA8; serial_put(t.serial, mt); res_add(mt); res_commit(); return t; } +static tex_t source_n(unsigned i, int n) { return source_tex(90001 + i, n, 73 + i); } // n x n texels of 73 + i static tex_t source(unsigned i) { return source_n(i, 8); } -static void pixels(id t, int value) { - id out = [g_dev newBufferWithLength:256 options:MTLResourceStorageModeShared]; +static id need(id o, const char *what) { if (!o) { fprintf(stderr, "t_present_snap: Metal returned no %s\n", what); exit(1); } return o; } // a Metal object the test cannot go on without +static id new_gate(void) { return need([g_dev newSharedEvent], "shared event"); } +static id read_block(id t, NSUInteger x0, NSUInteger y0) { // the 8 x 8 texels of t at (x0, y0), 4 bytes each + id out = need([g_dev newBufferWithLength:256 options:MTLResourceStorageModeShared], "buffer"); id cb = [g_q commandBuffer]; id b = [cb blitCommandEncoder]; - [b copyFromTexture:t sourceSlice:0 sourceLevel:0 sourceOrigin:MTLOriginMake(0,0,0) sourceSize:MTLSizeMake(8,8,1) + [b copyFromTexture:t sourceSlice:0 sourceLevel:0 sourceOrigin:MTLOriginMake(x0, y0, 0) sourceSize:MTLSizeMake(8, 8, 1) toBuffer:out destinationOffset:0 destinationBytesPerRow:32 destinationBytesPerImage:256]; - [b endEncoding]; [cb commit]; [cb waitUntilCompleted]; + [b endEncoding]; [cb commit]; [cb waitUntilCompleted]; return out; +} +static void pixels(id t, int value) { + id out = read_block(t, 0, 0); int bad = 0; for (int i = 0; i < 256; i++) bad += ((uint8_t *)out.contents)[i] != value; CHECK("snapshot has the expected pixels", bad == 0); } @@ -47,7 +53,7 @@ static void suspend_case(void) { tex_t t = source(0); state_reset(); memset(&R, 0, sizeof R); mtl_sub_begin(); CHECK("prior submission completed", mtl_wait(mtl_sub_commit(), 2000000000ull)); - id gpu_gate = [g_dev newSharedEvent]; + id gpu_gate = new_gate(); [g_q4 waitForEvent:gpu_gate value:1]; gate_encoder(); // The OS has stopped the display link before notifying the app to suspend. @@ -97,7 +103,7 @@ static void pacing_case(void) { } static void pending_copy_case(void) { tex_t t = source(0); - id gpu_gate = [g_dev newSharedEvent]; [g_q4 waitForEvent:gpu_gate value:1]; + id gpu_gate = new_gate(); [g_q4 waitForEvent:gpu_gate value:1]; pthread_mutex_lock(&g_pq_mu); g_link_owns_layer = 1; pthread_mutex_unlock(&g_pq_mu); CHECK("first snapshot queued", present_enqueue(&t, 1. / 60, NULL, 0) == 0); CHECK("second snapshot queued", present_enqueue(&t, 1. / 60, NULL, 0) == 0); @@ -117,7 +123,7 @@ static void resize_case(void) { snap_present(&small); snap_present(&small); CHECK("both ring slots copied", [g_snap_ev waitUntilSignaledValue:g_snap_v timeoutMS:2000]); id old0 = g_snap[0].tex, old1 = g_snap[1].tex; - id gpu_gate = [g_dev newSharedEvent]; [g_q4 waitForEvent:gpu_gate value:1]; // stands for display command buffers still queued + id gpu_gate = new_gate(); [g_q4 waitForEvent:gpu_gate value:1]; // stands for display command buffers still queued snap_present(&big); CHECK("slot 0 has a texture of the new size", g_snap[0].tex != old0 && g_snap[0].tex.width == 16); CHECK("slot 0's old texture is still resident", [g_snap_res containsAllocation:old0]); @@ -137,15 +143,69 @@ static void resize_case(void) { snap_present(&big); CHECK("slot 1's old texture leaves at its next use", ![g_snap_res containsAllocation:old1] && !g_snap[1].old); } +static tex_t source_flat(unsigned i, int n, int v) { return source_tex(90101 + i, n, v); } // n x n texels of value v (any n), RGBA8 +// The colour channels of an 8 x 8 block in the middle of t (BGRA8), all within tol of value +static void pixels_near(id t, int value, int tol, const char *what) { + id out = read_block(t, t.width / 2 - 4, t.height / 2 - 4); + int bad = 0, worst = 0; for (int i = 0; i < 256; i++) { if (i % 4 == 3) continue; int d = abs((int)((uint8_t *)out.contents)[i] - value); if (d > worst) worst = d; bad += d > tol; } + char b2[160]; snprintf(b2, sizeof b2, "%s (worst channel error %d)", what, worst); CHECK(b2, bad == 0); +} +// The MetalFX scaler at the snapshot (DM_PRESENT_FX_AT_SNAP): a 64 x 64 picture presented on a 256 x 256 canvas is scaled into the ring slot's up texture by the snapshot's command +// buffer, present_now would draw it 1:1 (snap_up_for), a canvas change replaces up (the old one resident until the slot's next use, the scaler remade once the queued snapshots ran), +// and a present on a canvas other than the snapshot's falls back to the raw copy +static void fx_snap_case(void) { + if (fx_mode() != 1) { printf("present upscaling unavailable on this device: the MetalFX-at-snapshot case is skipped\n"); return; } + g_snap_canvas_test[0] = g_snap_canvas_test[1] = 256; g_snap_canvas_test_pf = MTLPixelFormatBGRA8Unorm; + tex_t t = source_flat(0, 64, 100); + snap_present(&t); snap_present(&t); + CHECK("both snapshots completed", [g_snap_ev waitUntilSignaledValue:g_snap_v timeoutMS:4000]); + CHECK("the snapshot scaler was made once", g_fx_snap.sc != nil && g_fx_snap.made == 1 && g_fx_snap.out == nil); + CHECK("slot 0 has a scaled picture of the canvas rectangle's size", g_snap[0].up_valid && g_snap[0].up.width == 256 && g_snap[0].up.height == 256 && g_snap[0].up.pixelFormat == MTLPixelFormatBGRA8Unorm && g_snap[0].up_gen == 1); + CHECK("slot 1 too, and both are resident", g_snap[1].up_valid && g_snap[1].up.width == 256 && [g_snap_res containsAllocation:g_snap[0].up] && [g_snap_res containsAllocation:g_snap[1].up]); + pixels(g_snap[0].tex, 100); // the raw copy stays (the fallback's and the screenshots' source); its 8 x 8 corner + pixels_near(g_snap[0].up, 100, 3, "the scaled picture holds the flat colour"); + id up = nil; MTLViewport vp; + CHECK("a present on the snapshot's canvas draws the scaled picture 1:1", snap_up_for(0, 1, 256, 256, MTLPixelFormatBGRA8Unorm, &up, &vp) && up == g_snap[0].up && vp.originX == 0 && vp.originY == 0 && vp.width == 256 && vp.height == 256); + CHECK("a present on a resized canvas falls back to the raw copy", !snap_up_for(0, 1, 300, 256, MTLPixelFormatBGRA8Unorm, &up, &vp) && !snap_up_for(0, 1, 256, 256, MTLPixelFormatBGRA8Unorm_sRGB, &up, &vp)); + CHECK("another snapshot count of the slot does not match", !snap_up_for(0, 2, 256, 256, MTLPixelFormatBGRA8Unorm, &up, &vp)); + uint64_t fb = g_snap_fx_fallback; snap_up_stale(0, 1); snap_up_stale(0, 7); CHECK("a stale picture counts one fallback", g_snap_fx_fallback == fb + 1); + // The canvas changes (a window resize): the next snapshots scale for 128 x 96 (a 4:3 canvas: the picture's rectangle is 96 x 96 at x 16), the old up textures stay resident until each slot's next use + id old0 = g_snap[0].up, old1 = g_snap[1].up; + id gpu_gate = new_gate(); [g_q4 waitForEvent:gpu_gate value:1]; // stands for display command buffers still queued, which may read old0 / old1 + g_snap_canvas_test[0] = 128; g_snap_canvas_test[1] = 96; + uint64_t t0 = now_ns(); snap_present(&t); double ms = (now_ns() - t0) / 1e6; + CHECK("the scaler is remade for the new canvas", g_fx_snap.made == 2 && g_fx_snap.ow == 96 && g_fx_snap.oh == 96); + CHECK("slot 0's scaled picture has the new rectangle's size, at its place on the canvas", g_snap[0].up != old0 && g_snap[0].up.width == 96 && g_snap[0].up.height == 96 && g_snap[0].up_vx == 16 && g_snap[0].up_vy == 0 && g_snap[0].up_gen == 2); + CHECK("slot 0's old scaled picture is still resident", g_snap[0].old_up == old0 && [g_snap_res containsAllocation:old0]); + printf("the first snapshot after the canvas change took %.1f ms (the scaler's remake waits for the queued snapshots: the gate was closed, so it waited for nothing queued after it)\n", ms); + snap_present(&t); + CHECK("slot 1's old scaled picture is still resident", g_snap[1].old_up == old1 && [g_snap_res containsAllocation:old1]); + gpu_gate.signaledValue = 1; + CHECK("the replacing snapshots complete", [g_snap_ev waitUntilSignaledValue:g_snap_v timeoutMS:4000]); + snap_present(&t); + CHECK("slot 0's old scaled picture leaves at the slot's next use", !g_snap[0].old_up && ![g_snap_res containsAllocation:old0] && [g_snap_res containsAllocation:g_snap[0].up]); + CHECK("slot 1's old scaled picture waits for its own slot", [g_snap_res containsAllocation:old1]); + CHECK("the snapshot completes", [g_snap_ev waitUntilSignaledValue:g_snap_v timeoutMS:4000]); + pixels_near(g_snap[0].up, 100, 3, "the picture scaled for the new canvas holds the flat colour"); + CHECK("a present on the new canvas draws it 1:1 at x 16", snap_up_for(0, 3, 128, 96, MTLPixelFormatBGRA8Unorm, &up, &vp) && vp.originX == 16 && vp.width == 96 && vp.height == 96); + // The snapshot's GPU time is recorded by its version, for @snap_gpu_ms + CHECK("the snapshot command buffer's GPU time is recorded", g_snap_gpu[g_snap_v % PRING].v == g_snap_v && g_snap_gpu[g_snap_v % PRING].ms > 0); + // With the switch off the raw copy alone is taken and the slot's picture is not valid for the present + g_snap_canvas_test[0] = 0; // no canvas: as with no layer + snap_present(&t); CHECK("the snapshot completes without a canvas", [g_snap_ev waitUntilSignaledValue:g_snap_v timeoutMS:4000]); + CHECK("no canvas: the slot's scaled picture is not offered to the present", !g_snap[1].up_valid && !snap_up_for(1, g_snap[1].up_gen, 128, 96, MTLPixelFormatBGRA8Unorm, &up, &vp)); +} int main(int argc, char **argv) { @autoreleasepool { alarm(15); setbuf(stdout, NULL); if (argc != 2) return 2; setenv("DM_PRESENT_SNAP", "1", 1); setenv("DM_PRESENT_HZ", "0", 1); + if (!strcmp(argv[1], "fxsnap")) setenv("DM_PRESENT_UPSCALE", "metalfx", 1); mtl_init(); if (!strcmp(argv[1], "suspend")) suspend_case(); else if (!strcmp(argv[1], "pacing")) pacing_case(); else if (!strcmp(argv[1], "copy")) pending_copy_case(); else if (!strcmp(argv[1], "resize")) resize_case(); + else if (!strcmp(argv[1], "fxsnap")) fx_snap_case(); else return 2; printf("present snapshots: %d checks, %d failed\n", checks, failed); return failed != 0; } } diff --git a/dm/tools/lint_c_baseline.tsv b/dm/tools/lint_c_baseline.tsv index 3c6068ab8b..cdb8141ecf 100644 --- a/dm/tools/lint_c_baseline.tsv +++ b/dm/tools/lint_c_baseline.tsv @@ -63,7 +63,6 @@ dm/gfx/tests/t_present_alloc.m clang-analyzer-nullability.NullablePassedToNonnul dm/gfx/tests/t_present_crop.m clang-analyzer-nullability.NullablePassedToNonnull 1 dm/gfx/tests/t_present_rescue.m bugprone-unsafe-functions 1 dm/gfx/tests/t_present_snap.m bugprone-unsafe-functions 1 -dm/gfx/tests/t_present_snap.m clang-analyzer-nullability.NullablePassedToNonnull 1 dm/gfx/tests/t_present_snap.m clang-analyzer-osx.cocoa.RetainCount 1 dm/gfx/tests/t_primitive_restart.m clang-analyzer-osx.cocoa.RetainCount 1 dm/gfx/tests/t_primitive_restart.m clang-analyzer-unix.cstring.UninitializedRead 1 diff --git a/docs/agents/symptoms.md b/docs/agents/symptoms.md index 774d6d5873..f15853e5df 100644 --- a/docs/agents/symptoms.md +++ b/docs/agents/symptoms.md @@ -329,6 +329,7 @@ One line per symptom in the [subsystem references](../reference/): what you see - in a game the host steps at 60 fps (`FRAME_STEP`), a prerendered movie plays at twice its speed, its sound falls behind, and the frame counter shows 60 during it. The log has `[movie]` lines with pictures 33 ms apart (`time 0 / 33000 / 67000 µs`) and no `frame step cap 60 → 30` at the movie. → [Movies hold 30 fps under the frame step](../reference/frame-rate.md#movies-hold-30-fps-under-the-frame-step) - after a 30 fps cap ends (a prerendered movie, the thermal cap), a GPU-bound game stays at 30 fps in a scene that held 60 before the cap; the log shows `frame step cap 30 → 60 fps` and a few frames later `frame step: hold 1 → 2 vsyncs at present … (3 late frames; …)`, with no probe after it. → [The frame step after a 30 fps cap ends](../reference/frame-rate.md#the-frame-step-after-a-30-fps-cap-ends) - on a Mac, a GPU-bound game at 60 fps falls to 30 or 20 fps when the scene gets heavier and stays there until a menu or a lighter scene, while the GPU clock sits at its floor (338–400 MHz on an M5 Pro) and the GPU is powered 60–75% of the time; the log shows probes back to hold 1 that fail after about 33 frames (`frame step: hold 2 → 1 vsyncs … (probe, GPU 1.67× its time at hold 1)` then `the probe failed`), and the host's profiler (`@gpu_mhz`) shows the clock rising during each probe and falling back after it. → [A probe's grace lasts while its frames keep getting cheaper](../reference/frame-rate.md#a-probes-grace-lasts-while-its-frames-keep-getting-cheaper) +- on a Mac in fullscreen with `DM_PRESENT_UPSCALE=metalfx`, a game whose GPU work fits the frame runs at 48–56 fps at hold 1 with brief steps to 30 (the frame step's `3 late frames; cost 0.83 vsyncs, GPU 0.83` then a probe back 35 frames later), the GPU clock at its floor and the GPU powered 97–99%; `@gpu_ms` is 12.5–13.5 ms of a 17–19 ms frame, the GPU span of the frame exceeds its summed segment time by 1–4 ms, and the log's `present command buffer GPU time over 600 presents through MetalFX` is p50 2.6 ms (1 ms when the clock was at 850 MHz). → [The MetalFX present runs on the game's queue, inside its frame](../reference/frame-rate.md#the-metalfx-present-runs-on-the-games-queue-inside-its-frame) - a game whose profile has a frame step (`FRAME_STEP` in its `patches.py`) runs at double speed when packed from another update; the log has no `frame step in whole vsyncs` line, and the frame counter shows 60. → [A derived profile drops the frame step its build lacks](../reference/frame-rate.md#a-derived-profile-drops-the-frame-step-its-build-lacks) - a fixed-step game runs at double speed (or slow motion at 30) after `DM_FPS_TARGET` is set, in `Documents/env.txt` or the launcher, on a build its profile's frame step stubs and limiter rows do not know. → [A present cap applies only with a frame step or an engine limit the host writes](../reference/frame-rate.md#a-present-cap-applies-only-with-a-frame-step-or-an-engine-limit-the-host-writes) - selecting 30 FPS changes the engine's interval field, but the screen and frame loop still run near 60 FPS. → [Engine-native frame caps also govern presentation](../reference/frame-rate.md#engine-native-frame-caps-also-govern-presentation) diff --git a/docs/env_switches.tsv b/docs/env_switches.tsv index 9591f941b1..d22f391db6 100644 --- a/docs/env_switches.tsv +++ b/docs/env_switches.tsv @@ -203,12 +203,13 @@ DM_PHONE_MOTION switch On iOS, whether the phone's own device motion drives play DM_PREEMPT switch `0` / `1` overrides the profile's `core_preempt`: also check already-runnable higher-priority peers on the caller's core after every thread SVC DM_PRELOAD diagnostic Set: on the Mac, runs the host's early background loading (`dm_host_preload_start`) as the iOS app does, to exercise that path DM_PRESENT_FIFO switch `0` makes the display link take the newest queued frame each tick, as before; by default it shows frames in order, at most one tick behind +DM_PRESENT_FX_AT_SNAP switch With present snapshots and `DM_PRESENT_UPSCALE=metalfx`: `1` (the default on the Mac; `0` is the default on iOS, where it is not measured yet) runs the MetalFX scaler in the snapshot's command buffer, right after the frame's work, and the present draws the scaled picture 1:1; `0` scales in the present command buffer as before (between the next frame's segments); `ab` alternates with `DM_AB` DM_PRESENT_HZ switch `=`: the frequency of presentation pacing (default 60); `0` means no frame limit and is for performance profiling only DM_PRESENT_INTERVAL switch `display` presents one frame per display-link tick whatever interval the game sets; `game` follows the game's present interval (default: the profile's `present_interval`) DM_PRESENT_LATENCY switch `=1` or `2`: overrides the display link's preferred frame latency for every screen and window mode; larger positive values use 2 (default 2 in variable-refresh fullscreen, 1 otherwise) DM_PRESENT_LINK switch Present pacing: `0` acquires the drawable itself, `1` (the default) presents on a 60 Hz display link, `2` uses a 120 Hz display link with a frame every other tick DM_PRESENT_SNAP player `=`: present snapshots, a ring of n host textures (2 to 4; `1` = 2) the presents are copied to so the game's swapchain texture is free at once; `0` off (default: the profile's `present_snap`) -DM_PRESENT_UPSCALE player `metalfx` scales a picture smaller than its rectangle on the screen through MetalFX's spatial scaler; `off` (the default) scales it bilinearly +DM_PRESENT_UPSCALE player `metalfx` scales a picture smaller than its rectangle on the screen through MetalFX's spatial scaler; `off` (the default) scales it bilinearly; `ab` alternates the two with `DM_AB` (the scaler's GPU time runs on the game's queue, in its frame: `@present_gpu_ms`) DM_PROBE diagnostic `=module:offset,…` (Mac only): puts a `brk` at each guest address and on every hit prints the thread, registers, strings they point to and a backtrace, then runs the original instruction DM_PROBE_ALL diagnostic Set: probe hits (`DM_PROBE`) also print x8–x18 DM_PROBE_DUMP diagnostic `=module:offset:length[:file]`: on the first hit of any probe, writes that range of guest memory to a file (default `run//probe_dump.bin`) diff --git a/docs/reference/frame-rate.md b/docs/reference/frame-rate.md index 8187908f7c..9d4133b8bd 100644 --- a/docs/reference/frame-rate.md +++ b/docs/reference/frame-rate.md @@ -62,6 +62,13 @@ Frame pacing: the host's frame step, engine frame limiters, present intervals an - **Found on:** [The Legend of Zelda: Breath of the Wild](../../dm/games/01007EF00011E000/README.md#the-frame-step-current) (Mac M5 Pro, fullscreen, present snapshots, the host's profiler); resolved there: in a 470 s run with the rule switched every 30 s, every probe with it held (11 in a row). - **Note:** what shortens the serial chain itself, so the GPU's occupancy at a GPU-bound hold is higher and the clock rises faster: Metal encoding on its own thread (`DM_NVN_ENC_THREAD=1`, the profile's `enc_thread on`; the submit thread's translation 6.5 → about 4 ms a frame, measured on an M4 Pro and for Need for Speed), and a smaller first segment. Neither can start the GPU before the game's own work after its wait, and neither was measured on this symptom yet. +### The MetalFX present runs on the game's queue, inside its frame + +- **Symptom:** on a Mac in fullscreen with `DM_PRESENT_UPSCALE=metalfx`, a game whose GPU work fits the frame runs at 48–56 fps at hold 1 with brief steps to 30 (the frame step's `3 late frames; cost 0.83 vsyncs, GPU 0.83` then a probe back 35 frames later), the GPU clock at its floor and the GPU powered 97–99%; `@gpu_ms` is 12.5–13.5 ms of a 17–19 ms frame, the GPU span of the frame exceeds its summed segment time by 1–4 ms, and the log's `present command buffer GPU time over 600 presents through MetalFX` is p50 2.6 ms (1 ms when the clock was at 850 MHz). +- **Cause:** `present_now` (`nvn_mtl.m`) commits the present command buffer, the MetalFX spatial scaler (1920x1080 → the 3456x1944 fullscreen canvas) and the present pass, on `g_q4`, the queue the game's segments run on, from the display-link thread at each tick. The queue runs command buffers in commit order and every encoder starts with a queue barrier, so the present lands between two of the frame's segments or right after them: 2.6 ms of the game's GPU chain at the floor clock, where the frame's own 13 ms plus the chain's idle (the game's work after its fence wait, the first cut) already came to about 15 ms. The frame step does not see it (its cost is the frame's own GPU time), so the frames look as if they fit and only the screen is late. +- **Fix:** with present snapshots the scaler runs at the snapshot (`snap_take`, `DM_PRESENT_FX_AT_SNAP`, on by default on the Mac and off on iOS, where it is not measured yet; `0` the old placement, `ab` alternates with `DM_AB`): the snapshot's command buffer, committed right after the frame's last segment, copies the game's texture into the ring slot as before and then scales its presented rectangle through MetalFX into the slot's `up` texture, the size of the rectangle on the canvas (`present_viewport`), so the scaler runs in the gap the game's own work leaves before the next frame's first segment. The display-link present draws `up` 1:1 (`snap_up_for`, `present_draw_m4`), no scaler between the segments. The snapshot scaler (`g_fx_snap`, `fx_prepare` / `fx_run`) is the present's own code with the slot's texture as output; its input copy lives in `g_res`, `up` in `g_snap_res`. A canvas that changes (a resize, fullscreen) remakes the scaler once the queued snapshots ran (bounded: 200 ms, else this snapshot takes the old path) and gives the slot a new `up`; the old one stays resident until the slot's next use, as the slot's raw copy does ([A replaced snapshot ring texture stays resident until the slot's next use](#a-replaced-snapshot-ring-texture-stays-resident-until-the-slots-next-use)). A present whose drawable differs from the canvas the snapshot was scaled for (the resize came between) falls back to the raw copy and the present's scaler for that frame; so does a present without a layer, without snapshots, or with the switch off. Without the switch, `DM_PRESENT_UPSCALE=ab` alternates the scaler with the bilinear pass per phase. `@present_gpu_ms` and `@snap_gpu_ms` (`DM_NVN_TSV`, 8 presents late like `@presented_ms`) record each present's and each snapshot's command buffer GPU time, and the log's `present command buffer GPU time` line has a third kind, `of a snapshot scaled by MetalFX at the snapshot`. +- **Check:** `make -C dm/gfx/tests GAME=01007EF00011E000 check_t_present_snap` (`fxsnap`, both encode modes, Metal validation): a 64x64 picture on a 256x256 canvas is scaled into both slots' `up`, flat colour exact, the present's decision for the same, a resized and a reformatted canvas, a canvas change (128x96: a 96x96 rectangle at x 16) remakes the scaler and keeps each slot's old `up` resident until its next use, the snapshot's GPU time is recorded, no canvas offers no picture. In a run: `DM_AB=1800 DM_PRESENT_FX_AT_SNAP=ab`, the `[ab] phase N PRESENT_FX_AT_SNAP` lines' frame p50 against the base phases', `@present_gpu_ms` (about 0.3 against 2.6 ms) and `@snap_gpu_ms` (about 2.8 against 0.2 ms) in `perf_report.py`. +- **Found on:** [The Legend of Zelda: Breath of the Wild](../../dm/games/01007EF00011E000/README.md#gpu-work) (M5 Pro, fullscreen, present snapshots, encode thread; 320–460 s of a 470 s profile); resolved there: the present's GPU time on the game's queue 2.6 → 0.34–0.52 ms in the same run, and runs 7–10 held 60 fps until the display-link shift ([The display link loses ticks when the screen shifts 1/240 s under it](#the-display-link-loses-ticks-when-the-screen-shifts-1240-s-under-it)). ### A derived profile drops the frame step its build lacks From c92eff46067e39cde87a43f1b1c2da887c47dc6c Mon Sep 17 00:00:00 2001 From: Paolo Moretti Date: Sun, 1 Nov 2026 15:40:00 +0700 Subject: [PATCH 5/5] Present: pacing leaves the display link when the screen shifts under it in variable-refresh fullscreen Breath of the Wild in fullscreen on a ProMotion Mac (M5 Pro): at one frame of a session (87, 251, 342 and 355 s in four of them) the system starts showing every frame exactly 4.17 ms (1/240 s) after the display link's target and keeps that offset. Nothing on the host side changes at that frame. From then on the link calls back a tick late about every 11-12 frames: 56 fps on the 60 Hz link, 58.6 on the 120 Hz link at frame latency 2 and 1 alike. A display link made again keeps the offset. Without the link (mode 0, the present thread presenting each frame for its period) the game held 60.03 fps for 15 minutes at game time 1.000. - link_late_note checks each frame's presentation time against its link target. When 120 presents in a row were three quarters or more 2 ms or more late, a 60 fps game leaves the link for mode 0, where it fits (link_leave_ok): fullscreen on a variable-refresh screen, at any rate. Fixed-rate screens and windows keep the link; leaving those conditions takes pacing back to it. DM_PRESENT_RESYNC=0 turns the switch off. - Each move of the frames' offset against the link's targets is logged with its first present, the callback's time after the flip two frames back, the screen's rate and refresh kind, fullscreen, latency and pacing mode (the first 8, then a count a minute). - DM_NVN_TSV gains where the link callback that took each frame spent its time: @link_slack_ms (update.targetTimestamp minus the present call), @link_wait_ms (snapshot and external-producer waits), @link_alloc_ms (present_now's allocator wait), @link_run_ms (entry to exit), @link_idle_ms (since the previous callback exited), @link_held_ms (the longest callback that took no frame since the previous present), @link_lock_ms (the wait for g_pq_mu). On 200 late frames on the 120 Hz link our callbacks ran 0.16 ms (max 0.5) with no wait, each present came 8.1 ms before its deadline, and the link thread sat idle 20.7 ms before each late callback where it waits 8.33 ms otherwise: the system called back late, not the host. - The link callback's hold counts the link's own ticks (link_hold_s): a frame stays on screen for its whole period when that covers two or more ticks. The fixed "period > 25 ms" let every tick of the 120 Hz link (DM_PRESENT_LINK=2) take a 60 fps frame, and with present snapshots the game ran at 87 fps and 1.16 of real time. The 60 and 30 Hz links hold exactly as before. t_link_ticks 48 checks (the hold on 120, 60 and 30 Hz and virtual ticks; the shift judge; link_leave_ok; the offset tracker); t_present_rescue --metal; check_t_present_snap. A replay of the judge and the tracker over four sessions' frame rows dated the shift to the frame found by hand and fired where 56 fps began. Not checked: the switch itself in a run; external screens. --- dm/games/01007EF00011E000/README.md | 2 + dm/gfx/nvn/hle_nvn.c | 6 +- dm/gfx/nvn/nvn_mtl.m | 124 ++++++++++++++++++++++++++-- dm/gfx/nvn/nvn_obj.h | 1 + dm/gfx/tests/t_link_ticks.m | 53 ++++++++++++ dm/gfx/tests/t_present_rescue.m | 28 ++++++- dm/tools/lint_c_baseline.tsv | 4 +- docs/agents/symptoms.md | 1 + docs/env_switches.tsv | 1 + docs/reference/frame-rate.md | 8 ++ 10 files changed, 219 insertions(+), 9 deletions(-) diff --git a/dm/games/01007EF00011E000/README.md b/dm/games/01007EF00011E000/README.md index 048d655583..0a41594950 100644 --- a/dm/games/01007EF00011E000/README.md +++ b/dm/games/01007EF00011E000/README.md @@ -30,6 +30,7 @@ No `tex_flush_upload` (a minute's boot saw it flush 32 CPU-filled textures with - Mac (M4 Pro), from the title into the save's scene: 1.000 of real time at 60; with 12 ms added to every frame (`DM_TEST_PRESENT_LAG=1,12`) it drops to 30 and stays at 1.000. `DM_FPS_TARGET=30` holds 30 (saves power, also from `Documents/env.txt`); `0` runs the game's own interval controller. - **Frame-step probes (iPhone).** The GPU clock follows the hold: on an iPhone the game went from 14.4 to about 25 ms of GPU time a frame at 30 fps with the same 4,900 draws, its CPU still on the performance cores, and never tried 60 again; a GPU time at the longer hold of at least 1.3 times its time at 60 that alone does not fit 60 (`nvn_fstep_gpu_slowed`) now allows probes. Stepped up by pipeline compiles after a cutscene, it took 12.8–15.2 ms of GPU time a frame at 30 fps (p50) where 60 had held for minutes, and stayed at 30 for 36 and 46 s until the player switched out and back (the same 4,900 draws took 5.8 ms right after a trip to the background and 13.5 ms half a minute later); a step up after 8 s or more at 60 now keeps that run's cost, and a cost at the longer hold of at most 1.1 times it allows a probe (`nvn_fstep_same`). Log lines: `frame step: hold 2 → 1 … (probe, …)`, `the probe held / failed`, `hold 1 held at 0.86`. Details: [development.md, Power](../../../docs/development.md#power). - **Frame-step probes on the Mac (resolved, 2026-11-01).** An M5 Pro, fullscreen, present snapshots on, encode thread off, the host's profiler (`dm/host/sysprof.m`, `@gpu_mhz` / `@gpu_on`): at 60 fps macOS lowered the GPU clock from about 1,200 to 400 MHz over 4 s whenever the frame fit, until the frame's GPU work was about 11.7 of 16.6 ms (GPU powered 98%, occupied 70%: the game's own work after its fence wait, the first cut and segments drained faster than encoded leave 2–5 ms a frame without GPU work). A heavier scene (4,200–4,700 draws, GPU 20–27 ms at 400 MHz, 8 ms at 1,200) stepped the hold to 2 or 3 within three frames, where the GPU is occupied 55–75% and the clock fell to its floor (338 MHz); each probe back to hold 1 saw the clock rise 338 → 432 MHz and the GPU time fall 24.8 → 18.5 ms over its 33 frames, then failed, and hold 2 stayed for minutes. The probe's grace now lasts while its frames keep getting cheaper: [A probe's grace lasts while its frames keep getting cheaper](../../../docs/reference/frame-rate.md#a-probes-grace-lasts-while-its-frames-keep-getting-cheaper). The game waits on the fence of the frame it just submitted (`@sync_ms` 9.7 ms ≈ the GPU's end after the present at 400 MHz, 0 at 1,200), as on the Switch; the host's fence is the last commit's and wakes on the GPU's signal. Holding back the first segment (`DM_NVN_CUT_FIRST=ab`) only moved the GPU's start 4 ms later and lost 7 fps. With the fix (a 470 s run, `DM_FSTEP_PROBE_RAMP=ab`, encode thread on) every probe after the first 80 s held, 11 in a row, each within about a second; the probes that failed (presents 3834, 3929, 4083) were in a phase with the rule off. +- **56 fps once the screen shifts under the display link (resolved, 2026-11-02).** At one moment of a fullscreen session (87, 251, 342 and 355 s in four of them) the system starts showing every frame 4.17 ms after the display link's target, and from then on calls the link back a tick late about every 11–12 frames (56 fps on the 60 Hz link, 58.6 on the 120 Hz link; our callbacks are idle and on time). Without the link (mode 0) the game held 60.03 fps for 15 minutes, so the host now leaves the link for mode 0 when it sees the shift. In run 11 (27 minutes, no settings) it did so 2 s after the shift at 210 s, and the game held 60 fps in every 30 s window after it: [The display link loses ticks when the screen shifts 1/240 s under it](../../../docs/reference/frame-rate.md#the-display-link-loses-ticks-when-the-screen-shifts-1240-s-under-it). - **Screens whose rate is not a multiple of 60 (from PR #27).** A cheap 50 ms frame shows 54.5 ms at 165 Hz; counted as late it kept the game at 20 fps for good, so the frame step lets a frame on time show one refresh longer than its hold (`shown_slack`, `nvn_fstep.h`). - **Resolved: menu repeat twice as fast at 60 fps (2026-10-26).** `sead::ControllerBase::updateDerivativeParams_` (`main+0xeb0ef0`) adds a constant 1.0 (`main+0xeb0f78`..`88`) to each held button's count and repeats when `fmod(count - delay, pulse)` falls below that step, so delays and pulses were counted in frames: holding Down in the System menu for 0.3 s went 5 entries at 60 and 2 at 30 (found by MacNativeGames, `866beb9`). A `FRAME_STEP` stub at `main+0xeb0f88` takes the VFR's ratio (`+0x3c`, interval / 2) instead, keeping 1.0 when there is no VFR or the ratio is not positive. Mac, 60 fps: 0.2 / 0.3 / 0.4 s now move 1 / 2 / 3 entries, as the game does at 30. The pause menu's fast-repeat countdown (`main+0xe67d00`) already reads the VFR's delta. - `DM_NVN_CUT` growing segments (64, 128, 256 … draws) were tried for fewer commits: the game fell from 60 to 30 fps in the same scene (GPU idle while the long last segments were encoded). @@ -201,6 +202,7 @@ Before publishing, the fixes were integrated with main's pipeline archive and GP - **Open, a SIGSEGV in `nn::util::RelocationTable::Relocate` at one cutscene ([issue #810](https://github.com/seedds/nxnative/issues/810)):** not a host bug as far as the reporter's files show. Their `Event/Demo154_2.sbeventpack` has our length (1,196,295 bytes) but another SHA-256 (`e74e7826…`, ours `b822e8a2…`), from a base NSP that fails the hash check, extracted with `--allow-damaged`; the model's relocation table is inside that file, so heap placement is not the cause. Open until the scene loads after their extraction from a clean NSP. Led to [Extraction of a damaged NSP ends in "The LinkedList is empty"](../../../docs/reference/packing.md#extraction-of-a-damaged-nsp-ends-in-the-linkedlist-is-empty) and [A crash from a damaged NSP's file looks like a host bug](../../../docs/reference/packing.md#a-crash-from-a-damaged-nsps-file-looks-like-a-host-bug). - **Resolved, parallel rewriting (2026-10-31):** [Parallel scans preserve rewrite output](../../../docs/reference/rewriter.md#parallel-scans-preserve-rewrite-output). All 21 binary and TSV outputs of the three modules of v1114112 are byte-identical to the sequential rewriter. The full regression against `635e8008` passed: zero red diagnostics, matching screenshots, and no frame-time or memory regression (M4 Pro, Xcode 27.2 with the per-run compiler override on both revisions). - [Benchmark captures perturb the measured frame pacing](../../../docs/reference/frame-rate.md#benchmark-captures-perturb-the-measured-frame-pacing). +- **Resolved, 56 fps once the screen shifts 4.17 ms under the display link in fullscreen, whatever the scene:** [The display link loses ticks when the screen shifts 1/240 s under it](../../../docs/reference/frame-rate.md#the-display-link-loses-ticks-when-the-screen-shifts-1240-s-under-it). - **Resolved, the Mac's GPU clock at its floor at 30 fps in heavy scenes:** [A probe's grace lasts while its frames keep getting cheaper](../../../docs/reference/frame-rate.md#a-probes-grace-lasts-while-its-frames-keep-getting-cheaper). - **Resolved, MetalFX's present cost inside the frame:** [The MetalFX present runs on the game's queue, inside its frame](../../../docs/reference/frame-rate.md#the-metalfx-present-runs-on-the-games-queue-inside-its-frame). - **Resolved, two stale chain folders held 4.4 GB:** [Old shader library folders grew a game's build folder with each chain change](../../../docs/reference/shaders.md#old-shader-library-folders-grew-a-games-build-folder-with-each-chain-change). diff --git a/dm/gfx/nvn/hle_nvn.c b/dm/gfx/nvn/hle_nvn.c index 3ad101e494..f3d01c2e32 100644 --- a/dm/gfx/nvn/hle_nvn.c +++ b/dm/gfx/nvn/hle_nvn.c @@ -2038,7 +2038,11 @@ NVN(nvnQueuePresentTexture, void, NVNqueue *q, NVNwindow *w, int idx) { // The display-link tick that took this frame: its target display time (same base as @pres_at_ms, so @pres_at_ms − @link_target_ms is how late the system showed it), the callback's lead // before that target, the callbacks since the previous frame's (1 = every tick took a frame) and the longest interval between them (33 ms on a 60 Hz link = a refresh the link skipped) double lt, ll, lg; int lk; - if (g_tsv && mtl_link_tick(n, <, &ll, &lk, &lg)) { trow(f - 8, "@link_target_ms", lt * 1e3 - g_t0_ns / 1e6); trow(f - 8, "@link_lead_ms", ll); trow(f - 8, "@link_ticks", lk); trow(f - 8, "@link_gap_ms", lg); } } + if (g_tsv && mtl_link_tick(n, <, &ll, &lk, &lg)) { trow(f - 8, "@link_target_ms", lt * 1e3 - g_t0_ns / 1e6); trow(f - 8, "@link_lead_ms", ll); trow(f - 8, "@link_ticks", lk); trow(f - 8, "@link_gap_ms", lg); } + // Where that callback spent its time (mtl_link_detail): @link_slack_ms (submission deadline minus the present call), @link_wait_ms (snapshot / producer waits), @link_alloc_ms, + // @link_run_ms (entry to exit), @link_idle_ms (since the previous callback exited), @link_held_ms (longest callback that took no frame since the previous present), @link_lock_ms + double lv[7]; static const char *ln[7] = {"@link_slack_ms", "@link_wait_ms", "@link_alloc_ms", "@link_run_ms", "@link_idle_ms", "@link_held_ms", "@link_lock_ms"}; + if (g_tsv && mtl_link_detail(n, lv)) for (int i = 0; i < 7; i++) trow(f - 8, ln[i], lv[i]); } if (f >= 8 && slow_on()) slow_emit(f - 8); prev_out = now_ns(); } diff --git a/dm/gfx/nvn/nvn_mtl.m b/dm/gfx/nvn/nvn_mtl.m index 86e90dfb86..6ffd40052c 100644 --- a/dm/gfx/nvn/nvn_mtl.m +++ b/dm/gfx/nvn/nvn_mtl.m @@ -11408,8 +11408,87 @@ void ts_after(void) { double mtl_presented_time(uint64_t n) { pres_ent e = g_pres[n % PRING]; return e.n == n ? e.t : 0; } // Ring of the display-link tick that took each present (written on the display-link callback thread, read 8 presents later for DM_NVN_TSV, as g_pres): its target display time // (seconds, CACurrentMediaTime base), how long before it the callback ran, the callbacks since the previous present's (1 = no tick without a frame) and the longest interval between them -typedef struct { uint64_t n; double target, lead_ms, gap_ms; int ticks; } link_ent; +// Where the callback that took a present spent its time (ms): the submission deadline's slack (update.targetTimestamp − the present call: negative = past it), the snapshot and +// external-producer waits, present_now's allocator wait, the callback's own run (entry to exit), the idle time since the previous callback exited (near 0 = the previous one ran +// up to this one), the longest held callback since the previous present and the wait for g_pq_mu. They tell a tick the system did not deliver from one our own callback delayed +typedef struct { uint64_t n; double target, lead_ms, gap_ms; int ticks; double slack_ms, wait_ms, alloc_ms, run_ms, idle_ms, held_ms, lock_ms; } link_ent; static link_ent g_link_ring[PRING]; +// The screen moving under the display link (DM_PRESENT_RESYNC=1, default; 0 off). Measured on Breath of the Wild in fullscreen on a ProMotion Mac (DM_NVN_TSV, runs 4-10): at one +// frame (87, 251, 342, 355 s into a session, no timer of ours) the system starts showing every frame exactly 4.17 ms (1/240 s) after the link's target and keeps that offset; +// nothing on our side changes at that frame. From then on the link calls back a tick late about every 11-12 frames: our callbacks run 0.16 ms with no wait and present 8.1 ms +// before their deadline, and the link thread sits idle 20.7 ms before each late one (run 9). That costs 56 fps on the 60 Hz link and 58.6 on the 120 Hz link, at frame latency +// 2 and 1 alike, and a link made again keeps the offset. Without the link (mode 0: the present thread takes drawables and presents each frame for its period) the game held +// 60.03 fps for 15 minutes (run 10). So once LINK_SHIFT_N presents in a row were shown LINK_SHIFT_MS or more after their targets (three quarters of them; a frame a whole refresh +// late is a miss of its own; half of them, as when run 6's offset flipped each second at 60 fps, is not the steady shift), a 60 fps game leaves the link for mode 0, where it +// fits (link_leave_ok): fullscreen on a variable-refresh screen, which shows a frame when it is presented, at any rate. Fixed-rate screens (frame latency 1, where the shift was +// not seen) and windows keep the link; leaving those conditions takes pacing back to it. What the system changes at the shift is open (docs/reference/frame-rate.md) +#define LINK_SHIFT_N 120 +#define LINK_SHIFT_MS 2.0 +typedef struct { int late, n; } link_shift_t; +static int link_shift_judge(link_shift_t *s, double late_ms) { // one presented frame: 1 when a full window was steadily shown after its targets + s->n++; s->late += late_ms >= LINK_SHIFT_MS; + if (s->n < LINK_SHIFT_N) return 0; + int late = s->late >= LINK_SHIFT_N * 3 / 4; s->n = s->late = 0; + return late; +} +// Pacing may leave the display link for the screen's shift: fullscreen on a variable-refresh screen, at any rate. Not on a fixed-rate screen, not in a window +static int link_leave_ok(int fullscreen, int variable) { return fullscreen && variable; } +// The offset of the frames on screen against their targets, and when it moves (the log line that dates the system's shift): level is the settled offset; a new one (cand) settles +// after LINK_OFFSET_N presents within 1 ms of it. Isolated presents at neither are skipped (after the shift about one in twelve is on its target, and a few a refresh off); three in a +// row at the old level, or three in a row at neither, start the count again. Returns 1 on the present that settles it, with *first the first present at it and *was the offset before +#define LINK_OFFSET_N 30 +#define LINK_OFFSET_LOG 8 +typedef struct { double level, cand; int have, n, back, odd; uint64_t first; } link_offset_t; +static int link_offset_note(link_offset_t *o, double late_ms, uint64_t pn, uint64_t *first, double *was) { + if (!o->have) { o->level = late_ms; o->have = 1; return 0; } + if (fabs(late_ms - o->level) < 1.0) { if (++o->back >= 3) o->n = 0; return 0; } + o->back = 0; + if (o->n && fabs(late_ms - o->cand) >= 1.0) { if (++o->odd >= 3) o->n = 0; else return 0; } + if (!o->n) { o->cand = late_ms; o->n = 1; o->odd = 0; o->first = pn; return 0; } + o->odd = 0; + if (++o->n < LINK_OFFSET_N) return 0; + *first = o->first; *was = o->level; o->level = o->cand; o->n = 0; return 1; +} +__attribute__((weak)) int front_fullscreen(void); +__attribute__((weak)) int front_screen_variable_refresh(void); +__attribute__((weak)) int front_screen_max_fps(void); +static int link_latency(void); +static link_shift_t g_link_shift; static link_offset_t g_link_offset; static int g_link_moved, g_link_leave; // under g_pq_mu; moved: pacing left the link (mode 0) because of the shift; leave: the presented handler asks link_sync to leave it +static int link_resync_on(void) { static int v = -1; if (v < 0) { const char *e = getenv("DM_PRESENT_RESYNC"); v = !(e && !strcmp(e, "0")); } return v; } +static void link_late_note(uint64_t pn, double presented) { // a frame's actual presentation time against its display-link target (the presented handler, under g_pq_mu) + link_ent e = g_link_ring[pn % PRING]; if (e.n != pn || !(presented > 0) || !(e.target > 0)) return; + double late_ms = (presented - e.target) * 1e3; if (late_ms > 20) return; // a frame shown a whole refresh late or more is a miss of its own (a stall, a heavy frame), not the grid + int fs = front_fullscreen(), vrr = front_screen_variable_refresh(), hz = front_screen_max_fps(); uint64_t first; double was; + static unsigned moves, quiet; static uint64_t quiet_at; // the first LINK_OFFSET_LOG moves in full, then a count a minute (Breath of the Wild run 6: the offset went 0 ↔ 4.15 ms about once a second for four minutes) + if (link_offset_note(&g_link_offset, late_ms, pn, &first, &was)) { + uint64_t t = now_ns(); + if (++moves <= LINK_OFFSET_LOG) { + pres_ent f2 = g_pres[(pn - 2) % PRING]; double cb = e.target - e.lead_ms / 1e3; + MLOG("display link: frames now reach the screen %.2f ms after the link's targets (was %.2f) from present %llu; callback %.2f ms after present %llu reached the screen, lead %.2f ms; screen %d Hz %s, %s, frame latency %d, pacing mode %d", + g_link_offset.level, was, (unsigned long long)first, f2.n == pn - 2 && f2.t > 0 ? (cb - f2.t) * 1e3 : -1.0, + (unsigned long long)(pn - 2), e.lead_ms, hz, vrr ? "variable refresh" : "fixed refresh", fs ? "fullscreen" : "window", link_latency(), g_dm_present_link); + if (moves == LINK_OFFSET_LOG) quiet_at = t + 60000000000ull; + } else if (++quiet && t >= quiet_at) { + MLOG("display link: the frames' offset against the link's targets moved %u more times in the last minute or more (now %.2f ms)", quiet, g_link_offset.level); + quiet = 0; quiet_at = t + 60000000000ull; + } + } + // Mode 1 only: 1 is the default; 2 (120 Hz link) is a DM_PRESENT_LINK choice, which keeps the link though it also loses frames after the shift (58.6 fps) + if (!link_resync_on() || g_link_moved || g_link_leave || g_dm_present_link != 1 || !link_shift_judge(&g_link_shift, late_ms)) return; + if (link_leave_ok(fs, vrr) && mtl_fps_target() == 60) { + // Only a request: link_sync, on the game's present thread, sets the mode and invalidates the link in one step. Setting the mode here would stop the callback taking frames + // while the link still owns the layer, and a game waiting in mtl_present_wait for an untaken frame would wait forever (the ticking link keeps the stall drop from firing) + g_link_leave = 1; + MLOG("display link: %d presents shown %.2f ms after their targets: pacing leaves the link at the next present, the present thread presents each frame (DM_PRESENT_LINK=0)", LINK_SHIFT_N, g_link_offset.level); + } else { + static int said; if (!said++) MLOG("display link: %d presents shown %.2f ms after their targets; pacing stays on the link (screen %d Hz %s, %s: leaving it needs fullscreen on a variable-refresh screen and a 60 fps game)", + LINK_SHIFT_N, late_ms, hz, vrr ? "variable refresh" : "fixed refresh", fs ? "fullscreen" : "window"); + } +} +int mtl_link_detail(uint64_t n, double v[7]) { // link_ent's callback timing for the n-th present: slack, wait, alloc, run, idle, held, lock (ms); 0 when there is none + link_ent e = g_link_ring[n % PRING]; if (e.n != n || !(e.run_ms > 0)) return 0; + v[0] = e.slack_ms; v[1] = e.wait_ms; v[2] = e.alloc_ms; v[3] = e.run_ms; v[4] = e.idle_ms; v[5] = e.held_ms; v[6] = e.lock_ms; return 1; +} int mtl_link_tick(uint64_t n, double *target, double *lead_ms, int *ticks, double *gap_ms) { link_ent e = g_link_ring[n % PRING]; if (e.n != n) return 0; *target = e.target; *lead_ms = e.lead_ms; *ticks = e.ticks; *gap_ms = e.gap_ms; return 1; @@ -11689,6 +11768,8 @@ static void present_gpu_note(double s, int fx) { // fx: 0 bilinear, 1 MetalFX static double g_link_it_tin; // Enqueue time of the frame the display-link callback is presenting (read and written only on the display-link thread) static int snap_up_for(int slot, uint64_t gen, NSUInteger dw, NSUInteger dh, MTLPixelFormat pf, id *up, MTLViewport *vp); // the snapshot ring (below) static void snap_up_stale(int slot, uint64_t gen); +// For the display-link timing rows (link_ent): present_now's last wait for its command allocator and the time it called present (CACurrentMediaTime, seconds) +static double g_pn_alloc_s, g_pn_present_at; static int present_now(const tex_t *t, double period, uint64_t frame, uint64_t ticket, const int crop[4], id supplied, double target_ts, int up_slot, uint64_t up_gen) { if (g_present_stall_ns) { struct timespec ts = {0, (long)g_present_stall_ns}; nanosleep(&ts, NULL); } g_present_n++; @@ -11754,10 +11835,13 @@ static int present_now(const tex_t *t, double period, uint64_t frame, uint64_t t if (!supplied) g_drawable_ns += now_ns() - dt0; if (!dr) return 0; int alloc_i = (int)(ticket % 3); + g_pn_alloc_s = 0; if (g_present_alloc_fence[alloc_i]) { + double a0 = CACurrentMediaTime(); pthread_mutex_lock(&g_pq_mu); while (g_present_alloc_done[alloc_i] < g_present_alloc_fence[alloc_i]) pthread_cond_wait(&g_pq_cv, &g_pq_mu); pthread_mutex_unlock(&g_pq_mu); + g_pn_alloc_s = CACurrentMediaTime() - a0; } [g_present_alloc4[alloc_i] reset]; [g_q4 waitForDrawable:dr]; @@ -11809,8 +11893,10 @@ static int present_now(const tex_t *t, double period, uint64_t frame, uint64_t t [dr addPresentedHandler:^(id d) { // Actual presentation time (the time this frame is really put on screen, CACurrentMediaTime base) CFTimeInterval tt = d.presentedTime; g_pres[pn % PRING] = (pres_ent){pn, tt > 0 ? tt : -1}; + pthread_mutex_lock(&g_pq_mu); link_late_note(pn, tt); pthread_mutex_unlock(&g_pq_mu); // against the display link's target for this frame (the screen moving under the link) }]; // Each frame is displayed for at least one present period: when the GPU completion time jitters around a 120 Hz refresh boundary, the paired "25 ms + 8.33 ms" stutter no longer appears + g_pn_present_at = CACurrentMediaTime(); if (target_ts > 0) [dr present]; else if (period > 0) [dr presentAfterMinimumDuration:period]; else [dr present]; #endif @@ -11850,14 +11936,26 @@ @interface NvMetalDisplayLinkDelegate : NSObject #define LINK_RESCUE_NS 500000000ull static _Atomic int g_rescue_mode; // Also read by link_on without g_pq_mu, to stop pacing on silent ticks immediately static uint64_t g_rescue_back_at, g_rescue_back_ns = 3000000000ull, g_rescue_n; +static int link_takes(void) { return g_dm_present_link && !g_rescue_mode; } // under g_pq_mu: the display-link callback takes queued frames (mode and rescue change only in link_sync and mtl_present_wait, on the game's threads) // The display link watchdog only recognizes the "active" state: when the App loses active status (pulling down Control Center / notifications, incoming call, system popup) and in the background the system does not call back anyway, and the picture is covered too -- the frame-drop fallback stays as before, // but it is not counted as stuck and no failure is reported; the stall is measured from the later of "the most recent callback / the most recent activation" (A16 logs: 8–17 seconds inactive and 17 seconds in the background were both reported as "stuck in foreground") __attribute__((weak)) int dm_focus_now(void) { return 1; } // The host's hle_oe.c provides the strong definition; when graphics unit tests do not link the host it is treated as always active __attribute__((weak)) uint64_t dm_focus_in_since(void) { return 0; } +// One tick of the display link in seconds: a counted virtual tick (link_range) or one callback at the link's rate (120, 60 or 30 Hz) +static double link_tick_s(void) { return g_link_vperiod > 0 ? g_link_vperiod : 1.0 / mtl_link_rate(); } +// How long the link callback keeps a presented frame on screen before it takes the next one: the frame's present period when that covers two or more of the link's ticks, 0 when +// the next tick may take a frame. Measured in the link's own ticks, not in 60 Hz vsyncs: a 60 fps game's 16.7 ms frame on a 120 Hz link (DM_PRESENT_LINK=2) holds two ticks, as an +// interval-2 frame holds two on a 60 Hz link. A fixed "period > 25 ms" let every 120 Hz tick take a frame: with present snapshots, where the ring slot each present frees paces +// the game, Breath of the Wild then ran one frame per 8.3 ms tick at 1.16 of real time (87 fps, game time 30.3 s in 26.0 s) on the 120 Hz link +static double link_hold_s(double period) { double tick = link_tick_s(); return tick > 0 && period > 1.5 * tick ? period : 0; } +// The callback's run on every return (link_ent): when it exited, and the longest run of the callbacks that took no frame since the previous present +static double g_cb_exit, g_cb_held_max; static int g_cb_took; +static void link_cb_done(double *entry) { double t = CACurrentMediaTime(); if (!g_cb_took && t - *entry > g_cb_held_max) g_cb_held_max = t - *entry; g_cb_exit = t; } @implementation NvMetalDisplayLinkDelegate - (void)metalDisplayLink:(CAMetalDisplayLink *)link needsUpdate:(CAMetalDisplayLinkUpdate *)update { (void)link; - double cb = CACurrentMediaTime(); + double cb = CACurrentMediaTime(), idle = g_cb_exit > 0 ? cb - g_cb_exit : -1; + __attribute__((cleanup(link_cb_done))) double cb_entry = cb; g_cb_took = 0; pthread_mutex_lock(&g_pq_mu); if (g_stall_t0) { uint64_t since = dm_focus_in_since(), t = now_ns(); MLOG("display link recovered: stalled %.0f ms (%.0f ms of it active), fallback dropped %llu frames (stall #%llu)", (t - g_stall_t0) / 1e6, (t - (g_stall_t0 > since ? g_stall_t0 : since)) / 1e6, (unsigned long long)g_stall_drop, (unsigned long long)g_stall_n); g_stall_t0 = 0; } @@ -11877,9 +11975,11 @@ - (void)metalDisplayLink:(CAMetalDisplayLink *)link needsUpdate:(CAMetalDisplayL g_link_tick_n++; pthread_cond_broadcast(&g_link_cv); pthread_mutex_unlock(&g_link_mu); + double l0 = CACurrentMediaTime(); pthread_mutex_lock(&g_pq_mu); - if (!g_dm_present_link || g_rescue_mode || g_pq_read == g_pq_in) { if (g_dm_present_link && !g_rescue_mode) g_link_empty++; pthread_mutex_unlock(&g_pq_mu); return; } - // The previous frame's present interval was >= 2 (period > 25 ms): keep it on screen for its whole period before taking the next one, as the Switch flips only every N vertical syncs. This also holds while the link runs at 60 Hz (Mario 1.2.1 sets 2 for single frames, see nvn_game_fps in hle_nvn.c); + double lock_s = CACurrentMediaTime() - l0; + if (!link_takes() || g_pq_read == g_pq_in) { if (link_takes()) g_link_empty++; pthread_mutex_unlock(&g_pq_mu); return; } + // The previous frame's period covers two or more link ticks (link_hold_s: interval >= 2, or any 60 fps frame on a 120 Hz link): keep it on screen for its whole period before taking the next one, as the Switch flips only every N vertical syncs. This also holds while the link runs at 60 Hz (Mario 1.2.1 sets 2 for single frames, see nvn_game_fps in hle_nvn.c); // before, every tick took the newest frame, so that frame, carrying the extra time step the game advanced for it, was shown for only 16.7 ms and the game looked like it jumped ahead if (g_link_hold_until > 0 && update.targetPresentationTimestamp < g_link_hold_until - tol) { g_link_held++; pthread_mutex_unlock(&g_pq_mu); return; } uint64_t first = g_pq_read + 1, ticket = g_pq_in; @@ -11893,12 +11993,20 @@ - (void)metalDisplayLink:(CAMetalDisplayLink *)link needsUpdate:(CAMetalDisplayL if (ticket > first) { g_link_dropped += ticket - first; for (uint64_t k = first; k < ticket; k++) g_pres[k % PRING] = (pres_ent){k, -1}; } // Old frames merged and dropped are recorded as "not presented", so the present statistics honestly count them as dropped frames if (ticket > 1 && g_pq_done < ticket - 1) g_pq_done = ticket - 1; g_link_ring[ticket % PRING] = (link_ent){ticket, update.targetPresentationTimestamp, (update.targetPresentationTimestamp - cb) * 1e3, gap_max * 1e3, nticks}; nticks = 0; gap_max = 0; + double held_s = g_cb_held_max; g_cb_held_max = 0; g_cb_took = 1; pthread_cond_broadcast(&g_pq_cv); pthread_mutex_unlock(&g_pq_mu); int submitted; + double w0 = CACurrentMediaTime(); ext_wait(it.ev_val); snap_commit_wait(it.snap_v); + double wait_s = CACurrentMediaTime() - w0; g_pn_present_at = 0; g_pn_alloc_s = 0; @autoreleasepool { submitted = present_now(&it.t, it.period, it.frame, ticket, it.crop, update.drawable, update.targetPresentationTimestamp, it.up_slot, it.up_gen); } - g_link_hold_until = submitted && it.period > 0.025 ? update.targetPresentationTimestamp + it.period : 0; + { // written without g_pq_mu (the fields above are written under it): only this callback writes them, and hle_nvn.c reads them 8 presents later + link_ent *le = &g_link_ring[ticket % PRING]; double t1 = CACurrentMediaTime(); + le->slack_ms = g_pn_present_at > 0 ? (update.targetTimestamp - g_pn_present_at) * 1e3 : -999; le->wait_ms = wait_s * 1e3; le->alloc_ms = g_pn_alloc_s * 1e3; + le->run_ms = (t1 - cb) * 1e3; le->idle_ms = idle * 1e3; le->held_ms = held_s * 1e3; le->lock_ms = lock_s * 1e3; + } + double hold = submitted ? link_hold_s(it.period) : 0; g_link_hold_until = hold > 0 ? update.targetPresentationTimestamp + hold : 0; if (!submitted) { pthread_mutex_lock(&g_pq_mu); if (ticket > g_pq_done) g_pq_done = ticket; @@ -11966,6 +12074,12 @@ static void link_sync(void) { // Called every frame by the game's present thre g_rescue_mode = 0; g_stall_t0 = 0; __atomic_store_n(&g_link_tick_ns, now_ns(), __ATOMIC_RELAXED); MLOG("display link: rescue ended, trying pacing mode %d (frame %llu)", want, (unsigned long long)atomic_load(&g_cur_frame)); } + if (g_link_leave) { g_link_leave = 0; if (want == 1 && !g_rescue_mode) { g_dm_present_link = want = 0; g_link_moved = 1; } } // asked by link_late_note; a mode set meanwhile wins + else if (g_link_moved && want) { g_link_moved = 0; g_link_shift = (link_shift_t){0}; } // a runtime setting (DM_AB, the settings) put pacing back on a link: it wins, and the shift is judged afresh + if (g_link_moved && (!link_leave_ok(front_fullscreen(), front_screen_variable_refresh()) || mtl_fps_target() != 60)) { // left for the shift (link_late_note), and the screen, window or rate no longer fits it + g_link_moved = 0; g_dm_present_link = want = 1; g_link_shift = (link_shift_t){0}; + MLOG("display link: pacing back on the link (screen %d Hz %s, %s)", front_screen_max_fps(), front_screen_variable_refresh() ? "variable refresh" : "fixed refresh", front_fullscreen() ? "fullscreen" : "window"); + } if (g_rescue_mode) want = 0; pthread_mutex_unlock(&g_pq_mu); if (want && mtl_fps_target() == 30) want = 3; // Power-saving mode: display link at 30 Hz diff --git a/dm/gfx/nvn/nvn_obj.h b/dm/gfx/nvn/nvn_obj.h index 1a17f06304..8091eca975 100644 --- a/dm/gfx/nvn/nvn_obj.h +++ b/dm/gfx/nvn/nvn_obj.h @@ -224,6 +224,7 @@ int mtl_link_wait_tick(int vsyncs, uint64_t timeout_ns); // vsyncs = the game' int mtl_link_wait_ticks(int ticks, uint64_t timeout_ns); // the same in the display link's own ticks int mtl_link_rate(void); // the display link's rate: 120, 60 or 30 Hz double mtl_presented_time(uint64_t n); +int mtl_link_detail(uint64_t n, double v[7]); // where the callback that took the n-th present spent its time (ms): slack, wait, alloc, run, idle, held, lock (nvn_mtl.m link_ent); 0 = none int mtl_link_tick(uint64_t n, double *target, double *lead_ms, int *ticks, double *gap_ms); // the display-link tick that took the n-th present (0 = none: no display link, or not taken yet) int mtl_link_stalled(void); // the display link is silent (background, occluded window, a stall) and queued frames are dropped instead of shown int mtl_snap_on(void); uint64_t mtl_snap_acquire_wait(void); // present snapshots (DM_PRESENT_SNAP): on, and acquire's wait for ring capacity (returns ns spent pacing) diff --git a/dm/gfx/tests/t_link_ticks.m b/dm/gfx/tests/t_link_ticks.m index 33ef1d9224..7531e84ec0 100644 --- a/dm/gfx/tests/t_link_ticks.m +++ b/dm/gfx/tests/t_link_ticks.m @@ -61,6 +61,13 @@ static void acquire_ticks(int hz, int display, int interval, double want, const printf("%s: %.2f ticks per acquire (expected %.2f)\n", label, got, want); CHECK(got == want, label); } +// The link callback's hold, simulated on its tick grid with its 2 ms tolerance: how many ticks after the one that presented a frame of this period take no new frame +static int held(int mode, double period) { + g_link_mode = mode; g_link_vperiod = 0; + double hold = link_hold_s(period), t0 = 100.0, until = hold > 0 ? t0 + hold : 0, tick = link_tick_s(); int n = 0; + if (until > 0) while (t0 + (n + 1) * tick < until - 0.002) n++; + return n; +} int main(void) { @autoreleasepool { setenv("DM_RT", "0", 1); setenv("DM_PRESENT_SNAP", "0", 1); // Test uncapped display pacing independently of the selected game's default. @@ -111,5 +118,51 @@ int main(void) { @autoreleasepool { CHECK(g_link_tick_n == tick && test_now - start == 5000000ull, "timeout reaches its deadline without inventing ticks"); test_silent = 0; CHECK(mtl_link_wait_ticks(2, 10000000ull) && g_link_tick_n - tick == 2, "ticks resume from the last successful wait after timeout"); + { // The hold of the link callback (link_hold_s): a presented frame stays on screen for its whole period when that covers two or more of the link's ticks, so a 60 fps game takes + // exactly two ticks of a 120 Hz link (one frame per 16.7 ms, game time 1.000 of real time; with present snapshots the slot each present frees paces the game). Ticks are + // simulated on the callback's grid with its 2 ms tolerance: the number of ticks held is the ticks per frame minus the one that presented it + CHECK(held(2, 1.0 / 60) == 1, "a 60 fps frame on a 120 Hz link is held for the second tick: two ticks per frame"); + CHECK(held(2, 2.0 / 60) == 3, "an interval-2 frame on a 120 Hz link holds four ticks"); + CHECK(held(2, 1.0 / 120) == 0, "a 120 fps frame on a 120 Hz link takes every tick"); + CHECK(held(1, 1.0 / 60) == 0, "a 60 fps frame on a 60 Hz link takes every tick"); + CHECK(held(1, 2.0 / 60) == 1, "an interval-2 frame on a 60 Hz link holds two ticks, as before"); + CHECK(held(3, 1.0 / 30) == 0 && held(3, 1.0 / 60) == 0, "the 30 Hz power-saving link never holds a 60 or 30 fps frame"); + g_link_mode = 2; g_link_vperiod = 1.0 / 60; CHECK(link_hold_s(1.0 / 60) == 0, "counted 1/60 s virtual ticks: a 60 fps frame takes every counted tick"); + g_link_mode = 1; g_link_vperiod = 0; + } + { // The shift judge (link_late_note): frames on their targets, or half of them shifted (Breath of the Wild run 6 held 60 fps there), never move pacing; a full window of + // 120 presents with three quarters or more 2 ms late does + link_shift_t s = {0}; int due = 0; + for (int i = 0; i < 3 * LINK_SHIFT_N; i++) due += link_shift_judge(&s, 0.0); + CHECK(due == 0, "frames on their targets: pacing stays"); + for (int i = 0; i < LINK_SHIFT_N - 1; i++) due += link_shift_judge(&s, 4.17); + CHECK(due == 0, "a window is judged only when full"); + CHECK(link_shift_judge(&s, 4.17) == 1, "120 presents shown 4.17 ms late: pacing moves"); + link_shift_t m = {0}; due = 0; + for (int i = 0; i < 4 * LINK_SHIFT_N; i++) due += link_shift_judge(&m, (i / 60) % 2 ? 4.15 : 0.0); + CHECK(due == 0, "the offset flipping 0 <-> 4.15 ms each second (half the frames late) is not the steady shift"); + link_shift_t r = {0}; due = 0; // run 7 after the shift: eleven of every twelve presents 4.17 ms late, one on its target + for (int i = 0; i < LINK_SHIFT_N; i++) due += link_shift_judge(&r, i % 12 == 11 ? 0.0 : 4.17); + CHECK(due == 1, "eleven in twelve presents shifted: pacing moves"); + } + { // Where pacing may leave the link for the shift (mode 0): fullscreen on a variable-refresh screen at any rate, and nowhere else + CHECK(link_leave_ok(1, 1), "fullscreen on a variable-refresh screen (ProMotion, adaptive sync at 60-240 Hz): leaves the link"); + CHECK(!link_leave_ok(1, 0), "fullscreen on a fixed-rate screen (60, 120, 144 Hz; frame latency 1, where the shift was not seen): keeps the link"); + CHECK(!link_leave_ok(0, 1) && !link_leave_ok(0, 0), "a window: keeps the link"); + } + { // The offset tracker behind the log line: it dates the shift to its first present, skips isolated presents at the old offset or a refresh off, and stays quiet otherwise + link_offset_t o = {0}; uint64_t first = 0, pn = 0; double was = -1; int moved = 0; + for (int i = 0; i < 600; i++) moved += link_offset_note(&o, i % 50 == 7 ? 8.33 : 0.0, ++pn, &first, &was); + CHECK(moved == 0, "frames on their targets with an odd one a refresh late: no move"); + uint64_t at = pn + 1; + for (int i = 0; i < 600 && !moved; i++) moved += link_offset_note(&o, i % 12 == 11 ? 0.0 : i % 25 == 3 ? 12.5 : 4.17, ++pn, &first, &was); + CHECK(moved == 1 && first == at && was == 0.0 && o.level == 4.17, "the shift as run 7 had it (one in twelve on target, a few a refresh off): dated to its first present"); + moved = 0; + for (int i = 0; i < 600; i++) moved += link_offset_note(&o, i % 12 == 11 ? 0.0 : 4.17, ++pn, &first, &was); + CHECK(moved == 0, "the shifted offset held: no more moves"); + moved = 0; + for (int i = 0; i < 40; i++) moved += link_offset_note(&o, 0.0, ++pn, &first, &was); + CHECK(moved == 1 && was == 4.17 && o.level == 0.0, "back on the targets: one move back"); + } printf("t_link_ticks: %d checks, %d failed\n", checks, failed); return failed != 0; } } diff --git a/dm/gfx/tests/t_present_rescue.m b/dm/gfx/tests/t_present_rescue.m index 0df9fd3302..48d0e7b654 100644 --- a/dm/gfx/tests/t_present_rescue.m +++ b/dm/gfx/tests/t_present_rescue.m @@ -129,6 +129,32 @@ static void lifecycle(void) { } g_present_latency = 0; test_fullscreen = test_variable_refresh = 0; link_sync(); g_link = nil; g_link_started = 0; } +static void handoff(void) { // The shift judged while a frame waits untaken (link_late_note in the presented handler): the link keeps taking frames until link_sync, on the game's + // present thread, sets mode 0 and invalidates it. Setting the mode in the handler stopped the callback while the link still owned the layer, and the waiting game hung + reset(); test_fullscreen = 1; test_variable_refresh = 1; + SilentDisplayLink *link = [SilentDisplayLink new]; + g_link = link; g_link_started = 1; g_link_rl = CFRunLoopGetCurrent(); g_link_moved = g_link_leave = 0; g_link_shift = (link_shift_t){0}; g_link_offset = (link_offset_t){0}; + link_sync(); + g_pq_in = 2; g_pq_read = 1; g_pq_done = 0; // frame 1 on its way to the screen, frame 2 queued and not yet taken: what the game waits for at its next acquire + int fired = 0; + for (uint64_t pn = 1000; pn < 1000 + 4 * LINK_SHIFT_N && !g_link_leave; pn++) { + double target = pn / 60.0; + g_link_ring[pn % PRING] = (link_ent){.n = pn, .target = target}; + pthread_mutex_lock(&g_pq_mu); link_late_note(pn, target + 1.0 / 240); fired = g_link_leave; pthread_mutex_unlock(&g_pq_mu); + } + CHECK("the steady 1/240 s shift asks to leave the link", fired); + pthread_mutex_lock(&g_pq_mu); int takes = link_takes(); pthread_mutex_unlock(&g_pq_mu); + CHECK("after the request the link still takes the waiting frame", takes && g_dm_present_link == 1 && g_link_owns_layer); + link_sync(); + CHECK("the next present's link_sync moves to mode 0", g_dm_present_link == 0 && g_link_moved && !g_link_leave && !g_link); + pthread_mutex_lock(&g_pq_mu); takes = link_takes(); pthread_mutex_unlock(&g_pq_mu); + CHECK("the link stops taking frames only once mode 0 is applied", !takes); + CFRunLoopRunInMode(kCFRunLoopDefaultMode, 0.01, false); + CHECK("its run loop invalidates it and gives the layer to the present thread", link.invalidated && !g_link_owns_layer); + g_dm_present_link = 1; link_sync(); + CHECK("a runtime setting back on the link wins over the move", !g_link_moved && g_dm_present_link == 1); + test_fullscreen = test_variable_refresh = 0; g_link = nil; g_link_started = 0; g_link_owns_layer = 0; +} static void metal_lifecycle(void) { id device = MTLCreateSystemDefaultDevice(); CHECK("Metal device available", device != nil); if (!device) return; @@ -147,7 +173,7 @@ static void metal_lifecycle(void) { int main(int argc, char **argv) { @autoreleasepool { alarm(10); setbuf(stdout, NULL); if (argc > 2 || (argc == 2 && strcmp(argv[1], "--metal"))) return 2; - thresholds(); backoff(); settings(); lifecycle(); latency(); + thresholds(); backoff(); settings(); lifecycle(); latency(); handoff(); if (argc == 2) metal_lifecycle(); printf("present rescue: %d checks, %d failed\n", checks, failed); return failed != 0; } } diff --git a/dm/tools/lint_c_baseline.tsv b/dm/tools/lint_c_baseline.tsv index cdb8141ecf..23c0565b7f 100644 --- a/dm/tools/lint_c_baseline.tsv +++ b/dm/tools/lint_c_baseline.tsv @@ -25,10 +25,10 @@ dm/gfx/nvn/nvn_mtl.m bugprone-misplaced-widening-cast 1 dm/gfx/nvn/nvn_mtl.m bugprone-signed-char-misuse 1 dm/gfx/nvn/nvn_mtl.m bugprone-suspicious-memory-comparison 8 dm/gfx/nvn/nvn_mtl.m bugprone-suspicious-realloc-usage 20 -dm/gfx/nvn/nvn_mtl.m clang-analyzer-core.NullDereference 12 +dm/gfx/nvn/nvn_mtl.m clang-analyzer-core.NullDereference 11 dm/gfx/nvn/nvn_mtl.m clang-analyzer-core.uninitialized.Assign 2 dm/gfx/nvn/nvn_mtl.m clang-analyzer-nullability.NullableDereferenced 5 -dm/gfx/nvn/nvn_mtl.m clang-analyzer-nullability.NullablePassedToNonnull 15 +dm/gfx/nvn/nvn_mtl.m clang-analyzer-nullability.NullablePassedToNonnull 14 dm/gfx/nvn/nvn_mtl.m clang-analyzer-osx.cocoa.RetainCount 2 dm/gfx/nvn/nvn_mtl.m clang-analyzer-security.ArrayBound 2 dm/gfx/nvn/nvn_mtl.m clang-analyzer-unix.cstring.NullArg 4 diff --git a/docs/agents/symptoms.md b/docs/agents/symptoms.md index f15853e5df..3f905aa796 100644 --- a/docs/agents/symptoms.md +++ b/docs/agents/symptoms.md @@ -355,6 +355,7 @@ One line per symptom in the [subsystem references](../reference/): what you see - a Mac game started with `DM_FULLSCREEN=1` from an app that is itself in fullscreen (the launcher's console mode) came up as a window. → [A game opened from a fullscreen app stays a window](../reference/frame-rate.md#a-game-opened-from-a-fullscreen-app-stays-a-window) - on a ProMotion built-in screen, only in fullscreen, the frame step went 1 → 2 → 3 vsyncs on frames costing 0.1–0.6 vsyncs (`3 late frames; cost 0.32 vsyncs`) and the game presented 15 frames a second; a window, or the screen set to a fixed 60 Hz, did not do it. The `DM_NVN_TSV` rows show presents shown one 120 Hz refresh late (`@pres_at_ms` − `@link_target_ms` = 8.3 ms) with a skipped tick after each (`@link_gap_ms` 33 ms), and `@link_lead_ms` about 16 ms against about 50 ms in a window. → [Frame latency 2 for the display link in fullscreen](../reference/frame-rate.md#frame-latency-2-for-the-display-link-in-fullscreen) - on a MacBook Air M2's fixed 60 Hz built-in display, the reporter measured about 50 ms from the game's present call to on-screen presentation with the display link, at both requested frame latencies 1 and 2, versus 29 ms with `DM_PRESENT_LINK=0`. After loading, all three runs held 60 fps with 0.3% of on-screen intervals outside 16.7 ± 2 ms and no frame-step changes. → [Fixed-rate display-link delay remains at latency 1](../reference/frame-rate.md#fixed-rate-display-link-delay-remains-at-latency-1) +- a Mac game in fullscreen on a ProMotion screen runs at 60 fps and then, from one moment to the rest of the session, at 56 fps whatever the scene: GPU and CPU far inside the frame, `@sync_ms` 0, no step up. In `DM_NVN_TSV` `@pres_at_ms − @link_target_ms` goes from 0.0 to 4.17 ms on every frame, `@link_lead_ms` falls 32.9 → 28.7 ms, and about every 12th frame has `@link_gap_ms` near 24.6 ms with `@presented_ms` 25 then 20.8 ms. Moving the mouse makes it worse. → [The display link loses ticks when the screen shifts 1/240 s under it](../reference/frame-rate.md#the-display-link-loses-ticks-when-the-screen-shifts-1240-s-under-it) - autorelease work takes a measurable share of replay time, with temporary arena-buffer ownership traffic a few times per draw. → [Arena buffer ownership on allocation](../reference/frame-rate.md#arena-buffer-ownership-on-allocation) - the submit thread waits on the texture / sampler registry lock while a lower-priority registration thread is preempted holding it. → [Registry lock priority inheritance](../reference/frame-rate.md#registry-lock-priority-inheritance) - in a replay profile, `_platform_memcmp` is most of the time spent in serial lookups (`tex_mtl` through `g_by_serial`). → [Hash-table lookups of 8-byte keys](../reference/frame-rate.md#hash-table-lookups-of-8-byte-keys) diff --git a/docs/env_switches.tsv b/docs/env_switches.tsv index d22f391db6..8c02c61dd1 100644 --- a/docs/env_switches.tsv +++ b/docs/env_switches.tsv @@ -208,6 +208,7 @@ DM_PRESENT_HZ switch `=`: the frequency of presentation pacing (default 60); DM_PRESENT_INTERVAL switch `display` presents one frame per display-link tick whatever interval the game sets; `game` follows the game's present interval (default: the profile's `present_interval`) DM_PRESENT_LATENCY switch `=1` or `2`: overrides the display link's preferred frame latency for every screen and window mode; larger positive values use 2 (default 2 in variable-refresh fullscreen, 1 otherwise) DM_PRESENT_LINK switch Present pacing: `0` acquires the drawable itself, `1` (the default) presents on a 60 Hz display link, `2` uses a 120 Hz display link with a frame every other tick +DM_PRESENT_RESYNC switch `0` keeps pacing on the display link for the whole session; by default, when 120 presents in a row reached the screen 2 ms or more after the link's targets (three quarters of them) in fullscreen on a variable-refresh screen, a 60 fps game leaves the link for the present thread (mode 0) DM_PRESENT_SNAP player `=`: present snapshots, a ring of n host textures (2 to 4; `1` = 2) the presents are copied to so the game's swapchain texture is free at once; `0` off (default: the profile's `present_snap`) DM_PRESENT_UPSCALE player `metalfx` scales a picture smaller than its rectangle on the screen through MetalFX's spatial scaler; `off` (the default) scales it bilinearly; `ab` alternates the two with `DM_AB` (the scaler's GPU time runs on the game's queue, in its frame: `@present_gpu_ms`) DM_PROBE diagnostic `=module:offset,…` (Mac only): puts a `brk` at each guest address and on every hit prints the thread, registers, strings they point to and a backtrace, then runs the original instruction diff --git a/docs/reference/frame-rate.md b/docs/reference/frame-rate.md index 9d4133b8bd..fcd9a51cee 100644 --- a/docs/reference/frame-rate.md +++ b/docs/reference/frame-rate.md @@ -284,6 +284,14 @@ Frame pacing: the host's frame step, engine frame limiters, present intervals an - **Fix:** **open**. Fixed-rate screens now request latency 1 by default, as described [above](#frame-latency-2-for-the-display-link-in-fullscreen); this only corrects the workaround's scope. The display link remains enabled, and the remaining presentation delay needs its own diagnosis. - **Found on:** [issue #822](https://github.com/seedds/nxnative/issues/822), Lollipop Chainsaw RePOP (`0100DD301A686000`, [PR #684](https://github.com/seedds/nxnative/pull/684)'s profile), macOS 27, `--platform mac-app`. +### The display link loses ticks when the screen shifts 1/240 s under it + +- **Symptom:** a Mac game in fullscreen on a ProMotion screen runs at 60 fps and then, from one moment to the rest of the session, at 56 fps whatever the scene: GPU and CPU far inside the frame, `@sync_ms` 0, no step up. In `DM_NVN_TSV` `@pres_at_ms − @link_target_ms` goes from 0.0 to 4.17 ms on every frame, `@link_lead_ms` falls 32.9 → 28.7 ms, and about every 12th frame has `@link_gap_ms` near 24.6 ms with `@presented_ms` 25 then 20.8 ms. Moving the mouse makes it worse. +- **Cause (the trigger is open):** at one frame the system starts showing every frame exactly 4.17 ms (1/240 s) after the display link's target and keeps that offset. Nothing on the host side changes at that frame: in run 7 frame 20813 took 16.3 ms of work, its GPU work ended 58 ms before its target, and its callback ran 33 ms ahead as before. The moment differs per session (87, 251, 342 and 355 s), so it is no timer of ours; declaring the controller's input as user activity (`IOPMAssertionDeclareUserActivity`; macOS counts only keyboard and mouse) did not prevent it in a run. The offset alone costs nothing: frames 20814–20823 were all shifted and still 16.67 ms apart, and in run 6 the offset flipped 0 ↔ 4.15 ms about once a second for four minutes at 60 fps. Once it holds, the link calls back a tick late about every 11–12 frames: on the 60 Hz link at frame latency 2 the callback, which had started 0.43 ms after the frame two back reached the screen (p10–p90 0.37–0.47 ms over 18,800 frames, also the link's own schedule), now follows that flip 4.17 ms behind its schedule and every 12th tick comes 8 ms late (12.5 ms lost in every 200 ms, 56.5 fps); on the 120 Hz link one callback in 11 comes 4.17 ms late (58.6 fps), at frame latency 2 and 1 alike. Our side is idle then: the callback timing rows of 200 such frames show our callbacks running 0.16 ms with no wait, each present 8.1 ms before its deadline, and the link thread idle 20.7 ms before each late callback where it waits 8.33 ms otherwise. A display link made again keeps the offset (three sessions). What the system changes at the shift, and its rule for the late callbacks, are open. +- **Fix (a workaround):** `nvn_mtl.m` `link_late_note` checks each frame's presentation time against its link target. It counts presents in windows of 120 that follow each other (not a sliding window); a present more than 20 ms late (a whole refresh, a miss of its own) or dropped is not counted, so a window can span more presents and detection can take up to about 240. When three quarters or more of a window were 2 ms or more late (half late, as in run 6's flipping, is not the steady shift and held 60 fps), a 60 fps game leaves the display link for mode 0 (the present thread takes the drawables and presents each frame for its period), logged as `pacing leaves the link` with the settled offset. The presented handler only asks for it (`g_link_leave`); `link_sync`, on the game's present thread, sets `g_dm_present_link = 0` and invalidates the link in one step, as the runtime settings do, so the link keeps taking frames until then and a game waiting in `mtl_present_wait` for one it has not taken is served. Only the default mode 1 leaves the link: `DM_PRESENT_LINK=2` (the 120 Hz link), a manual setting, keeps it although it also loses frames after the shift (58.6 fps). A runtime setting that puts pacing back on a link (`DM_AB`, the settings) wins, and the shift is judged afresh. Only where it fits (`link_leave_ok`): fullscreen on a variable-refresh screen, which shows a frame when it is presented, at any rate. Fixed-rate screens (latency 1, where the shift was not seen) and windows keep the link, logged once as `pacing stays on the link`; leaving those conditions takes pacing back to it (`pacing back on the link`). `DM_PRESENT_RESYNC=0` turns the switch off. Every move of the offset is logged with the first present at the new offset, how long after the flip of the frame two back the callback ran, the screen's rate and refresh kind, fullscreen, latency and pacing mode (`frames now reach the screen … ms after the link's targets`; the first 8 in full, then a count a minute). +- **Found on:** [The Legend of Zelda: Breath of the Wild](../../dm/games/01007EF00011E000/README.md#gpu-work) (M5 Pro, fullscreen, controller only), runs 4–11. Run 7: 60 → 56 at the shift (355 s), then 58.6 fps on the 120 Hz link; run 8 on the 120 Hz link at latency 1 the same (58.63 fps after the shift at 340 s); run 9 the callback timing rows; run 10 in mode 0 from the start: 60.03 fps in every 30 s window for 15 minutes, game time 1.000 of real time. Mode 0 has no link targets, so the shift itself cannot be dated in run 10; every earlier session had it by 87–518 s. Run 11, with no settings: the shift at 210 s, `pacing leaves the link` about 2 s later and the move to mode 0 at frame 12729, then 60.0 fps in every 30 s window for the remaining 23 minutes, game time 1.000 of real time (but for one window in which the game lost focus). +- **Check:** `t_link_ticks` (the judge: no move for frames on their targets or for the offset flipping each second, a move for run 7's pattern; `link_leave_ok` for fixed and variable refresh, window and fullscreen; the offset tracker dates run 7's shift to its first present despite one on-target frame in twelve, and moves back once), `t_present_rescue --metal`, `check_t_present_snap`. A replay of the judge and the tracker over runs 4–7's `DM_NVN_TSV` dated the shift to the frame found by hand in runs 4, 5 and 7, and the judge fired where 56 fps began in run 6 (518 s). `t_present_rescue` also checks the handoff: with the shift judged while a frame waits untaken, the link still takes it, and the next present's `link_sync` moves to mode 0 and gives the layer to the present thread. **Not checked:** external screens (60 Hz, 144/165 Hz, adaptive sync) in a run. + ## CPU cost and pacing ### Arena buffer ownership on allocation