diff --git a/dm/games/04003F40232DE000/README.md b/dm/games/04003F40232DE000/README.md index 7a06c8725f..e37961d8aa 100644 --- a/dm/games/04003F40232DE000/README.md +++ b/dm/games/04003F40232DE000/README.md @@ -1,6 +1,6 @@ # Hyrule Warriors: Age of Imprisonment (`04003F40232DE000`) -A Switch 2 game: update v196608, SDK 20.5.15 built for the Switch 2 (`Ounce`). Koei Tecmo's KTGL engine on NVN2, modules `main`, `subsdk0` (NintendoSDK_movie: VP9 movies) and `sdk`. **Plays on the Mac** from a new save through the first-run settings, the opening movies and cutscenes into the first field, where Zelda walks; the frame time's median is 16.6 ms there, with long frames every few frames on a 16 GB Mac ([Performance](#performance)). Battles have not been reached. No IPA has been built. +A Switch 2 game: update v196608, SDK 20.5.15 built for the Switch 2 (`Ounce`). Koei Tecmo's KTGL engine on NVN2, modules `main`, `subsdk0` (NintendoSDK_movie: VP9 movies) and `sdk`. **Plays on the Mac** from a new save through the first-run settings, the opening movies and cutscenes into the first field, where Zelda walks; the frame time's median is 16.6 ms there, with long frames every few frames on a 16 GB Mac ([Performance](#performance)). The first battle (the village) plays at 1x and at 2x; the first outpost mission froze the GPU once in the Mac app ([GPU hang in a battle](#gpu-hang-in-a-battle-open)). No IPA has been built. ## What it needs @@ -29,6 +29,15 @@ The rewritten modules take 62.5 MB, so the default `mem_used` (64 MB) covers the - Resolved: about 10 fps (p50 100 ms) in the field. Each dedicated c1 constant block of the partial library was a Metal buffer of its own, and the residency set's 16,118 objects made every commit slow ([Dedicated c1 constants as slices of a bank](../../../docs/reference/frame-rate.md#dedicated-c1-constants-as-slices-of-a-bank)). - Current (open): the Metal driver wires and unwires memory for each submission, 2.8 s of every 4 s in a Metal System Trace. The game's own GPU memory pool is a constant 4,655 MB (`main+0x19eb098`), with a second pool of 350 MB, and its GPU allocations total 7 GB; the 16 GB Mac had 9.7 GB wired system-wide and about 160 MB free. With fewer commits per frame (`DM_NVN_CUT=0`) p99 was 52–69 ms. A Mac with more memory has not been tried. +## GPU hang in a battle (open) + +On 2026-11-04 the Mac app froze in the first outpost mission while a special attack filled the screen, after 18 minutes at a locked 60 fps (host 48b9911e, `DM_UPSCALE=2` scaling nothing yet). The game kept running (its threads poll and wait) while the GPU showed 100 % utilization for minutes and the host's submit thread waited without a timeout for the oldest submission's fence (`mtl_wait_at`, site WS_ALLOC): the picture froze in silence. The evidence is in the work folder's `logs/freeze-20261104-1938/` (host log, a 5 s `sample`, the pipeline ledger) with a README. + +- The four pipeline bases compiled at that instant are (`c13c00c6b467d521`, `1bcc1a39c37f54eb`), (`fd6f2ce7f7046571`, `8d7d98c7b654f6b3`), (`41671ebe006f5bd4`, `328b6d7aa0940939`) and (`4a2396e4f9fea11b`, `f07838d26866e16b`). Pixel shaders `1bcc1a39c37f54eb` and `328b6d7aa0940939` (both from `/b6e28c40/0x38f972af.fdata`, IDRK@0x2f394788) hold KTGL's clustered-lighting loops: the cluster index comes from `gl_FragCoord`, the scene depth (slot 3) and the constants `c3[15..18]` (row and slice strides, z mapping); texel `2i` of the list in slot 16 is the cluster's offset into the index list and texel `2i + 1` packs two counts (`>> 16` and `& 0xffff`); each count bounds a do-while loop that reads a light index from the list and the light's data from slots 17 to 21. A count read from the wrong place (a float's bits give 16,000 or more) runs the loop that often per pixel and the GPU never returns. The vertex shaders have no loops; the other two pixel shaders have none. The pipeline of `1bcc1a39c37f54eb` compiled at the freeze differs from the one its draws use in the first battle only in the blend state (src alpha ONE, dst alpha ONE_MINUS_SRC_ALPHA): the same shader in another material pass, as the special's effect would use. +- The list is a texture buffer of 1,012,000 R32 elements (NVN format `0xb`, serial 3013 in a headless run), zero copy over the pool, bound as 16,384-texel rows (`tbuf_as_2d`) and viewed as R32Float since the shader declares float ([Integer buffer textures read through float slots](../../../docs/reference/rendering.md#integer-buffer-textures-read-through-float-slots)). Checked on this Mac (M2 Pro): such a view returns every bit pattern unchanged, denormal and NaN ones included, and a read past the view's edge returns 0, so an index past the list cannot make a count. The slots 17 to 21 hold RGBA32Float buffers of 1,024 and 3,072 elements and R32 ones of 3,072 and 192; no compute dispatch writes the list (the game's CPU does), and all texture IDs the draws bind lie in the first of the game's two 33,024-entry descriptor pools. +- Not reproduced: the first battle (the village, reached with the route under [Driving it on the Mac](#driving-it-on-the-mac)) draws those pixel shaders at 1x and at 2x and never hangs, but its list is empty in every dump taken (count 0 in every cluster), so the loops never ran there; the special attack's gauge never filled in the scripted rounds, and the outpost mission was not reached headless. The texel the loop read at the freeze is therefore still unknown. +- The host now reports such a hang ([A GPU that never finishes: the hang watchdog](../../../docs/reference/rendering.md#a-gpu-that-never-finishes-the-hang-watchdog)): a `[RED] GPU watchdog` line names the pipelines of the submission the GPU is stuck on. To play on past a fragment shader it names, `DM_NVN_SKIP_FS=` in `~/Library/Application Support/nxnative/04003F40232DE000/env.txt` drops its draws (the effect is missing, nothing else). Next: reach the outpost mission with the watchdog host, `DM_NVN_PASSDUMP_ALL=1` and `DM_NVN_CBDUMP` set, `passdump 3` and a `memdump` of the list right at the special (the scratch scripts `fight2.sh` / `lightlist.py` of the 2026-11-04 session do that), and compare the counts with the pixels' cluster indices. + ## Saves - The save is one file, `DATA.BIN` (8 MB). A new save creates it at boot with its defaults (operation 0 of the game's file request routine, `main+0x1325be0`); every boot reads its header and three areas (operations 1, 6, 7 and 8). @@ -43,7 +52,8 @@ Run headless: `DM_WINDOW` set to anything, `0` too, opens a window, and a covere ## Open - The long frames ([Performance](#performance)). -- Battles, the picture against a Switch 2, an IPA (a full iOS shader build first). +- [The GPU hang in a battle](#gpu-hang-in-a-battle-open): the outpost mission, with the special attack's light list dumped. +- The picture against a Switch 2, an IPA (a full iOS shader build first). ## Found on this game @@ -54,3 +64,4 @@ Run headless: `DM_WINDOW` set to anything, `0` too, opens a window, and a covere - [Dedicated c1 constants as slices of a bank](../../../docs/reference/frame-rate.md#dedicated-c1-constants-as-slices-of-a-bank): about 10 fps in the first field. - [Barrier moves around warp shuffles](../../../docs/reference/shaders.md#barrier-moves-around-warp-shuffles): two pixel shaders left out of the build. - [LDC with the bank in its address register (`.IS`)](../../../docs/reference/shaders.md#ldc-with-the-bank-in-its-address-register-is): two shaders left out of the build. +- [A GPU that never finishes: the hang watchdog](../../../docs/reference/rendering.md#a-gpu-that-never-finishes-the-hang-watchdog): the freeze in the first outpost mission ([GPU hang in a battle](#gpu-hang-in-a-battle-open)). diff --git a/dm/gfx/nvn/nvn_geometry.inc b/dm/gfx/nvn/nvn_geometry.inc index dbb12d7df8..42743b413e 100644 --- a/dm/gfx/nvn/nvn_geometry.inc +++ b/dm/gfx/nvn/nvn_geometry.inc @@ -603,6 +603,24 @@ static void mtk_encode(id en_) { // DrawMeshTasksIndirect: {count, first}, which the game's culling writes earlier in the submission, while Metal's indirect mesh draw takes {x, y, z}. mdx_run copies the count to a {count, 1, 1} on the // GPU, before the render pass and for every such draw up to the next write, and the shader reads first from the record. Reading the record on the CPU instead took a wait for the GPU at each hazard: // 73 % of the submit thread in Ocarina of Time's Kokiri Forest, frames of 90 ms and more against 25 ms of GPU work +// Diagnostic DM_NVN_MESHLOG_CB_GPU=1 (with DM_NVN_MESHLOG_CB, off by default): what the GPU reads, not what the CPU holds. Before a task draw the render pass is ended and the same four words are copied +// in queue order into a host buffer (one slot per record and draw, set to 0xfeedface first, so a copy that never ran shows), which the failure report prints beside the CPU's. It splits the pass +// at every task draw, so it can change what hangs: use it to see the value, not to count hangs. The slot is handed to subrec_mesh_words (g_mlcb_gw) +static void mlcb_gpu_copy(NvShader *ts) { + static int on = -1, reg = -1; static uint32_t off; static __strong id buf; + if (on < 0) { const char *g = getenv("DM_NVN_MESHLOG_CB_GPU"), *e = getenv("DM_NVN_MESHLOG_CB"); unsigned r, o; on = g && atoi(g) && e && sscanf(e, "%u:%u", &r, &o) == 2 && r < 16; + if (on) { reg = (int)r; off = o & ~3u; buf = [g_dev newBufferWithLength:(size_t)SUBREC_RING * SUBREC_MESH * 16 options:MTLResourceStorageModeShared]; if (buf) res_add(buf); else on = 0; // res_add: a buffer a command writes must be in the residency set + MLOG("DM_NVN_MESHLOG_CB_GPU: the task stage's register %d at byte %u is copied by the GPU before each task draw (the render pass is split there)", reg, off); } } + g_mlcb_gw = NULL; + subrec_t *r = g_subrec_cur; if (!on || !ts || !r || r->nm >= SUBREC_MESH) return; + const p_bind_buf *u = &S.ubo[3][reg]; void *mb; uint64_t mo; + if (!u->addr || (uint64_t)off + 16 > u->size || !mtl_addr(u->addr + off, 16, &mb, &mo) || (g_nubd && ubd_hits(u->addr + off, u->addr + off + 16))) return; + uint32_t *slot = (uint32_t *)buf.contents + ((size_t)(r - g_subrec) * SUBREC_MESH + r->nm) * 4; + slot[0] = slot[1] = slot[2] = slot[3] = 0xfeedface; + rp_end(); + enc_b_copy_buffer(blit_buf(u->addr + off, u->addr + off + 16, 0, 0), (__bridge id)mb, (NSUInteger)mo, buf, (NSUInteger)((uint8_t *)slot - (uint8_t *)buf.contents), 16); + g_mlcb_gw = slot; +} static void mesh_tasks_draw(const p_draw *dw) { if (!S.prog || (!dw->ind && dw->count <= 0)) return; // Diagnostic DM_NVN_SKIP_MESH=1 (off by default): drops every task / mesh draw, as DM_NVN_SKIP_FS drops draws by fragment shader, to measure what they cost in all (the picture is wrong) @@ -614,6 +632,7 @@ static void mesh_tasks_draw(const p_draw *dw) { RED_ONCE(150, "DrawMeshTasks without its task and mesh shaders (task %s mesh %s): draw skipped", ts ? ts->key : "-", ms ? ms->key : "-"); return; } image_prepare(pr, 1u << 3 | 1u << 4); if (g_nubd && (g_enc || ubd_lazy()) && ((ts && ubd_conflict_sh(ts, 3)) || ubd_conflict_sh(ms, 4))) { g_ubd_conflicts++; rp_end(); ubd_land(); } // as draw_ does for its stages + mlcb_gpu_copy(ts); // DM_NVN_MESHLOG_CB_GPU NvProg *raster = pr->geo_lean_raster; // the pixel stage alone if (!raster || raster->sh[1] != pr->sh[1] || raster->sh[0]) { raster = [NvProg new]; raster->sh[1] = pr->sh[1]; pr->geo_lean_raster = raster; } uint64_t ind = 0, ind_first = 0; @@ -628,6 +647,11 @@ static void mesh_tasks_draw(const p_draw *dw) { draw_(&triangle, NULL); g_geo_program = nil; g_mtk.on = 0; args_dirty_all(); if (g_mtk.miss) { g_mtk_wait++; return; } + // named if the command buffer fails (subrec_mesh_fmt): a direct draw's grid, a GPU-written one's count as the copy mdx_run made holds it when the report prints + subrec_mesh_add(ts ? ts->key : NULL, ms->key, pr->sh[1] ? pr->sh[1]->key : NULL, (uint32_t)dw->count, (uint32_t)dw->first, ind ? mdx_cpu(dw->ind, dw->ind) : NULL); + if (g_subrec_cur && g_subrec_cur->nm && g_subrec_cur->nm_more == 0) { subrec_mesh *me = &g_subrec_cur->m[g_subrec_cur->nm - 1]; me->no_first = 1; me->ind = dw->ind != 0; // the copy holds {count, 1, 1} + if (ts) { subrec_mesh_words(S.ubo[3]); // DM_NVN_MESHLOG_CB + if (me->has_words && g_nubd && ubd_hits(me->cb_addr + me->cb_off, me->cb_addr + me->cb_off + 16)) me->cb_state |= 1; } } // an update deferred in the pass: the GPU reads its shadow, not these words swrite_note(pr); g_wr_epoch++; if (!g_mtk_n++) MLOG("task / mesh: first draw, task %s mesh %s fragment %s, %u workgroups from %u%s", ts ? ts->key : "-", ms->key, pr->sh[1] ? pr->sh[1]->key : "-", g_mtk.count, g_mtk.first, ind ? " (indirect)" : ""); } diff --git a/dm/gfx/nvn/nvn_mtl.m b/dm/gfx/nvn/nvn_mtl.m index 38dd85c408..0a22781402 100644 --- a/dm/gfx/nvn/nvn_mtl.m +++ b/dm/gfx/nvn/nvn_mtl.m @@ -209,6 +209,9 @@ static int gpu_err_has(NSError *e, NSInteger code, int depth) { for (NSError *u in e.underlyingErrors) if (gpu_err_has(u, code, depth + 1)) return 1; return 0; } +// Whether a command buffer's error is its own: a victim of another's fault and a submission refused after one ran nothing of their own (Splatoon Raiders, issue #1289), so +// the failed command buffer reports (cbs_feedback, subrec_failed) leave them out +static int cb_err_own(NSError *e) { NSString *d = e.description; return e && ![d containsString:@"InnocentVictim"] && ![d containsString:@"SubmissionsIgnored"]; } static void gpu_lost_check(NSError *e, const char *where) { if (!e || atomic_load(&g_gpu_lost) || !gpu_err_has(e, MTL4CommandQueueErrorAccessRevoked, 0) || atomic_exchange(&g_gpu_lost, 1)) return; MLOG("[RED] GPU access revoked: the %s command buffer was ignored (fences back %llu of %llu); macOS runs none of this process's GPU work any more, so the game stops", where, @@ -1055,8 +1058,180 @@ void mtl_prepare(void) { } static void sub_cut_begin(void); static void ts_sub_begin(void), ts_boundary(void); static int ts_on(void); static void gmem_commit_patch(void); // the raw pool table words of the arguments encoded so far follow the pools (gmem_slot_note) +// GPU hang watchdog. A shader that never ends (Hyrule Warriors: Age of Imprisonment's light-list loops in a battle: the game README, "Found on this game") keeps the GPU busy +// without a fault, so no command buffer completes, no feedback handler runs, g_done stops, and every wait on the CPU for the GPU blocks for good: the allocator wait of the next +// submission (WS_ALLOC, no timeout) froze the host silently. Metal cannot abort GPU work, so the watchdog only tells: a wait that sees no fence complete for DM_NVN_GPU_WATCHDOG +// seconds (5 by default, 0 off) while submissions are in flight logs one [RED] line per stuck fence naming the pipelines of the oldest submission in flight (the GPU runs them in +// order, so that is the one it is stuck on) and of the two after it, from a record each submission keeps of the distinct (vertex, fragment) pairs its draws bound and the compute +// shaders it dispatched (subrec_add from draw_ and dispatch), per command buffer of the submission and in the order they first ran there, each with the render pass it first ran in. +// The record is filled by the submit thread and read by other threads only for fences already committed, which the ring rewrites 64 submissions later. The line names what to pass +// to DM_NVN_SKIP_FS to play on without the looping draws (docs/env_switches.tsv). +// The same record is printed when a command buffer of the submission fails (subrec_failed): macOS ends a shader that runs too long by aborting its command buffer (issue #1326, +// Ocarina of Time), so the fence completes with an error, g_done moves on and the watchdog never fires +#define SUBREC_RING 64 +#define SUBREC_PAIRS 48 // per submission, over all its command buffers; the rest is only counted (n_more) +#define SUBREC_LINE 8192 // the longest line a report builds: 48 pairs of two 16-character keys with their pass marks fit with room to spare +// vs / fs: shader keys (16 hex digits, or a builtin's name cut to 16); cb: the command buffer of the submission it ran in (0 = the first, 255 = that one or later); +// pass: render passes begun since the submission began when it first ran in that command buffer (65535 = that many or more) +typedef struct { char vs[17], fs[17]; uint8_t cb, pull; uint16_t pass; } subrec_pair; +// last: the program or compute shader of the previous add (most draws repeat it); cb: the command buffer being encoded (its index in the submission), cb_first: its first entry in p +// (pairs are kept once per command buffer, so a failed one lists all it ran); pass0: g_stat_pass when the submission began; fb: subrec_failed's state, SUBREC_FB_* bits +// A task / mesh draw of the submission (subrec_mesh_add), as many as SUBREC_MESH, the rest counted: its three keys, where it ran, and its workgroups: count and first of a direct draw, or for a +// GPU-written one the converted arguments in the frame arena (args, words 0 and 4), read when the report is printed. Printed after the pipelines when a command buffer fails (issue #1326: +// the foliage task's draws are in the hung command buffers; their grids tell whether a count ran away) +#define SUBREC_MESH 24 +// words: with DM_NVN_MESHLOG_CB, four words of the task stage's uniform buffer as the CPU saw them when the draw was encoded (has_words) +// cb_addr / cb_size / cb_gpu: where that uniform buffer was bound (the guest address of the buffer, its size, the Metal GPU address of it, 0 when no pool holds it); gw: with DM_NVN_MESHLOG_CB_GPU=1, the four +// words a GPU copy ahead of the draw took from the same place (mesh_tasks_draw), 0xfeedface until that copy ran; cb_state: 1 an update deferred in the pass covers it +typedef struct { char ts[17], ms[17], fs[17]; uint8_t cb, has_words, cb_state, no_first, ind; uint16_t pass; uint32_t count, first, words[4]; const uint32_t *args; uint64_t cb_addr, cb_gpu; uint32_t cb_size, cb_off; const volatile uint32_t *gw; } subrec_mesh; +typedef struct { uint64_t fence, frame, pass0; uint32_t draws, dispatches, n, n_more, cb, cb_first, nm, nm_more, pulls; subrec_pair p[SUBREC_PAIRS]; subrec_mesh m[SUBREC_MESH]; const void *last; _Atomic uint32_t fb; } subrec_t; +static subrec_t g_subrec[SUBREC_RING]; static subrec_t *g_subrec_cur; // g_subrec_cur: the record draws go to, NULL between mtl_sub_commit and the next mtl_sub_begin +static _Atomic uint64_t g_cur_frame; // tentative, as below: the presented frame counter (mtl_set_frame) +static uint64_t g_stat_pass; // tentative, as below: render passes begun since launch (the number DM_NVN_PASSDUMP's lines carry) +static void subrec_begin(uint64_t fence) { subrec_t *r = &g_subrec[fence % SUBREC_RING]; memset(r, 0, sizeof *r); r->fence = fence; r->frame = atomic_load(&g_cur_frame); r->pass0 = g_stat_pass; g_subrec_cur = r; } +static void subrec_key(char *dst, const char *key, const char *builtin) { const char *s = key && key[0] ? key : builtin ? builtin : "(unnamed)"; size_t n = strlen(s); if (n > 16) n = 16; memcpy(dst, s, n); dst[n] = 0; } // not "?" for the fallback: that string is DMSH_KIND_UNKNOWN, which test_dmsh_abi counts as an ABI literal +// who: the NvProg of a draw or the NvShader of a dispatch, to skip the scan when a run of draws uses one program; vs / fs: the keys as subrec_key makes them +static void subrec_add(const char *vs, const char *fs, const void *who, int dispatch) { + subrec_t *r = g_subrec_cur; if (!r) return; + if (dispatch) r->dispatches++; else r->draws++; + if (who == r->last) return; + r->last = who; + for (uint32_t i = r->cb_first; i < r->n; i++) if (!strcmp(r->p[i].vs, vs) && !strcmp(r->p[i].fs, fs)) return; // only this command buffer's: a failed one lists every pipeline it ran + if (r->n == SUBREC_PAIRS) { r->n_more++; return; } + subrec_pair *e = &r->p[r->n]; + memcpy(e->vs, vs, 17); memcpy(e->fs, fs, 17); + e->cb = (uint8_t)(r->cb < 255 ? r->cb : 255); uint64_t dp = g_stat_pass - r->pass0; e->pass = (uint16_t)(dp < 65535 ? dp : 65535); + r->n++; +} +static void subrec_mesh_add(const char *ts, const char *ms, const char *fs, uint32_t count, uint32_t first, const uint32_t *args) { + subrec_t *r = g_subrec_cur; if (!r) return; + if (r->nm == SUBREC_MESH) { r->nm_more++; return; } + subrec_mesh *e = &r->m[r->nm++]; + subrec_key(e->ts, ts, "-"); subrec_key(e->ms, ms, NULL); subrec_key(e->fs, fs, "-"); + e->cb = (uint8_t)(r->cb < 255 ? r->cb : 255); uint64_t dp = g_stat_pass - r->pass0; e->pass = (uint16_t)(dp < 65535 ? dp : 65535); + e->count = count; e->first = first; e->args = args; e->has_words = 0; +} +// Diagnostic DM_NVN_MESHLOG_CB=: (off by default): each task / mesh draw the failure report lists also carries the four words at that offset of the task +// stage's uniform buffer in that register, read on the CPU when the draw is encoded (an update deferred in the pass is not seen). Ocarina of Time's foliage task a5288d0a6c4971fd +// bounds its occlusion loops by the grid size at c3[193] (register 0, offset 3088): DM_NVN_MESHLOG_CB=0:3088 +static const volatile uint32_t *g_mlcb_gw; // the GPU copy's words of the draw about to be recorded (mesh_tasks_draw's mlcb_gpu_copy), taken by subrec_mesh_words +static void subrec_mesh_words(const p_bind_buf *ubo) { + static int reg = -2; static uint32_t off; + if (reg == -2) { const char *e = getenv("DM_NVN_MESHLOG_CB"); reg = -1; unsigned r, o; if (e && sscanf(e, "%u:%u", &r, &o) == 2 && r < 16) { reg = (int)r; off = o & ~3u; } } + subrec_t *r = g_subrec_cur; if (reg < 0 || !r || !r->nm || r->nm > SUBREC_MESH) return; + const p_bind_buf *u = &ubo[reg]; subrec_mesh *e = &r->m[r->nm - 1]; + if (!u->addr || (uint64_t)off + 16 > u->size) return; + memcpy(e->words, (const void *)(uintptr_t)(u->addr + off), 16); e->has_words = 1; + e->cb_addr = u->addr; e->cb_size = (uint32_t)u->size; e->cb_off = off; e->gw = g_mlcb_gw; g_mlcb_gw = NULL; + { void *mb; uint64_t mo, g; if (mtl_gpu_addr(u->addr, u->size ? u->size : 1, &mb, &mo, &g)) e->cb_gpu = g; } + static int once; if (!once++) MLOG("DM_NVN_MESHLOG_CB: task uniform register %d at byte %u of the first draw (task %s): %#x %#x %#x %#x", reg, off, e->ts, e->words[0], e->words[1], e->words[2], e->words[3]); +} +// A draw that went through its pulling stand-in (hybrid pipelines): counted, and its pair in this command buffer marked (vs / fs: the keys as subrec_key makes them, after subrec_add) +static void subrec_pull(const char *vs, const char *fs) { + subrec_t *r = g_subrec_cur; if (!r) return; + r->pulls++; + for (uint32_t i = r->n; i-- > r->cb_first;) if (!strcmp(r->p[i].vs, vs) && !strcmp(r->p[i].fs, fs)) { r->p[i].pull = 1; return; } +} +// A segment of the submission is committed (sub_cut): the draws after it go to the next command buffer. Returns the index of the committed one, which its feedback handler gives +// back to subrec_failed. Without a record (no submission begun) 0, which subrec_failed cannot match to a fence anyway +static uint32_t subrec_cut(void) { subrec_t *r = g_subrec_cur; if (!r) return 0; uint32_t k = r->cb++; r->cb_first = r->n; r->last = NULL; return k; } +// Appends to line, which holds o characters of size, without running past its end (snprintf returns the length it wanted, not what it wrote). Returns the new length, at most size - 1 +static int sr_put(char *line, size_t size, int o, const char *fmt, ...) __attribute__((format(printf, 4, 5))); +static int sr_put(char *line, size_t size, int o, const char *fmt, ...) { + if (o < 0 || (size_t)o + 1 >= size) return o; + va_list ap; va_start(ap, fmt); int n = vsnprintf(line + o, size - (size_t)o, fmt, ap); va_end(ap); + if (n < 0) return o; + return (size_t)o + (size_t)n >= size ? (int)size - 1 : o + n; +} +// One record as text: " fence F (frame N, D draws, X dispatches, C command buffers, from pass P): cb 0: pass +0 vs/fs vs/fs pass +2 -/cs | cb 1 FAILED: …;". failed: bit k marks +// command buffer k as failed (bit 29: that one or a later one), 0 for none. A command buffer with no entry (no draw or dispatch of its own, or past a full record) shows only if it +// failed, after the others ("cb K FAILED: none listed"). Its index counts the submission's commits, so it matches the shader list's "segment K" (cbs_report) except where game +// timestamps (ts_boundary) numbered a segment without committing one +static int subrec_fmt(char *line, size_t size, int o, const subrec_t *r, uint32_t failed) { + uint32_t listed = 0; // the command buffers with an entry, as failed's bits + o = sr_put(line, size, o, " fence %llu (frame %llu, %u draws, %u dispatches, %u command buffers, from pass %llu", (unsigned long long)r->fence, (unsigned long long)r->frame, + r->draws, r->dispatches, r->cb + 1, (unsigned long long)r->pass0); + if (r->pulls) o = sr_put(line, size, o, ", %u draws through a pulling stand-in", r->pulls); + o = sr_put(line, size, o, "):"); + for (uint32_t i = 0; i < r->n; i++) { + const subrec_pair *e = &r->p[i]; + int new_cb = !i || e->cb != r->p[i - 1].cb; + uint32_t bit = 1u << (e->cb < 29 ? e->cb : 29); listed |= bit; + if (new_cb) o = sr_put(line, size, o, "%s cb %u%s:", i ? " |" : "", e->cb, failed & bit ? " FAILED" : ""); + if (new_cb || e->pass != r->p[i - 1].pass) o = sr_put(line, size, o, " pass +%u", e->pass); + o = sr_put(line, size, o, " %s/%s%s", e->vs, e->fs, e->pull ? "+pull" : ""); + } + for (uint32_t k = 0; k < 30; k++) if (failed >> k & 1 && !(listed >> k & 1)) o = sr_put(line, size, o, "%s cb %u%s FAILED: none listed", r->n || k ? " |" : "", k, k == 29 ? " or later" : ""); + if (!r->n && !failed) o = sr_put(line, size, o, " no draw or dispatch"); + if (r->n_more) o = sr_put(line, size, o, " (+%u more)", r->n_more); + return sr_put(line, size, o, ";"); +} +// The record's task / mesh draws as one line: "[RED] task / mesh draws of the failed submission fence F: cb 0 pass +3 task/mesh/fragment direct 12 from 0, ...". The arena of a +// GPU-written draw's arguments is still held by the submission while its handlers run +static const char *subrec_mesh_fmt(char *line, size_t size, const subrec_t *r) { + int o = sr_put(line, size, 0, "[RED] task / mesh draws of the failed submission fence %llu (%u%s):", (unsigned long long)r->fence, r->nm + r->nm_more, r->nm_more ? ", the first listed" : ""); + for (uint32_t i = 0; i < r->nm; i++) { const subrec_mesh *e = &r->m[i]; + o = sr_put(line, size, o, "%s cb %u pass +%u %s/%s/%s ", i ? "," : "", e->cb, e->pass, e->ts, e->ms, e->fs); + if (e->args) { const volatile uint32_t *a = e->args; o = sr_put(line, size, o, "indirect %u", a[0]); if (!e->no_first) o = sr_put(line, size, o, " from %u", a[4]); } + else if (e->ind) o = sr_put(line, size, o, "indirect (count not kept)"); + else o = sr_put(line, size, o, "direct %u from %u", e->count, e->first); + if (e->has_words) { + o = sr_put(line, size, o, " (task uniform words %#x %#x %#x %#x at +%u of the buffer bound at guest %#llx, size %u, Metal GPU %#llx%s", e->words[0], e->words[1], e->words[2], e->words[3], e->cb_off, + (unsigned long long)e->cb_addr, e->cb_size, (unsigned long long)e->cb_gpu, e->cb_state & 1 ? ", an update deferred in the pass covers it" : ""); + // the memory now, when the report is printed: a difference from the words above is a write after the draw was encoded; its pool may be gone, then nothing is read + void *mb; uint64_t mo; + if (e->cb_addr && mtl_addr(e->cb_addr + e->cb_off, 16, &mb, &mo)) { const uint32_t *w = (const uint32_t *)(uintptr_t)(e->cb_addr + e->cb_off); + o = sr_put(line, size, o, "; now %#x %#x %#x %#x", w[0], w[1], w[2], w[3]); } + if (e->gw) o = sr_put(line, size, o, "; GPU copy ahead of the draw %#x %#x %#x %#x", e->gw[0], e->gw[1], e->gw[2], e->gw[3]); + o = sr_put(line, size, o, ")"); } } + return line; +} +// A failed command buffer of a submission, from its feedback handler: once all of the submission's command buffers are committed (its last one's handler has run, last = 1) and one +// of its own failed, the record is printed, once per fence and for the first SUBREC_REPORTS fences. Every handler of the last command buffer calls it, failed or not, to close the +// record; a segment's handler only on an error. The record is complete only after the last commit, so a segment that fails first leaves a bit for the last handler to print, and a +// segment whose handler runs after the last one prints itself. Victims of another's fault and refused submissions ran nothing of their own (cb_err_own) and set no bit. +// cb: the command buffer's index in the submission (subrec_cut, or the record's cb for the last). Returns 1 if it printed (for the tests) +enum { SUBREC_FB_CLOSED = 1u << 31, SUBREC_FB_PRINTED = 1u << 30, SUBREC_FB_CBS = 30, SUBREC_REPORTS = 16 }; +static _Atomic uint32_t g_subrec_reports; +static int cb_err_own(NSError *e); +static int subrec_failed(uint64_t fence, uint32_t cb, NSError *err, int last) { + subrec_t *r = &g_subrec[fence % SUBREC_RING]; + if (r->fence != fence) return 0; // rewritten by a submission 64 later, or never begun + uint32_t bit = err && cb_err_own(err) ? 1u << (cb < SUBREC_FB_CBS - 1 ? cb : SUBREC_FB_CBS - 1) : 0, set = bit | (last ? SUBREC_FB_CLOSED : 0); + uint32_t now = atomic_fetch_or(&r->fb, set) | set; // one of the two handlers sees both the failure and the close, whichever order they run in + if (!(now & SUBREC_FB_CLOSED) || !(now & ((1u << SUBREC_FB_CBS) - 1))) return 0; + if (atomic_fetch_or(&r->fb, SUBREC_FB_PRINTED) & SUBREC_FB_PRINTED) return 0; + if (atomic_fetch_add(&g_subrec_reports, 1) >= SUBREC_REPORTS) return 0; + char *line = malloc(SUBREC_LINE); if (!line) return 0; + int o = sr_put(line, SUBREC_LINE, 0, "[RED] pipelines of the failed submission (vertex/fragment pairs and -/compute, per command buffer in the order they first ran):"); + subrec_fmt(line, SUBREC_LINE, o, r, now & ((1u << SUBREC_FB_CBS) - 1)); + MLOG("%s", line); + if (r->nm) { MLOG("%s", subrec_mesh_fmt(line, SUBREC_LINE, r)); } + free(line); + return 1; +} +#define WD_SLICE_MS 2000ull // a blocking wait is cut into slices of this length so the watchdog can look between them +static long wd_secs(void) { static long v = -1; if (v < 0) { const char *e = getenv("DM_NVN_GPU_WATCHDOG"); v = e && *e ? strtol(e, NULL, 0) : 5; if (v < 0) v = 0; } return v; } +static _Atomic uint64_t g_wd_reported; // the oldest in-flight fence the last report named: one report per stuck fence, whichever threads wait +// Called between slices of a blocking wait: done0 is g_done when the slice loop began or last saw progress, t0 that moment (CLOCK_UPTIME_RAW ns). Returns the current g_done +static uint64_t wd_check(uint64_t waited_for, int site, uint64_t *t0, uint64_t done0) { + uint64_t done = atomic_load(&g_done), now = ws_t0(); + if (done != done0) { *t0 = now; return done; } // the GPU completed something: not stuck + long secs = wd_secs(); uint64_t newest = atomic_load(&g_fence); + if (!secs || now - *t0 < (uint64_t)secs * 1000000000ull || newest <= done) return done; // nothing in flight: the wait is for work not committed yet, not the GPU's fault + uint64_t oldest = done + 1; + if (atomic_exchange(&g_wd_reported, oldest) == oldest) return done; + char *line = malloc(SUBREC_LINE); if (!line) return done; + int o = sr_put(line, SUBREC_LINE, 0, "[RED] GPU watchdog: no submission completed in %llu s (waiting for fence %llu at '%s', done %llu, committed %llu): the GPU is stuck on fence %llu or keeps it from running;", + (unsigned long long)((now - *t0) / 1000000000ull), (unsigned long long)waited_for, ws_name[site], (unsigned long long)done, (unsigned long long)newest, (unsigned long long)oldest); + for (uint64_t f = oldest; f <= newest && f < oldest + 3; f++) { const subrec_t *r = &g_subrec[f % SUBREC_RING]; if (r->fence == f) o = subrec_fmt(line, SUBREC_LINE, o, r, 0); } + MLOG("%s", line); free(line); + MLOG("[RED] GPU watchdog: the host cannot abort GPU work; if a fragment shader above loops, relaunch with DM_NVN_SKIP_FS= (the title's env.txt on the Mac) to play on without its draws"); + return done; +} void mtl_sub_begin(void) { mtl_init(); g_sub_serial++; g_seg = 0; seg_clk_put(g_sclk); g_sclk = NULL; g_rc_npend = 0; g_rc_skip = 0; + subrec_begin(atomic_load(&g_fence) + 1); // GPU hang watchdog: this submission's pipelines, under the fence mtl_sub_commit will give it sub_cut_begin(); defer_drain(); defer_reset(); @@ -1934,6 +2109,7 @@ uint64_t mtl_sub_commit(void) { treg_finish_submission(); // Late descriptor views retire behind this submission's fence. rt_preserve_bound(); // The game may reuse completed command memory; queue bindings must not point into its texture snapshots. uint64_t fence = ++g_fence; + uint32_t sr_cb = g_subrec_cur ? g_subrec_cur->cb : 0; g_subrec_cur = NULL; // GPU hang watchdog: the record is complete; the feedback handler reads it (subrec_failed) gw_commit(fence); if (g_vis_ring_i >= 0) g_vis_ring[g_vis_ring_i].fence = fence; // CPU-visible effects after completion: copy the op table into the callback @@ -1959,6 +2135,7 @@ uint64_t mtl_sub_commit(void) { uint64_t c0 = 0, c1 = 0; if (seg_ts()) { c0 = gpu_s_guest_ns(cb.GPUStartTime); c1 = gpu_s_guest_ns(cb.GPUEndTime); } if (cb.error) { atomic_store(&g_last_commit_error, 1); res_top_once(cb.error); static int n, nv; int victim = [cb.error.description containsString:@"InnocentVictim"]; if (victim ? nv++ < 1 : n++ < 8) MLOG("[RED] command buffer error details fence=%llu: %s | GPU %.3f→%.3f", (unsigned long long)fence, cb.error.description.UTF8String, cb.GPUStartTime, cb.GPUEndTime); if (!victim) MLOG("[RED] state of the failed submission fence=%llu: %s", (unsigned long long)fence, cctx.UTF8String); MLOG("[RED] command buffer execution error: %s", cb.error.localizedDescription.UTF8String); } char where[64]; snprintf(where, sizeof where, "fence %llu, its last command buffer", (unsigned long long)fence); cbs_feedback(cbs, cb.error, where); + subrec_failed(fence, sr_cb, cb.error, 1); // the pipelines of this submission if one of its command buffers failed (closes its record either way) gpu_lost_check(lost_test ? gpu_lost_test_error() : cb.error, "submission"); post_complete(fence, c0, c1); if (atomic_load(&g_gpu_lost)) gpu_lost_release(); // the GPU signals none of these fences @@ -1991,9 +2168,15 @@ static void post_early(uint64_t fence) { static int mtl_wait_at(uint64_t fence, uint64_t timeout_ns, int site) { if (g_done >= fence) { if (ws_on()) ws_put(site, 0, 0); return 1; } uint64_t w0 = ws_t0(); + uint64_t wd_t0 = w0, wd_done = atomic_load(&g_done); // GPU hang watchdog (wd_check): progress seen so far if ((site == WS_SYNC || site == WS_SYNC_NEWEST || site == WS_ACQ) && fast_wake() && g_ev && fence <= g_fence) { // the game's own wait: wake on the GPU's signal (rec_signal(g_ev, fence) after each submission) uint64_t ms = timeout_ns / 1000000ull; if (ms > 3600000ull) ms = 3600000ull; - if ([g_ev waitUntilSignaledValue:fence timeoutMS:ms]) post_early(fence); + for (;;) { // in slices, so a GPU that never signals is reported (wd_check) instead of waited for in silence + uint64_t slice = ms > WD_SLICE_MS ? WD_SLICE_MS : ms; + if ([g_ev waitUntilSignaledValue:fence timeoutMS:slice]) { post_early(fence); break; } + ms -= slice; if (!ms) break; + wd_done = wd_check(fence, site, &wd_t0, wd_done); + } int ok = g_done >= fence; if (ws_on()) { ws_put(site, w0, 1); ws_wake(fence); } if (ok || timeout_ns < 1000000ull) return ok; @@ -2009,7 +2192,14 @@ static int mtl_wait_at(uint64_t fence, uint64_t timeout_ns, int site) { dl.tv_sec += ns / 1000000000ull; dl.tv_nsec = ns % 1000000000ull; pthread_mutex_lock(&g_mu); int r = 0; - while (g_done < fence) if ((r = pthread_cond_timedwait(&g_cv, &g_mu, &dl))) break; + while (g_done < fence) { // in slices of WD_SLICE_MS up to the deadline, with the watchdog looking between them (the lock is dropped for its report) + struct timespec sl; clock_gettime(CLOCK_REALTIME, &sl); + uint64_t sns = (uint64_t)sl.tv_nsec + WD_SLICE_MS * 1000000ull; sl.tv_sec += sns / 1000000000ull; sl.tv_nsec = sns % 1000000000ull; + int last = sl.tv_sec > dl.tv_sec || (sl.tv_sec == dl.tv_sec && sl.tv_nsec >= dl.tv_nsec); // the slice reaches the deadline: wait to the deadline itself + if ((r = pthread_cond_timedwait(&g_cv, &g_mu, last ? &dl : &sl))) { if (r != ETIMEDOUT || last) break; r = 0; } + if (g_done >= fence) break; + pthread_mutex_unlock(&g_mu); wd_done = wd_check(fence, site, &wd_t0, wd_done); pthread_mutex_lock(&g_mu); + } int ok = g_done >= fence; pthread_mutex_unlock(&g_mu); if (ws_on()) { ws_put(site, w0, 1); if (site == WS_SYNC_NEWEST || site == WS_SYNC || site == WS_ACQ) ws_wake(fence); } @@ -9302,8 +9492,8 @@ static void cbs_report(const cbs_list *l, const char *where, uint64_t nth) { / free(b); } static void cbs_feedback(cbs_list *l, NSError *err, const char *where) { // from a command buffer's feedback handler; owns l - if (err && l) { NSString *d = err.description; - if (![d containsString:@"InnocentVictim"] && ![d containsString:@"SubmissionsIgnored"]) { + if (err && l) { + if (cb_err_own(err)) { pthread_mutex_lock(&g_cbs_mu); uint64_t nth = ++g_cbs_failures; cbs_tally_add(l); @@ -11699,7 +11889,7 @@ static uint32_t mdi_count(uint64_t cnt) { // (Kamura Village draws the same records with two counts between the same writes: keyed by the record alone, the second multi-draw found no copy and waited for the GPU each frame) #define MDX_SLOTS 16384 // a power of two; a scan fills at most a quarter static const p_multi_draw *g_mdx_range; // only while replaying a compact range through the GPU mask -typedef struct { uint64_t ind, cnt, out, tag; } mdx_ent; // out: GPU address of the copy, 0 when the record or count is in no Metal buffer (those draws wait, mdi_live) +typedef struct { uint64_t ind, cnt, out, tag; const uint32_t *cpu; } mdx_ent; // out: GPU address of the copy, 0 when the record or count is in no Metal buffer (those draws wait, mdi_live) static mdx_ent g_mdx[MDX_SLOTS]; static int g_mdx_n; static uint64_t g_mdx_tag = 1, g_mdx_ep = ~0ull, g_mdx_sub, g_mdx_runs, g_mdx_splits, g_mdx_draws, g_mdx_fast; static const uint8_t *g_mdx_stop; // The kernel mdx_mask: dm/gfx/msl/mdx.metal static int mdx_wanted(const p_draw *dw, const p_draw_idx *di) { return dw ? dw->mdi_cnt && !ixc_wanted(dw, NULL) : di->mdi_cnt && !ixc_wanted(NULL, di); } @@ -11711,6 +11901,7 @@ static int mdx_find(uint64_t ind, uint64_t cnt, uint64_t *out) { // → 1 when const mdx_ent *e = mdx_slot(ind, cnt); if (e->tag != g_mdx_tag) return 0; *out = e->out; return 1; } +static const uint32_t *mdx_cpu(uint64_t ind, uint64_t cnt) { const mdx_ent *e = mdx_slot(ind, cnt); return e->tag == g_mdx_tag ? e->cpu : NULL; } // the copy mdx_find found, as the CPU sees it static void mdx_run(const p_draw *dw, const p_draw_idx *di) { static id ps; static id at; static int failed; if (failed) return; @@ -11722,7 +11913,7 @@ static void mdx_run(const p_draw *dw, const p_draw_idx *di) { enum { QMAX = MDX_SLOTS / 4 }; static struct { mdx_ent *e; uint32_t i, words; } q[QMAX]; int nq = 0; uint64_t lo = ~0ull, hi = 0; // the hull of the records and counts taken, for the uniform update check - #define MDX_TAKE(IND, CNT, I, W) do { mdx_ent *e_ = mdx_slot((IND), (CNT)); if (e_->tag != g_mdx_tag && nq < QMAX) { *e_ = (mdx_ent){(IND), (CNT), 0, g_mdx_tag}; g_mdx_n++; \ + #define MDX_TAKE(IND, CNT, I, W) do { mdx_ent *e_ = mdx_slot((IND), (CNT)); if (e_->tag != g_mdx_tag && nq < QMAX) { *e_ = (mdx_ent){(IND), (CNT), 0, g_mdx_tag, NULL}; g_mdx_n++; \ q[nq].e = e_; q[nq].i = (uint32_t)(I); q[nq++].words = (W); lo = MIN(lo, MIN((IND), (CNT))); hi = MAX(hi, MAX((IND) + 4 * (W), (CNT) + 4)); } } while (0) if (dw && dw->prim == DM_PRIM_MESH_TASKS) MDX_TAKE(dw->ind, dw->ind, 0, 0); else if (dw) MDX_TAKE(dw->ind, dw->mdi_cnt, dw->mdi_i, 4); else MDX_TAKE(di->ind, di->mdi_cnt, di->mdi_i, 5); // words 0: an indirect mesh draw, keyed by its record alone if (g_mdx_range) { @@ -11756,7 +11947,7 @@ static void mdx_run(const p_draw *dw, const p_draw_idx *di) { memset(j, 0, (size_t)nj * sizeof(mjob)); for (int k = 0; k < nq; k++) { mdx_ent *e = q[k].e; void *mb; uint64_t mo, rg, cg; if (!mtl_gpu_addr(e->ind, 4 * (q[k].words ? q[k].words : 2), &mb, &mo, &rg) || !mtl_gpu_addr(e->cnt, 4, &mb, &mo, &cg)) continue; - e->out = og + 32 * (uint64_t)k; j[k] = (mjob){rg, cg, e->out, q[k].i, q[k].words}; } + e->out = og + 32 * (uint64_t)k; e->cpu = (const uint32_t *)((const uint8_t *)ab.contents + ao + (size_t)nj * sizeof(mjob) + 32 * (size_t)k); j[k] = (mjob){rg, cg, e->out, q[k].i, q[k].words}; } id ce = enc_c_begin(NULL); [ce setArgumentTable:at]; [at setAddress:ab.gpuAddress + ao atIndex:0]; [ce setComputePipelineState:ps]; [ce dispatchThreadgroups:MTLSizeMake((NSUInteger)nj / 64, 1, 1) threadsPerThreadgroup:MTLSizeMake(64, 1, 1)]; enc_c_end(ce); @@ -12192,6 +12383,10 @@ static void draw_(const p_draw *dw, const p_draw_idx *di) { __unsafe_unretained id ps = cur_ps; if (!ps) { PD("Z %llu draw skipped: no render pipeline (vertex %s fragment %s)", g_stat_pass, pr->sh[0] ? pr->sh[0]->key : "-", pr->sh[1] ? pr->sh[1]->key : "-"); return; } if (ps != g_enc_pso) { enc_r_pso(en, ps); g_enc_pso = ps; } + if (g_subrec_cur && g_subrec_cur->last != (__bridge const void *)pr) { // GPU hang watchdog: the pipelines of this submission (a repeated program costs one compare) + char vk[17], fk[17]; subrec_key(vk, pr->sh[0] ? pr->sh[0]->key : NULL, pr->sh[0] ? pr->sh[0]->builtin : NULL); subrec_key(fk, pr->sh[1] ? pr->sh[1]->key : NULL, pr->sh[1] ? pr->sh[1]->builtin : "-"); + subrec_add(vk, fk, (__bridge const void *)pr, 0); if (cur_pull && !g_geo_mesh.on) subrec_pull(vk, fk); } + else if (g_subrec_cur) g_subrec_cur->draws++; if (g_sm_pass && g_sm_applied != g_sm_cur) { // the layer this draw goes to (see g_sm_plan) MTLVertexAmplificationViewMapping vm = {0, (uint32_t)(g_sm_cur - g_sm_lo)}; [(id)en setVertexAmplificationCount:1 viewMappings:&vm]; g_sm_applied = g_sm_cur; } static id cur_ds; static uint64_t cur_ds_pass; @@ -12522,6 +12717,7 @@ static void dispatch(const p_dispatch *dp) { if (own && g_blit) { enc_b_end(g_blit); g_blit = nil; } id ce = own ? pg_compute() : (id)dispatch_enc(); enc_c_pso(ce, ps); + { char ck[17]; subrec_key(ck, cs->key, cs->builtin); subrec_add("-", ck, (__bridge const void *)cs, 1); } // GPU hang watchdog: the compute shaders of this submission g_dispatch_dim[0] = (uint32_t)dp->x; g_dispatch_dim[1] = (uint32_t)dp->y; g_dispatch_dim[2] = (uint32_t)dp->z; // read back by the driver segment c0 (encode_args_) g_c0_dim_buf = nil; encode_args(ce, cs, 5, 0); @@ -13245,7 +13441,7 @@ static void sub_cut(void) { uint64_t f = atomic_load(&g_cur_frame); gpu_tag_begin(f); uint32_t k = g_seg++; seg_clk *sc = NULL; // reports encoded so far keep this segment's GPU times (seg_ts) if (seg_ts()) { if (!g_sclk) { g_sclk = calloc(1, sizeof *g_sclk); atomic_store(&g_sclk->refs, 1); } sc = g_sclk; atomic_fetch_add(&sc->refs, 1); } - cbs_list *cbs = cbs_take(); uint64_t cbs_fence = g_fence + 1; + cbs_list *cbs = cbs_take(); uint64_t cbs_fence = g_fence + 1; uint32_t sr_cb = subrec_cut(); MTL4CommitOptions *o = [MTL4CommitOptions new]; atomic_fetch_add(&g_seg_inflight, 1); [o addFeedbackHandler:^(id cb) { @@ -13254,6 +13450,7 @@ static void sub_cut(void) { if (sc) { if (k < SEG_CLK_N) { atomic_store(&sc->t[k][0], gpu_s_guest_ns(cb.GPUStartTime)); atomic_store(&sc->t[k][1], gpu_s_guest_ns(cb.GPUEndTime)); } seg_clk_put(sc); } if (cb.error) { atomic_store(&g_last_commit_error, 1); static int k; if (k++ < 8) MLOG("[RED] segment command buffer execution error: %s", cb.error.description.UTF8String); res_top_once(cb.error); } char where[64]; snprintf(where, sizeof where, "fence %llu, segment %u", (unsigned long long)cbs_fence, k); cbs_feedback(cbs, cb.error, where); + if (cb.error) subrec_failed(cbs_fence, sr_cb, cb.error, 0); // printed with the whole submission once its last command buffer is committed gpu_lost_check(cb.error, "segment"); }]; gmem_commit_patch(); diff --git a/dm/gfx/tests/Makefile b/dm/gfx/tests/Makefile index 9643eb09e1..b0c773aa51 100644 --- a/dm/gfx/tests/Makefile +++ b/dm/gfx/tests/Makefile @@ -150,6 +150,8 @@ check_t_ms_slot: t_ms_slot MTL_DEBUG_LAYER=1 ./t_ms_slot t_cbs_fault: t_cbs_fault.m $(MTL_T_DEP) clang $(CFLAGS) -fobjc-arc -o $@ t_cbs_fault.m $(MTL_T_SRC) $(FW) +t_gpu_watchdog: t_gpu_watchdog.m $(MTL_T_DEP) + clang $(CFLAGS) -fobjc-arc -o $@ t_gpu_watchdog.m $(MTL_T_SRC) $(FW) .PHONY: check_t_cbs_fault check_t_cbs_fault: t_cbs_fault ./t_cbs_fault @@ -216,6 +218,11 @@ t_ub: t_ub.m $(MTL_T_DEP) clang $(CFLAGS) -fobjc-arc -o $@ t_ub.m $(MTL_T_SRC) $(FW) t_gpuprof: t_gpuprof.m $(MTL_T_DEP) clang $(CFLAGS) -fobjc-arc -o $@ t_gpuprof.m $(MTL_T_SRC) $(FW) +t_mlcb_gpu: t_mlcb_gpu.m $(MTL_T_DEP) + clang $(CFLAGS) -fobjc-arc -o $@ t_mlcb_gpu.m $(MTL_T_SRC) $(FW) +.PHONY: check_t_mlcb_gpu +check_t_mlcb_gpu: t_mlcb_gpu + @MTL_DEBUG_LAYER=1 ./t_mlcb_gpu t_vbuf: t_vbuf.m $(MTL_T_DEP) clang $(CFLAGS) -fobjc-arc -o $@ t_vbuf.m $(MTL_T_SRC) $(FW) .PHONY: check_t_vbuf diff --git a/dm/gfx/tests/t_gpu_watchdog.m b/dm/gfx/tests/t_gpu_watchdog.m new file mode 100644 index 0000000000..f74e1fd100 --- /dev/null +++ b/dm/gfx/tests/t_gpu_watchdog.m @@ -0,0 +1,126 @@ +// The per-submission pipeline record (subrec_*) and the two reports that print it: the GPU hang watchdog (wd_check), when no fence completes for DM_NVN_GPU_WATCHDOG seconds, and +// a failed command buffer (subrec_failed), when macOS aborts a shader that ran too long and the fence completes with an error (issue #1326), so the watchdog never fires. +// Checks the record's contents (pairs once per command buffer, pass offsets, the overflow count), its text, and that a failure prints it once per fence in either handler order +#include "../nvn/nvn_mtl.m" +void *front_metal_layer(void) { return NULL; } +module_t *module_of(const void *p) { (void)p; return NULL; } +module_t *g_mod; int g_nmod; +void svc_thread_dump(void) {} +uint64_t now_ns(void) { return bp_now(); } +static int checks, failed; +#define CHECK(c, label) do { checks++; if (!(c)) { failed++; fprintf(stderr, "FAIL: %s\n", label); } } while (0) +static NSError *error(NSString *text) { return [NSError errorWithDomain:@"t" code:1 userInfo:@{NSLocalizedDescriptionKey: text}]; } +static NSString *const HANG = @"Impacting Interactivity (00000002:kIOGPUCommandBufferCallbackErrorHang)"; // macOS aborting a command buffer that ran too long +static NSString *const VICTIM = @"Discarded (victim of GPU error/recovery) (00000005:kIOGPUCommandBufferCallbackErrorInnocentVictim)"; +static int has(const char *s, const char *part) { return strstr(s, part) != NULL; } +// A record as subrec_fmt writes it, into buf +static const char *text(const subrec_t *r, uint32_t failed_cbs, char *buf, size_t size) { buf[0] = 0; subrec_fmt(buf, size, 0, r, failed_cbs); return buf; } +// Begins the record of a fence the way mtl_sub_begin and mtl_sub_commit bracket it, the commit leaving g_fence at that fence +static subrec_t *begin(uint64_t fence) { g_fence = fence - 1; subrec_begin(fence); return g_subrec_cur; } +static uint32_t commit(void) { uint32_t cb = g_subrec_cur->cb; g_fence++; g_subrec_cur = NULL; return cb; } +static int A, B, C, D; // stand-ins for programs and compute shaders: only their addresses matter (subrec_add's who) +int main(void) { @autoreleasepool { + char buf[SUBREC_LINE]; + // The record: a run of draws of one program costs one entry; a pair seen again in the same command buffer is not added twice; the next command buffer lists it again + g_stat_pass = 1000; subrec_t *r = begin(10); + subrec_add("aaaa", "bbbb", &A, 0); subrec_add("aaaa", "bbbb", &A, 0); subrec_add("cccc", "dddd", &B, 0); + g_stat_pass += 2; subrec_add("aaaa", "bbbb", &A, 0); subrec_add("-", "eeee", &C, 1); + CHECK(r->n == 3 && r->draws == 4 && r->dispatches == 1, "pairs once per command buffer, every draw and dispatch counted"); + CHECK(r->p[2].pass == 2 && r->p[0].pass == 0 && r->p[2].cb == 0, "each pair carries the pass it first ran in, from the submission's first"); + uint32_t cb0 = subrec_cut(); + g_stat_pass += 3; subrec_add("aaaa", "bbbb", &A, 0); subrec_add("ffff", "gggg", &D, 0); + CHECK(cb0 == 0 && r->cb == 1 && r->n == 5 && r->p[3].cb == 1 && r->p[3].pass == 5, "a segment cut starts the next command buffer's list, a pair it repeats included"); + uint32_t last = commit(); + subrec_add("zzzz", "zzzz", &A, 0); + CHECK(last == 1 && r->n == 5 && r->draws == 6, "draws after the commit leave the record alone"); + text(r, 1u << 1, buf, sizeof buf); + CHECK(has(buf, " fence 10 (frame 0, 6 draws, 1 dispatches, 2 command buffers, from pass 1000):"), "the header names the fence, its counts and its first pass"); + CHECK(has(buf, " cb 0: pass +0 aaaa/bbbb cccc/dddd pass +2 -/eeee | cb 1 FAILED: pass +5 aaaa/bbbb ffff/gggg;"), "pipelines per command buffer in order, the failed one marked"); + + // Overflow: past SUBREC_PAIRS only a count; the line stays within its buffer + r = begin(11); + static int who[SUBREC_PAIRS + 7]; + for (int i = 0; i < SUBREC_PAIRS + 7; i++) { char v[17], f[17]; snprintf(v, sizeof v, "%016x", i); snprintf(f, sizeof f, "%016x", ~i); subrec_add(v, f, &who[i], 0); } + commit(); + CHECK(r->n == SUBREC_PAIRS && r->n_more == 7, "a full record counts the rest"); + text(r, 0, buf, sizeof buf); + CHECK(has(buf, "(+7 more);") && strlen(buf) < sizeof buf - 1, "a full record fits one line and says how many more"); + char small[64]; small[0] = 0; int o = subrec_fmt(small, sizeof small, 0, r, 0); + CHECK(o == (int)sizeof small - 1 && strlen(small) == sizeof small - 1, "a line too short for the record is cut at its end, not past it"); + + // Draws through a pulling stand-in: counted in the header, their pair marked in its command buffer only + g_stat_pass = 2000; r = begin(13); + subrec_add("aaaa", "bbbb", &A, 0); subrec_add("cccc", "dddd", &B, 0); subrec_pull("aaaa", "bbbb"); subrec_cut(); subrec_add("aaaa", "bbbb", &A, 0); + commit(); + text(r, 0, buf, sizeof buf); + CHECK(r->pulls == 1 && has(buf, "from pass 2000, 1 draws through a pulling stand-in): cb 0: pass +0 aaaa/bbbb+pull cccc/dddd | cb 1: pass +0 aaaa/bbbb;"), "pulling draws counted, their pair marked"); + + // Task / mesh draws: a direct one's count and first, a GPU-written one's converted arguments as they are when printed; past SUBREC_MESH only counted + g_stat_pass = 2000; r = begin(12); + uint32_t args[8] = {0}; + subrec_mesh_add("a5288d0a6c4971fd", "a80a03d4747a70c7", "de4c1ebffd6c3960", 12, 3, NULL); + g_stat_pass += 4; subrec_cut(); subrec_mesh_add("a5288d0a6c4971fd", "842d6cfcc9e9df67", NULL, 0, 0, args); + setenv("DM_NVN_MESHLOG_CB", "2:3088", 1); // the second draw: four words of uniform register 2 at byte 3088, read when it was recorded + static uint32_t ub[1024]; ub[772] = 160; ub[773] = 90; ub[774] = 7; ub[775] = 0xdeadbeef; ub[771] = 1; + p_bind_buf ubo[16] = {0}; ubo[2] = (p_bind_buf){3, 2, (uintptr_t)ub, sizeof ub}; + subrec_mesh_words(ubo); + ub[772] = 0; // a later write is not what that draw saw + args[0] = 65535; args[4] = 40; + for (int i = 0; i < SUBREC_MESH; i++) subrec_mesh_add(NULL, "1111", "2222", 1, 0, NULL); + commit(); + CHECK(r->nm == SUBREC_MESH && r->nm_more == 2, "task / mesh draws past the record's room are counted"); + subrec_mesh_fmt(buf, sizeof buf, r); + char want[512]; snprintf(want, sizeof want, "[RED] task / mesh draws of the failed submission fence 12 (26, the first listed): cb 0 pass +0 a5288d0a6c4971fd/a80a03d4747a70c7/de4c1ebffd6c3960 direct 12 from 3," + " cb 1 pass +4 a5288d0a6c4971fd/842d6cfcc9e9df67/- indirect 65535 from 40 (task uniform words 0xa0 0x5a 0x7 0xdeadbeef at +3088 of the buffer bound at guest %#llx, size %zu, Metal GPU 0)," + " cb 1 pass +4 -/1111/2222 direct 1 from 0,", (unsigned long long)(uintptr_t)ub, sizeof ub); + CHECK(has(buf, want), "each task / mesh draw with its grid, a GPU-written one read at print time, the uniform words as recorded with where the buffer was bound (no pool: no GPU address, no 'now')"); + + // The same words from a buffer in a memory pool: its Metal GPU address, the memory as it is when the report prints (a later write shows), and the GPU's own copy when there is one + { void *mem = NULL; CHECK(!posix_memalign(&mem, getpagesize(), getpagesize()), "a page for the pool"); memset(mem, 0, getpagesize()); mtl_pool_add(mem, getpagesize()); + uint32_t *pw = mem; pw[772] = 160; pw[773] = 90; pw[774] = 7; pw[775] = 1; + static const uint32_t gpu_saw[4] = {160, 90, 7, 0x7fffffff}; + r = begin(14); subrec_mesh_add("a5288d0a6c4971fd", "a80a03d4747a70c7", "de4c1ebffd6c3960", 12, 3, NULL); + p_bind_buf ub2[16] = {0}; ub2[2] = (p_bind_buf){3, 2, (uintptr_t)mem, 4096}; g_mlcb_gw = gpu_saw; subrec_mesh_words(ub2); + CHECK(r->m[0].cb_gpu != 0 && r->m[0].gw == gpu_saw && g_mlcb_gw == NULL, "the GPU address of the bound buffer and the GPU copy's slot are recorded, the slot taken once"); + pw[775] = 0xbad; commit(); + subrec_mesh_fmt(buf, sizeof buf, r); + snprintf(want, sizeof want, "(task uniform words 0xa0 0x5a 0x7 0x1 at +3088 of the buffer bound at guest %#llx, size 4096, Metal GPU %#llx; now 0xa0 0x5a 0x7 0xbad; GPU copy ahead of the draw 0xa0 0x5a 0x7 0x7fffffff)", + (unsigned long long)(uintptr_t)mem, (unsigned long long)r->m[0].cb_gpu); + CHECK(has(buf, want), "the report prints the words at encode, the memory now and the GPU's copy side by side"); } + + // The error path: a failed command buffer prints the record once its submission is closed, once per fence + r = begin(20); subrec_add("aaaa", "bbbb", &A, 0); uint32_t s0 = subrec_cut(); subrec_add("cccc", "dddd", &B, 0); last = commit(); + CHECK(!subrec_failed(20, s0, error(HANG), 0), "a failed segment waits for its submission's last command buffer"); + CHECK(subrec_failed(20, last, nil, 1), "the last command buffer's handler prints it, though it succeeded"); + CHECK(!subrec_failed(20, last, error(HANG), 1) && !subrec_failed(20, s0, error(HANG), 0), "once per fence"); + r = begin(30); subrec_add("aaaa", "bbbb", &A, 0); subrec_cut(); commit(); + text(r, 1u << 1, buf, sizeof buf); + CHECK(has(buf, " cb 0: pass +0 aaaa/bbbb | cb 1 FAILED: none listed;"), "a failed command buffer with no draw of its own is named too"); + + r = begin(21); subrec_add("aaaa", "bbbb", &A, 0); s0 = subrec_cut(); subrec_add("cccc", "dddd", &B, 0); last = commit(); + CHECK(!subrec_failed(21, last, nil, 1), "a submission whose command buffers all succeeded prints nothing"); + CHECK(subrec_failed(21, s0, error(HANG), 0), "a segment whose handler runs after the last one prints itself"); + + r = begin(22); subrec_add("aaaa", "bbbb", &A, 0); last = commit(); + CHECK(!subrec_failed(22, last, error(VICTIM), 1), "a victim of another's fault ran nothing of its own"); + CHECK(!subrec_failed(23, 0, error(HANG), 1), "a fence with no record prints nothing"); + + r = begin(24); subrec_add("aaaa", "bbbb", &A, 0); last = commit(); + begin(24 + SUBREC_RING); commit(); + CHECK(!subrec_failed(24, last, error(HANG), 1), "a record the ring has rewritten is not printed under the old fence"); + + int printed = 0; + for (int i = 0; i < SUBREC_REPORTS + 4; i++) { uint64_t f = 100 + (uint64_t)i; begin(f); subrec_add("aaaa", "bbbb", &A, 0); last = commit(); printed += subrec_failed(f, last, error(HANG), 1); } + CHECK(printed == SUBREC_REPORTS - 2, "reports stop after SUBREC_REPORTS fences (two printed above)"); + + // The watchdog: no fence completed for longer than DM_NVN_GPU_WATCHDOG seconds with work in flight names the oldest fence in flight, once + setenv("DM_NVN_GPU_WATCHDOG", "1", 1); + begin(200); subrec_add("aaaa", "bbbb", &A, 0); commit(); begin(201); commit(); + g_done = 199; + uint64_t t0 = ws_t0() - 2000000000ull; + CHECK(wd_check(201, WS_ALLOC, &t0, 199) == 199 && atomic_load(&g_wd_reported) == 200, "a stuck GPU is reported, naming the oldest fence in flight"); + atomic_store(&g_wd_reported, 0); g_done = 201; t0 = ws_t0() - 2000000000ull; + wd_check(201, WS_ALLOC, &t0, 201); + CHECK(atomic_load(&g_wd_reported) == 0, "nothing in flight: no report"); + printf("GPU watchdog and failed submission pipelines: %d checks, %d failed\n", checks, failed); return failed != 0; +} } diff --git a/dm/gfx/tests/t_mlcb_gpu.m b/dm/gfx/tests/t_mlcb_gpu.m new file mode 100644 index 0000000000..6a0e0ab30c --- /dev/null +++ b/dm/gfx/tests/t_mlcb_gpu.m @@ -0,0 +1,36 @@ +// DM_NVN_MESHLOG_CB_GPU: a task draw's uniform words copied by the GPU in queue order (mlcb_gpu_copy), next to what the CPU read when the draw was encoded (subrec_mesh_words) +#include "../nvn/nvn_mtl.m" +void *front_metal_layer(void) { return NULL; } +module_t *module_of(const void *p) { (void)p; return NULL; } +module_t *g_mod; int g_nmod; +void svc_thread_dump(void) {} +uint64_t now_ns(void) { return bp_now(); } +static int checks, failed; +#define CHECK(c, label) do { checks++; if (!(c)) { failed++; fprintf(stderr, "FAIL: %s\n", label); } } while (0) + +int main(void) { @autoreleasepool { + setenv("DM_NVN_MESHLOG_CB", "2:16", 1); setenv("DM_NVN_MESHLOG_CB_GPU", "1", 1); + mtl_init(); + void *mem = NULL; if (posix_memalign(&mem, getpagesize(), getpagesize())) return 1; + memset(mem, 0, getpagesize()); mtl_pool_add(mem, getpagesize()); + uint32_t *w = mem; w[4] = 1; w[5] = 2; w[6] = 3; w[7] = 4; + NvShader *ts = [NvShader new]; + mtl_sub_begin(); state_reset(); memset(&R, 0, sizeof R); + S.ubo[3][2] = (p_bind_buf){.addr = (uint64_t)mem, .size = 1024}; + subrec_t *r = g_subrec_cur; CHECK(r != NULL, "the submission has a record"); + mlcb_gpu_copy(ts); + const volatile uint32_t *slot = g_mlcb_gw; CHECK(slot != NULL, "the copy handed out its slot"); + CHECK(slot && slot[0] == 0xfeedface && slot[3] == 0xfeedface, "the slot says 'not run' until the GPU has copied"); + subrec_mesh_add("a5288d0a6c4971fd", "a80a03d4747a70c7", "de4c1ebffd6c3960", 12, 3, NULL); + subrec_mesh_words(S.ubo[3]); + CHECK(g_mlcb_gw == NULL && r->m[0].gw == slot && r->m[0].has_words, "the record took the slot once"); + CHECK(r->m[0].words[0] == 1 && r->m[0].words[3] == 4, "the CPU's words are those at encode time"); + w[4] = 9; w[5] = 9; w[6] = 9; w[7] = 9; // written after the draw was encoded, before the GPU ran it: the GPU copy sees this, the CPU's words do not + uint64_t fence = mtl_sub_commit(); CHECK(mtl_wait(fence, 2000000000ull), "the copy completes"); mtl_drain(); + CHECK(!mtl_last_commit_error(), "no GPU error"); + CHECK(slot && slot[0] == 9 && slot[1] == 9 && slot[2] == 9 && slot[3] == 9, "the GPU copied the memory as it was when it ran"); + CHECK(r->m[0].words[0] == 1, "the CPU's words stay the encode-time ones"); + char buf[SUBREC_LINE]; subrec_mesh_fmt(buf, sizeof buf, r); + CHECK(strstr(buf, "words 0x1 0x2 0x3 0x4 at +16") && strstr(buf, "; now 0x9 0x9 0x9 0x9; GPU copy ahead of the draw 0x9 0x9 0x9 0x9)"), "the report prints all three"); + printf("t_mlcb_gpu: %d checks, %d failed\n", checks, failed); return failed != 0; +} } diff --git a/docs/agents/symptoms.md b/docs/agents/symptoms.md index f1d471850e..2c93afc1e8 100644 --- a/docs/agents/symptoms.md +++ b/docs/agents/symptoms.md @@ -608,6 +608,7 @@ One line per symptom in the [subsystem references](../reference/): what you see - `texture type mismatch: shader declares 2, texture is 9`; the slot read 0. → [Buffer textures read by 1D integer fetches (row wrap)](../reference/rendering.md#buffer-textures-read-by-1d-integer-fetches-row-wrap) - none of its own seen here. Pull request #984 reports GPU hangs from huge light counts on its build of the same game. → [Integer buffer textures read through float slots](../reference/rendering.md#integer-buffer-textures-read-through-float-slots) - none visible on an M6, where at most 0.23 % of pixels differ between paired runs. GitHub issue #783 reports wrong light offsets on an M2. → [Integer textures read through float slots](../reference/rendering.md#integer-textures-read-through-float-slots) +- the picture freezes while the game keeps running (its threads poll and wait), the log stops after an ordinary frame, `ioreg -r -c AGXAccelerator -d 1` shows Device, Renderer and Tiler Utilization at 100 % for minutes, no GPU restart in the unified log; a `sample` of the host shows the submit thread in `mtl_wait_at` (site WS_ALLOC: every command allocator in flight) under `mtl_sub_begin`, and Metal's submission queue thread inside the kernel trap `IOGPUCommandQueueSubmitCommandBuffers`. → [A GPU that never finishes: the hang watchdog](../reference/rendering.md#a-gpu-that-never-finishes-the-hang-watchdog) - particle effects drawn at the wrong scale or place, or flickering, where the particle data is a buffer texture at a pool offset that is not a multiple of 16; log line `buffer texture at pool offset …, below Metal's 16-byte alignment`. → [Buffer textures at offsets below 16 bytes](../reference/rendering.md#buffer-textures-at-offsets-below-16-bytes) - lighting that alternates between lit and unlit from one frame to the next on an iPhone, the same scene steady on a Mac; log lines `texture buffer (texture ID …, … at pool offset …) has no 2D-row form for a wrapped 1D fetch: the slot reads 0` and `texture type mismatch: … a buffer texture: the slot reads 0 (dummy)`. → [Buffer texture rows at a pool offset the device will not view](../reference/rendering.md#buffer-texture-rows-at-a-pool-offset-the-device-will-not-view) - torn digits and a background in blue steps (Rhythm Heaven Groove's latency calibration). → [Automatic block height truncates](../reference/rendering.md#automatic-block-height-truncates) diff --git a/docs/env_switches.tsv b/docs/env_switches.tsv index a63ca6e93b..5d45464c65 100644 --- a/docs/env_switches.tsv +++ b/docs/env_switches.tsv @@ -155,6 +155,9 @@ DM_NVN_GEO_MESH switch `0` draws passthrough geometry pairs that have a mesh lib DM_NVN_GEO_MESH_RUN switch `0` dispatches every mesh geometry draw on its own; by default consecutive mesh draws of one pair whose result does not depend on their order are drawn as one dispatch (`geo_mesh_take`) DM_NVN_GPUPROF diagnostic `=`, `-` or `every:`: logs the GPU start and duration of every encoder of those frames (`[gpuprof]` lines from Metal 4 counter heap timestamps) DM_NVN_GPU_TS switch `segment` or `submission`: what timestamp reports record (GPU start / end of the segment holding each report, or one time for the whole submission), instead of the profile's `gpu_timestamps` +DM_NVN_GPU_WATCHDOG diagnostic `=` (5 by default, `0` off): a wait for the GPU that sees no submission complete for that long while some are in flight logs a `[RED] GPU watchdog` line naming the pipelines of the oldest submission in flight (the one the GPU is stuck on; Metal cannot abort it), instead of blocking in silence. A submission macOS aborted completes with an error instead: its pipelines are printed then whatever this is set to (`[RED] pipelines of the failed submission`) +DM_NVN_MESHLOG_CB diagnostic `=:`: the failure report's task / mesh draws also show four words of the task stage's uniform buffer in that register at that offset, as the CPU saw them at encoding, with where that buffer was bound (guest address, size, Metal GPU address) and the same four words as the memory holds when the report prints (Ocarina of Time's foliage task: `0:3088`, its occlusion grid size) +DM_NVN_MESHLOG_CB_GPU diagnostic `=1` with `DM_NVN_MESHLOG_CB`: before each task draw the render pass is ended and the same four words are copied by the GPU, in queue order, into a host buffer; the failure report prints them as the GPU's copy (0xfeedface when the copy never ran). It splits the pass at every task draw, so it can change what hangs: for seeing the value, not counting hangs DM_NVN_HILITE diagnostic `=,…`: those draws use a solid colour instead (magenta, green, cyan, yellow, blue, white in order), to tell wrong geometry from wrong shading DM_NVN_INDLOG diagnostic `=`: the first n indirect draws (and those of pass-dumped frames) log their arguments at encode and as the GPU left them once the submission completed, with the first indices DM_NVN_IXCLOG diagnostic `=` logs the first n indirect draw and dispatch conversions (record to arguments) once the GPU has run them @@ -181,7 +184,7 @@ DM_NVN_SHDUMP diagnostic `=` saves programs missing from the shader map as DM_NVN_SHMAP path The shader map (`shader_map.tsv`); `c1_full.tsv` and `pso_manifest.tsv` are taken from the same folder. Default: the game profile's folder on the Mac; the iOS app sets it DM_NVN_SHOT diagnostic `=[,…]:` saves the swapchain texture as an image at those frames (`%d` in the path = frame number) DM_NVN_SHOT_OUT diagnostic `=x` makes `DM_NVN_SHOT` capture the picture as the present pass upscales it to that size, the crop included, instead of the raw swapchain texture -DM_NVN_SKIP_FS diagnostic `=[,…]` (up to 16) drops all draws of those fragment shaders, to measure their GPU cost or bisect a wrong draw; the picture is wrong +DM_NVN_SKIP_FS diagnostic `=[,…]` (up to 16) drops all draws of those fragment shaders, to measure their GPU cost, bisect a wrong draw, or play on past a fragment shader that hangs the GPU (the one the `DM_NVN_GPU_WATCHDOG` line names); the picture is wrong where they drew DM_NVN_SKIP_MESH diagnostic `=1` drops every task and mesh draw, to measure what they cost in all; the picture is wrong DM_NVN_SKIP_SMALL diagnostic `=` drops all draws whose target width is at most that, to measure the cost of tiny render passes; the picture is wrong DM_NVN_SLICE_MERGE switch `0` keeps passes into other layers of one array or cube texture level apart (on by default: they run as one layered pass) diff --git a/docs/reference/rendering.md b/docs/reference/rendering.md index cc0bef118e..527c5bf702 100644 --- a/docs/reference/rendering.md +++ b/docs/reference/rendering.md @@ -178,6 +178,15 @@ The replay on Metal (`dm/gfx/nvn/nvn_mtl.m`) and the Vulkan and OpenGL layers. E - **Found on:** [Metroid Prime Remastered](../../dm/games/010012101468C000/README.md): the clustered lighting's R32Uint light grid (`fde1a3e769219a77` and the other world materials). Reported and fixed by nobz226. - **Check:** `t_int_float_view` reads small integers (denormal floats), NaN patterns and negatives through the R32Float view in a compute shader and takes back every bit. +### A GPU that never finishes: the hang watchdog + +- **Symptom:** the picture freezes while the game keeps running (its threads poll and wait), the log stops after an ordinary frame, `ioreg -r -c AGXAccelerator -d 1` shows Device, Renderer and Tiler Utilization at 100 % for minutes, no GPU restart in the unified log; a `sample` of the host shows the submit thread in `mtl_wait_at` (site WS_ALLOC: every command allocator in flight) under `mtl_sub_begin`, and Metal's submission queue thread inside the kernel trap `IOGPUCommandQueueSubmitCommandBuffers`. +- **Cause:** a shader that never ends (a loop whose count is a fetched texel, as KTGL's light-list loops, or a translation or data fault) keeps the GPU busy without a fault, so no command buffer completes, `g_done` stops and every CPU wait for the GPU blocks for good: the allocator wait of the next submission had no timeout, and the host froze in silence. Metal cannot abort GPU work. +- **Fix:** every blocking wait for the GPU runs in slices of two seconds; a wait that sees no fence complete for `DM_NVN_GPU_WATCHDOG` seconds (5 by default) while submissions are in flight logs one `[RED] GPU watchdog` line per stuck fence, naming the frame, draw and dispatch counts and the distinct vertex / fragment pairs and compute shaders of the oldest submission in flight (the one the GPU is stuck on; the GPU runs them in order) and of the two after it, from a record each submission keeps (`subrec_add` in `nvn_mtl.m`, filled by `draw_` and `dispatch`): per command buffer of the submission (`cb 0`, `cb 1` after a segment cut), in the order they first ran there, each run marked with the render pass it began in, counted from the submission's first (`pass +N`; the header gives that first pass's number, the one `DM_NVN_PASSDUMP` lines carry). The first 48 pairs are listed and the rest counted. The line ends with the way to play on: `DM_NVN_SKIP_FS=` (the title's `env.txt` on the Mac) drops the draws of a fragment shader named there. The hang itself is not recovered: the process has to be quit. +- **Found on:** [Hyrule Warriors: Age of Imprisonment](../../dm/games/04003F40232DE000/README.md#gpu-hang-in-a-battle-open): the first outpost mission froze while a special attack filled the screen, 18 minutes in at 60 fps; the pipelines compiled at that instant hold the light-list loops. Not reproduced yet: its first battle, at 1x and 2x, runs the same pixel shaders with empty light lists (every cluster count 0) and never hangs. +- **Aborted instead:** when macOS ends the work itself (a command buffer that ran too long comes back `kIOGPUCommandBufferCallbackErrorHang`), its fence completes with an error and the watchdog never fires; the same record is printed in the error path then ([Naming the shaders of a GPU fault](#naming-the-shaders-of-a-gpu-fault)). +- **Check:** `make -C dm/gfx/tests GAME= check_t_gpu_watchdog` (the record, its text, the report once per stuck fence); `DM_NVN_GPU_WATCHDOG=1` on a game whose GPU work exceeds a second (a `DM_NVN_PASSDUMP_ALL` frame with uniform dumps) logs the line and the run goes on. + ### Buffer textures at offsets below 16 bytes - **Symptom:** particle effects drawn at the wrong scale or place, or flickering, where the particle data is a buffer texture at a pool offset that is not a multiple of 16; log line `buffer texture at pool offset …, below Metal's 16-byte alignment`. @@ -600,9 +609,11 @@ The replay on Metal (`dm/gfx/nvn/nvn_mtl.m`) and the Vulkan and OpenGL layers. E - **Cause:** Metal 4's commit feedback gives only the error and two times, so the log can name a submission but no pass or shader. `MTL_SHADER_VALIDATION=1` can name one, at about a fifth of the frame rate, which is little use for a fault several minutes into a game. - **Fix:** each command buffer keeps the list of the game shaders it encoded (`cbs_note` in `encode_args`, one comparison per binding once a shader is listed). On an error that command buffer caused, the log has `[RED] game shaders of failed command buffer #N (fence F, segment K): …`, then `[RED] game shaders by failed/ran over N failed of M command buffers: key failed/ran, …`, most often failed first: in how many failed command buffers the shader was, of how many that encoded it. Read the second line of the last report: a shader in most failures with a high ratio is the suspect; one that runs everywhere has a low ratio. A victim of another's fault and a submission refused after one do not count. The first 16 failures are printed. The lists leave out the host's own passes and geometry emulation's kernels, so no shader standing out points there. Nothing here shows a shader is wrong, only that it was present: check it with validation or by reading what it addresses. A validation run must not share a `pso_archive` with normal runs: they cannot use the files it writes. - **What can fault:** measured on an M4 Pro, with a Metal 4 queue: loads and atomics through a buffer address that is unmapped, freed, not resident or null, from compute or fragment shaders, raise no error (reads give 0 or whatever is mapped there, so an overrun can silently write into another allocation). A fragment shader sampling a texture not in the residency set, or one freed whose resource ID nothing holds, raises `PageFault`; after two of these macOS refused every later submission. A freed texture's resource ID goes to the next texture made, and a stale binding then reads that texture with no error. Other chips may differ. +- **Pipelines of the failed submission:** after those lines, once the submission's last command buffer has come back, `[RED] pipelines of the failed submission (…): fence F (frame N, D draws, X dispatches, C command buffers, from pass P): cb 0: pass +0 vs/fs … | cb 1 FAILED: pass +3 vs/fs -/cs …;`, the record [the hang watchdog](#a-gpu-that-never-finishes-the-hang-watchdog) keeps for every submission, once per fence, for the first 16 fences with a failure of their own (`subrec_failed`). The shader lists above have each game shader once per command buffer, vertex, fragment and compute alike, and rank them across failures. This record has, for the one failed submission, which vertex shader drew with which fragment shader, the compute shaders and the host's own builtins by name, grouped by command buffer with the failed ones marked, in the order they first ran and with the render pass each began in. A failed segment's handler leaves a mark and the record is printed when the last command buffer's handler runs, as the record is complete only after the last commit. Ocarina of Time's hangs (issue #1326) are of this kind: macOS aborts the work, the fence completes with an error, and the watchdog, which needs a fence that never completes, never fires. +- **Task / mesh draws, pulling stand-ins and the task's uniform words:** the record also keeps every task / mesh draw of the submission (up to 24, the rest counted): `[RED] task / mesh draws of the failed submission fence F (N): cb K pass +P task/mesh/fragment direct COUNT from FIRST, …` (a GPU-written draw prints the count of the copy `mdx_run` made, read when the report prints). A draw that went through its pulling stand-in (hybrid pipelines) is counted in the header (`, N draws through a pulling stand-in`) and its pair is marked `+pull`. `DM_NVN_MESHLOG_CB=:` (off by default) adds, to each listed draw with a task shader, four words of the task stage's uniform buffer in that register (Ocarina of Time's foliage task `a5288d0a6c4971fd` bounds its occlusion loops by the grid size at `c3[193]`: `0:3088`): as the CPU read them when the draw was encoded, where the buffer was bound (guest address, size, Metal GPU address), and the memory as it is when the report prints (a difference is a write after the draw was encoded). With `DM_NVN_MESHLOG_CB_GPU=1` too, the render pass is ended before each task draw and the same four words are copied by the GPU, in queue order, into a host buffer, and the report prints them as `GPU copy ahead of the draw` (`0xfeedface` when that copy never ran): what the GPU read, not what the CPU holds. **It splits the pass at every task draw, so it can change whether a hang happens**; use it to see a value, not to count hangs. Checks: `check_t_gpu_watchdog` (the lines), `check_t_mlcb_gpu` (the GPU copy sees a write made after the draw was encoded). - **Early release:** `DM_RES_CHECK=1` also reports `[RED] released too early`: an object retired behind an earlier fence than a binding of it. Its `missing residency` line cannot see this, as the object is still in the set at that binding. - **Found on:** [Splatoon Raiders](../../dm/games/0400380020056000/README.md) ([issue #1289](https://github.com/seedds/nxnative/issues/1289)), whose faults recur every minute or so before a fatal one. -- **Check:** `make -C dm/gfx/tests GAME= check_t_cbs_fault`. +- **Check:** `make -C dm/gfx/tests GAME= check_t_cbs_fault`; `check_t_gpu_watchdog` for the pipelines line (a failed segment printed with its submission, in either handler order, once per fence; victims left out). ### A present snapshot's copy needs the same residency commit