From 46d4f03e5a491dc7853b434deca2252294ee85bb Mon Sep 17 00:00:00 2001 From: James Dansereau <106631954+jkdansereau@users.noreply.github.com> Date: Sat, 29 Aug 2026 23:32:17 -0400 Subject: [PATCH] D134: task-done SP/DP events must not be dropped into a full sched interruptQ The frame-2 boot hang blamed on D117 flakiness since M-13 is a real bug: osSpTaskStartGo posted OS_EVENT_SP/DP with OS_MESG_NOBLOCK into the 8-slot scheduler interruptQ that the 60 Hz VI pacemaker also fills. A gfx task runs the whole frame synchronously on the sched thread, so a slow early frame lets retraces fill the queue and the done event is silently discarded -> curRSPTask never clears -> pendingGfx never clears -> permanent stall. portPostEventForce() drops the oldest (stale retrace) message and retries; portPostVIEvent reserves 2 slots. -level_09: 6/6 boots to frame 600, 0 heartbeats (pre-fix 1/3). Also hardens tools_pc/level_sweep.sh: 45s watchdog, lockdir serialization, stray-process kill, one retry on NO-FRAMES. --- docs/HANDOFF.md | 14 ++++++ docs/PCPortResearch.md | 1 + docs/PORT-LEARNINGS.md | 15 +++++++ port/src/libultra.c | 36 ++++++++++++++-- tools_pc/level_sweep.sh | 95 ++++++++++++++++++++++++++++++++++------- 5 files changed, 142 insertions(+), 19 deletions(-) diff --git a/docs/HANDOFF.md b/docs/HANDOFF.md index d80d6550..f2744fc0 100644 --- a/docs/HANDOFF.md +++ b/docs/HANDOFF.md @@ -152,6 +152,20 @@ Full workstream breakdown (WS1–WS6) in `docs/PLAN-linear-level-sweep.md`. ## Next task +-1. **D134 DONE (M-22)** — the frame-2 boot hang that every session since + M-13 wrote off as "sweep flakiness / D117 / machine load" was a **real, + fixed bug**: the SP/DP task-done event was posted `OS_MESG_NOBLOCK` into + the sched `interruptQ` that the 60 Hz VI pacemaker also fills, so a slow + synchronous fast3d frame let a retrace backlog swallow the done event → + permanent stall. Fix in `port/src/libultra.c` (`portPostEventForce` + + 2 reserved slots in `portPostVIEvent`). `-level_09` 6/6 boots to frame 600, + 0 heartbeats (pre-fix 1/3). §F/§H **D134**, PORT-LEARNINGS §E. + **Consequence: re-run the full 21-level sweep** — several NO-FRAMES / + "hang" rows in `docs/LEVEL-STATUS.md` (incl. the M-20 Facility/Jungle + re-verify failures) are probably this and may now pass. `level_sweep.sh` + is also hardened this session (45 s watchdog, lockdir serialization, + stray-process kill, one retry on NO-FRAMES). + 0. **D132 DONE (M-21, commit `fa296b17`)** — propDef union-index slots for types 14/19/38/44 (LINK/SWITCH/LOCK_DOOR/SAFE_ITEM) now emitted at the right PC offsets (`d88_propdefs.py` + `loadobjectmodel.c sizepropdef` diff --git a/docs/PCPortResearch.md b/docs/PCPortResearch.md index 6c4fda91..aa491e9a 100644 --- a/docs/PCPortResearch.md +++ b/docs/PCPortResearch.md @@ -824,6 +824,7 @@ covers D24–D69; the log continues in §H (D32 procedure, D70–D121). | D124 | crash class C2: fast3d bad texture pointer. **Jungle** (`0xabcd0824`): `gimgSyncCompiledGlobalDLs()` slot-detect keyed on the post-fixup marker, which `texLoad()` had already overwritten → compiled `globalDL_0xNNN` explosion DLs kept link-time `IMAGESEG` words → latent on every level, tripped by the first explosion-DL draw. **Facility** (`0x72181ee8`): see **D130** — the model-GDL-relocation hypothesis (M-14 addendum) was WRONG; real cause was `romdataFixupFont` | Jungle fixed (`port/src/gimgfixup.c`); Facility → D130 | | D131 | crash class C2m (Jungle `-level_37`): fast3d `gfx_sp_matrix` AV on a wild matrix pointer `0x401c68e0` (`gfx_pc.cpp:1046`) ~frame 300, when the first explosion/smoke prop renders. `explosionRenderPropSmoke` builds `gSPMatrix(gdl++, osVirtualToPhysical((void*)&dword_CODE_bss_8007A100), …MODELVIEW)` (+ `applyRoomMatrixToDisplayList`). `osVirtualToPhysical()` is a `u32`-returning shim (`libultra.c:1207`) → truncates the compiled `.bss` symbol's `0x1_00000000` module high word → w1 = `0x40xxxxxx` → `seg_addr()` returns it raw. Same class as D94 (chraction 32-bit ptr truncation), but in a GBI DL word. The projection matrix in the same DL is fine (`get_BONDdata_field_10E0()` is a runtime `0x70xxxxxx` ptr, fits u32); the `gSPDisplayList(&globalDL_0xNNN)` refs are fine (port `Gwords.w1` is 64-bit `uintptr_t`, no macro truncation). ~30 `osVirtualToPhysical()` sites exist (`explosion.c`, `glass*.c`, `blood_animation.c`, `bondview2.c`) — all latent until that effect first draws. | resolved — `seg_addr()` restores the module high word for any fallthrough w1 in `[0x40000000, 0x70000000)` (module fixed-based at `0x140000000`, no ASLR; DRAM/KSEG0/segmented/phys all handled earlier). Jungle renders to frame 2400+ clean; `-level_20`/`-level_24` unregressed. **18→19/21.** (`-level_09` has a separate pre-existing boot crash, see below.) | | D133 | intro render triage (M-20): the "intro renders mostly black" item in the M-18/M-19 handoff is **NOT a regression** — it is the D75/D76 parked-cosmetic steady state. M-17 (`9ec6121e`), whose handoff claimed "the entire intro renders — logos → gun barrel → cast", was built in a scratch worktree and captured with the same `GE_PCDUMP="20-900:20"` window: coverage is **pixel-identical** to HEAD `0b5f5d1a` (legal screen 6677 non-clear px / 2.17% on both; centred-logo frames ~7% on both; near-black between). 2D/text/texture layers draw; animated character-model layers (Nintendo-logo transform, gun-barrel Bond, cast models) never appear = D75 exactly. No cheap regression to fix; parked. Secondary: Facility `-level_34` + Jungle `-level_37` re-verify FAILED this pass (boot crash / frame-2 hang) — flagged in LEVEL-STATUS for a clean-machine re-check, not investigated (scope). | not a regression — parked (D75/D76, `GRAPHICS-BACKLOG.md`) | +| D134 | **Frame-2 boot hang / sweep "NO-FRAMES" flakiness — root-caused and fixed (M-22).** `osSpTaskStartGo` (port/src/libultra.c) posted the SP/DP task-done events with `OS_MESG_NOBLOCK` into the scheduler's 8-slot `interruptQ`, which the 60 Hz VI pacemaker thread also fills with `VIDEO_MSG`. A gfx task runs the whole frame synchronously on the sched thread (fast3d); the first two frames take 30-80 ms, so the pacemaker queues several retraces meanwhile. Once the queue is full the RSP-done post is **silently dropped** -> `__scMain` never clears `sc->curRSPTask` -> the client never gets `OS_SC_DONE_MSG` -> `bossMainloop`'s `pendingGfx` never clears -> permanent stall (log: `frame 2 rendered`, then `kernel heartbeat ... frames=2`, retrace queue pinned at `valid=8/8 ret=-1`). Reproduced 2 of 3 `-level_09` boots on an idle machine, i.e. most of what M-13..M-21 wrote off as D117 nondeterminism / machine load. `OS_MESG_BLOCK` is NOT the fix (the done event is posted from the sched thread, the queue's only consumer -> self-deadlock): `portPostEventForce()` drops the OLDEST message (always a stale retrace) and retries, and `portPostVIEvent` now reserves 2 slots. Verified: 6/6 `-level_09` boots reach frame 600 with 0 heartbeats (pre-fix 1/3). | FIXED (`port/src/libultra.c`) | | D130 | crash class C2 (Facility `-level_34`, Runway `-level_35`): `import_texture_i8` AV on a wild texture pointer (`0x72181ee8`), baked into the HUD glyph DL by `gDPLoadTextureBlock(gdl, curchar->pixeldata, …)` when the level-title string ("Chemical Warfare Facility #2") renders `#`/`"`. Root cause: `romdataFixupFont` (`port/src/romdata.c`) converts the N64 24B fontchar array to the PC 32B array **in place**, forward-field, backward-glyph. PC−N64 stride = 8, so for glyphs 0/1/2 `d` overlaps `s` by less than the 24B read span and an early field write clobbers a later field's source mid-`for k<5` loop → glyph 1's `width` = `bswap(index)` = `0x01000000`, glyph 2's `pixeldata` = `pcPixOff+(index−pixStart)` ≈ `0x020002e8` → `+= font_base` → wild → fast3d AV. On N64 the array is read-only rodata, never re-laid-out, so no bug there. NOT the model-GDL relocation (`sub_GAME_7F0762E0` / `texLoadFromGdl`) the D124-Facility addendum suspected — `gdl` there is still a segmented `0x05xxxxxx` value so the `& 0x00ffffff` masks are correct, and `texLoadFromGdl` never copies a `G_SETTIMG` for these levels. | resolved — stage all 6 N64 fields in a local `f[6]` before writing any. Facility + Runway now PASS (16→18/21). Probes reverted. | Phase 2 replaced the Phase-1 demo loop with the real `mainproc()` on real OS diff --git a/docs/PORT-LEARNINGS.md b/docs/PORT-LEARNINGS.md index 93432d84..1d6582b9 100644 --- a/docs/PORT-LEARNINGS.md +++ b/docs/PORT-LEARNINGS.md @@ -264,6 +264,21 @@ deprioritised below level-progression / crash work. See independently-built binaries proves the path is unchanged → not a regression, don't bisect. Clean up the worktree with `git worktree remove --force` (safe only because `data/` was copied). +- **D134 — a dropped `OS_MESG_NOBLOCK` "interrupt" event is a permanent + stall, and it looks exactly like D117 flakiness.** The port's SP/DP + task-done events shared the scheduler's 8-slot `interruptQ` with the 60 Hz + VI pacemaker. A gfx task runs the whole frame *synchronously on the sched + thread*, so a slow frame lets the pacemaker fill the queue and the done-post + is silently discarded → `curRSPTask` never clears → no further frames + (`frames=2` heartbeat, retrace queue pinned `valid=8/8 ret=-1`). Rule: + classify every posted event as **droppable** (retrace — N64 drops these too) + or **must-arrive** (task done, DMA done); a must-arrive event needs + guaranteed delivery, and `OS_MESG_BLOCK` is wrong whenever the poster runs + on the queue's only consumer thread (self-deadlock) — drop the oldest + droppable message instead, and reserve slots in the pacemaker. + **Before blaming a hang on D117 / machine load, run it N times and count**: + this reproduced 2 of 3 boots on an idle machine and had been written off as + sweep flakiness for ~8 sessions. - **Watch item: `osYieldThread` = `Sleep(0)`.** The one place we fake cooperative behavior. If a level-sweep hot loop misbehaves under host load, this shim is the first thing to inspect. Keep as-is until then. diff --git a/port/src/libultra.c b/port/src/libultra.c index da02bc85..4f771282 100644 --- a/port/src/libultra.c +++ b/port/src/libultra.c @@ -579,6 +579,32 @@ void osSetEventMesg(OSEvent e, OSMesgQueue *mq, OSMesg msg) } } +/* D134: an SP/DP "task done" event must NEVER be dropped. + * + * These land in the scheduler's 8-slot interruptQ, which the 60 Hz VI + * pacemaker also posts VIDEO_MSG into. osSpTaskStartGo runs the whole frame + * synchronously on the sched thread (fast3d), so a slow frame (the first two + * are 30-80 ms) lets the pacemaker queue several retraces meanwhile. Once the + * queue is full the NOBLOCK done-post is silently discarded, __scMain never + * clears sc->curRSPTask, the client never gets OS_SC_DONE_MSG, and the main + * loop's pendingGfx never clears -> permanent stall at frames=2. + * + * OS_MESG_BLOCK is NOT the fix: the done event is posted from the sched thread + * itself, the only consumer of that queue, so blocking self-deadlocks. Instead + * make room by dropping the OLDEST message (always a stale retrace -- retrace + * drops are already normal, N64 osViSetEvent posts NOBLOCK too). */ +static void portPostEventForce(OSId e) +{ + PortEvent *ev = &g_events[e]; + if (!ev->used || !ev->mq) return; + if (osSendMesg(ev->mq, ev->msg, OS_MESG_NOBLOCK) == 0) return; + (void)osDequeueMesg(ev->mq); + if (osSendMesg(ev->mq, ev->msg, OS_MESG_NOBLOCK) != 0) { + sysLogPrintf(LOG_ERROR, "D134: task-done event %d lost (mq=%p full)", + (int)e, (void *)ev->mq); + } +} + static void portPostEvent(OSId e) { PortEvent *ev = &g_events[e]; @@ -605,6 +631,10 @@ static uint64_t g_viPostCount = 0; static void portPostVIEvent(void) { if (g_viRetraceMQ) { + /* D134: keep two slots free for the SP/DP done events posted at the + * end of a synchronous fast3d frame. A retrace posted into a backlog + * is stale anyway -- sched has not drained the previous one yet. */ + if (g_viRetraceMQ->validCount >= g_viRetraceMQ->msgCount - 2) return; s32 r = osSendMesg(g_viRetraceMQ, g_viRetraceMsg, OS_MESG_NOBLOCK); if (++g_viPostCount % 60 == 1 || r != 0) { sysLogPrintf(r != 0 ? LOG_ERROR : LOG_NOTE, @@ -997,11 +1027,11 @@ void osSpTaskStartGo(OSTask *t) (unsigned long long)(sysGetMicroseconds() - t0)); } - portPostEvent(OS_EVENT_SP); + portPostEventForce(OS_EVENT_SP); /* D134: must not be dropped */ if (t->t.type != M_AUDTASK) { /* A gfx task is also its own DP task (sp == dp in __scExec): the * DP "finishes" right after the RSP. */ - portPostEvent(OS_EVENT_DP); + portPostEventForce(OS_EVENT_DP); } } @@ -1022,7 +1052,7 @@ s32 osDpSetNextBuffer(void *buf, u64 size) { /* DP-only task: "rendering" is done by the time the RSP finished. */ (void)buf; (void)size; - portPostEvent(OS_EVENT_DP); + portPostEventForce(OS_EVENT_DP); /* D134 */ return 1; } void osDpGetCounters(u32 *counters) diff --git a/tools_pc/level_sweep.sh b/tools_pc/level_sweep.sh index 25310863..1686c0f1 100644 --- a/tools_pc/level_sweep.sh +++ b/tools_pc/level_sweep.sh @@ -1,33 +1,96 @@ #!/bin/bash +# Level sweep: bare -level_XX boot for all 21 solo levels; PASS/NO-FRAMES/CRASH. +# +# Flakiness notes (M-13..M-21): the port is not frame-deterministic (D117) and +# a loaded machine (a concurrent ninja build, another sweep, a stray ge007) +# routinely turns a known-good level into a spurious NO-FRAMES. This runner is +# therefore SERIALIZED (a lockdir + a stray-process kill before each level) and +# uses a 45 s watchdog, and it RETRIES a NO-FRAMES row once before reporting it. +# Do not run it next to a build. +# +# Env overrides: +# SWEEP_SECS=45 per-level watchdog seconds +# SWEEP_DUMP=80-400:40 GE_PCDUMP window +# SWEEP_LEVELS="Dam:33" subset to run cd "$(dirname "$0")/.." -LV="Dam:33 Facility:34 Runway:35 Surface1:36 Bunker1:09 Silo:20 Frigate:26 Surface2:43 Bunker2:27 Statue:22 Archives:24 Streets:29 Depot:30 Train:25 Jungle:37 Control:23 Caverns:39 Cradle:41 Aztec:28 Egypt:32 Cuba:54" + +SWEEP_SECS=${SWEEP_SECS:-45} +SWEEP_DUMP=${SWEEP_DUMP:-80-400:40} +LV=${SWEEP_LEVELS:-"Dam:33 Facility:34 Runway:35 Surface1:36 Bunker1:09 Silo:20 Frigate:26 Surface2:43 Bunker2:27 Statue:22 Archives:24 Streets:29 Depot:30 Train:25 Jungle:37 Control:23 Caverns:39 Cradle:41 Aztec:28 Egypt:32 Cuba:54"} + OUT=/tmp/sweep_results -mkdir -p /tmp/sweeplogs +LOGS=/tmp/sweeplogs +LOCK=/tmp/ge007_sweep.lock + +# --- serialize: one sweep at a time ----------------------------------------- +if ! mkdir "$LOCK" 2>/dev/null; then + echo "another sweep holds $LOCK (stale? rmdir it)" >&2 + exit 1 +fi +trap 'taskkill //F //IM ge007.x86_64.exe >/dev/null 2>&1; rmdir "$LOCK" 2>/dev/null' EXIT INT TERM + +export PATH="/c/msys64/mingw64/bin:$PATH" # addr2line + runtime DLLs + +mkdir -p $LOGS : > $OUT -rm -f /tmp/sweeplogs/*.crash.log -for entry in $LV; do - name=${entry%%:*}; num=${entry##*:} +rm -f $LOGS/*.crash.log + +# one run of one level -> echoes the status string +run_level() { + local name=$1 num=$2 rm -f ge007.crash.log; rm -rf ppm - export PATH="/c/msys64/mingw64/bin:$PATH"; GE_PCDUMP="80-260:40" ./build-pc/ge007.x86_64.exe -level_$num > /tmp/sweeplogs/$name.log 2>&1 & - pid=$! - sleep 24 + # kill anything left over from a previous level / another session taskkill //F //IM ge007.x86_64.exe > /dev/null 2>&1 + sleep 1 + + GE_PCDUMP="$SWEEP_DUMP" ./build-pc/ge007.x86_64.exe -level_$num > $LOGS/$name.log 2>&1 & + local pid=$! + + # watchdog: poll so a clean early exit does not cost the full window + local waited=0 + while [ $waited -lt $SWEEP_SECS ] && kill -0 $pid 2>/dev/null; do + sleep 1; waited=$((waited + 1)) + done + taskkill //F //IM ge007.x86_64.exe > /dev/null 2>&1 + wait $pid 2>/dev/null sleep 2 - status="UNKNOWN" + if [ -f ge007.crash.log ]; then + local pc sym pc=$(grep -oE '0x[0-9a-fA-F]+' ge007.crash.log | head -1) sym=$(addr2line -e build-pc/ge007.x86_64.exe -f -C "$pc" 2>/dev/null | head -1) - status="CRASH @ $sym ($pc)" - cp ge007.crash.log /tmp/sweeplogs/$name.crash.log + cp ge007.crash.log $LOGS/$name.crash.log + echo "CRASH @ $sym ($pc)" + return + fi + + local last pcnt + last=$(ls ppm/*.ppm 2>/dev/null | tail -1) + if [ -n "$last" ]; then + pcnt=$(python tools_pc/pixcount.py "$last" 2>/dev/null | grep -oE 'non-clear [0-9]+ \([0-9.]+%\)') + echo "PASS $pcnt" else - last=$(ls ppm/*.ppm 2>/dev/null | tail -1) - if [ -n "$last" ]; then - pcnt=$(python tools_pc/pixcount.py "$last" 2>/dev/null | grep -oE 'non-clear [0-9]+ \([0-9.]+%\)') - status="PASS $pcnt" + echo "NO-FRAMES" + fi +} + +for entry in $LV; do + name=${entry%%:*}; num=${entry##*:} + status=$(run_level "$name" "$num") + + # NO-FRAMES is the flaky outcome (D117 + host load) -- retry once before + # believing it. A CRASH is deterministic enough to report as-is. + if [ "$status" = "NO-FRAMES" ]; then + sleep 3 + retry=$(run_level "$name" "$num") + if [ "$retry" = "NO-FRAMES" ]; then + status="NO-FRAMES (2 attempts)" else - status="NO-FRAMES" + status="$retry [passed on retry]" + [ -f $LOGS/$name.crash.log ] || true fi fi + echo "$name ($num): $status" | tee -a $OUT done echo "SWEEP DONE"