port(determ): experimental GE_DETERM=1 fixed-tick mode, not yet achieved (D117)

Adds an env-gated (GE_DETERM=1, default OFF), test-only deterministic-clock
mode to port/src/libultra.c per the design in docs/dev/findings.md section D117:
osGetCount() returns a virtual clock advanced synchronously in osRecvMesg()
when __scMain (the sole consumer of the scheduler's retrace queue) asks for
the next message, instead of tracking real elapsed time. Goal: two runs of
the same build take the same simulation path, for exact frame-diff
regression testing and reproducible crash repro.

Four passes this session, each is a real, verified result, not a guess:
1. Fixed the predicted pre-first-frame deadlock (a poll-driven fallback
   caused it in the first cut).
2. Replaced the poll-driven fallback with synchronous per-ask generation
   in osRecvMesg -- fixed the deadlock cleanly, but two-run divergence was
   still 33-38%.
3. Capped the pre-first-task tick backlog to a fixed constant -- divergence
   dropped to 17-20%, still not the ~0% target.
4. Added GE_DETERM_TRACE=1 instrumented tracing and diffed two runs' clock
   event logs directly. Proved the tick mechanism is now fully
   deterministic (byte-identical clock values through the first real task).
   Root-caused the actual remaining divergence: every synthesized retrace
   increments the scheduler's frameCount, which gates a half-rate client
   (the audio client) by parity -- since the pre-task spin count is still
   real-time-scheduling-dependent, that parity isn't guaranteed to match
   between runs.

GE_DETERM is NOT achieving its determinism goal yet and is not meant to be
used for anything today -- it ships here purely as a well-documented,
zero-risk-when-off checkpoint (verify.sh bunker1 PASS, worst_cell unchanged,
confirmed after every change this session) so the next attempt starts from
proof instead of re-deriving four sessions of dead ends. Full trace numbers,
exact line citations, and the mechanism: docs/dev/findings.md section D117
(four M-52 addenda).

Claude-Session: https://claude.ai/code/session_01P3WrUHAFQZUuhrHhiJgTUr
This commit is contained in:
James Dansereau committed 2026-09-04 22:10:58 -04:00
1 parent 226f0490cb
commit bf195d3eb5
2 files changed
+306 -1

No files matched your search

+190 -1
View File
@@ -424,7 +424,7 @@ covers D24–D69; the log continues in §H (D32 procedure, D70–D121).
| D103–D107 | BUNKER1 viewport height, depth-buffer clear (`G_CLEAR_DEPTH_EXT`), portal near-plane, LOD mip tile | resolved |
| D108–D112 | skeletal models: `d43_emit.py put_f32` byte-reversal bug | resolved |
| D113–D116 | portal BFS ok · matrix chain ok · player raw-offset audit + `gunfire.c` THROW* · HUD text X-mirror | **D114/D116 CLOSED — NOT A BUG (M-33, see D168): the "X-mirror" was an upside-down `GE_PCDUMP` capture misread as mirrored. PPM writer fixed; the game renders correctly on hardware.** |
| D117 | frame nondeterminism root-caused; `GE_DETERM` deferred; `framediff.py` structural | resolved (mode deferred) |
| D117 | frame nondeterminism root-caused; `GE_DETERM` deferred; `framediff.py` structural. **M-52: `GE_DETERM=1` attempted — boot deadlock fixed, determinism NOT achieved (load-phase fallback still real-time-dependent). See addendum below.** | OPEN (mode attempted, not achieved) |
| D118 | SDL input layer (`port/src/input.c`); M-24 mouse-look rework: mode-aware map (aim mode = analog stick, hipfire = digital C-pitch), `config.c` INI now real. D118b/c FIXED; D118a residual (hipfire pitch only) | resolved (D118a residual) |
| D150 | watch OBJECTIVES / BRIEF page crash: `strcat(buf, langGet(id))` with `langGet` → NULL (unloaded bank) → NULL deref; `str.c` str* builtins elide a plain param NULL check, so guard via asm-laundered `GE_IS_NULL` | FIXED (`src/str.c` `#ifdef PORT`); interactive re-verify pending |
| D137 | right-mouse (aim-sight) crash: `gunDrawSight` (`gunfire.c:6235`) `s32 sp54` holds a `Gfx*` the whole function (`sp54 = *gdl`; `texSelect(&sp54,…)`/`display_image_at_position(&sp54,…)` take `Gfx**`). As N64 `s32` it is 4 B, so `*(Gfx**)&sp54` reads 4 B of the adjacent stack float as the pointer high word → `_g = 0x03e4fca0_70081220` → wild DL write in `texSetRenderMode` (`othermodemicrocode.c:177`) the moment the crosshair raises. §A. | FIXED (`src/game/gunfire.c` `#ifdef PORT` — `sp54` is `Gfx *`) |
@@ -3675,6 +3675,195 @@ Golden set at `tools_pc/golden/frame_0002{00,320,440}.png` is the D115
baseline — since it is a nondeterministic capture, only structural mode
is meaningful against it today.
**D117 — M-52 addendum: `GE_DETERM=1` implemented per the design above,
tested live (Windows console). Boot deadlock FIXED as predicted; full
determinism NOT achieved. Confidence: HIGH on both findings (live-tested,
not argued).**
Implemented exactly the 5-step design (`port/src/libultra.c`, env-gated,
default off, zero change to the non-`GE_DETERM` path): `osGetCount()`
returns a virtual `g_determTicks` seeded to the region quantum; a
`g_determFrameReady` flag is set at the `osSpTaskStartGo` graphics-task call
site (i.e. by the real "a frame was presented" event, not `videoEndFrame`
directly — same effect, one call site, no `video.c` change needed);
`portTickThread` gets a `GE_DETERM` branch that advances the clock + posts
one retrace only when that flag is set, polling every 200 µs instead of
pacing to the real 16.7/20 ms tick interval.
*Step 1(b) risk, confirmed exactly as written.* Without a load-phase
fallback, `-level_09 GE_DETERM=1` hangs before the first frame: symbolicated
the live hang (not guessed) — `shedThread` blocked in `osRecvMesg`
(`sched.c:256`, `__scMain`) and `mainThread` in `joyCheckStatusThreadSafe`
(`joy.c:166`), both waiting on the scheduler's interruptQ (the same queue
`portPostVIEvent` posts into, per the D134 comment), which never receives a
retrace because no frame has rendered yet to set `g_determFrameReady` —
exactly the chicken-and-egg the design called out ("boss.c:442 hangs the
same way").
*Fallback added, per the design's own suggestion — fixes the hang, breaks
determinism.* Added: when `g_determFrameReady` is false AND
`g_viRetraceMQ->validCount == 0` (nothing left to consume from a prior
tick), advance the clock and post a retrace anyway, so a boot-time waiter
isn't stuck forever. This **does** fix the hang — `-level_09 GE_DETERM=1`
now boots and renders past frame 3000+ instead of hanging. It does **not**
achieve determinism: two independent runs, same build, same command,
`framediff.py --exact` at the golden frame numbers (200/320/440):
```
FAIL frame_000200: 276998/307200 px over tol (90.169%, maxchan=218)
FAIL frame_000320: 85131/307200 px over tol (27.712%, maxchan=102)
FAIL frame_000440: 47936/307200 px over tol (15.604%, maxchan=102)
```
That's *worse* at frame 200 than the port's existing wall-clock
nondeterminism without any `GE_DETERM` mode at all (32–69 % per the
original D117 measurement above) — the fallback didn't just fail to fix
determinism, it introduced a new, bigger source of it. Root cause (analysis,
not yet re-tested): the fallback fires whenever the 200 µs poll happens to
observe an empty queue, which during the load phase depends on real
OS-scheduling latency between the polling thread and whatever the load path
is doing — so the *number* of extra ticks consumed before the first real
frame renders varies run-to-run, exactly the same class of divergence D117
already documents, just relocated from "wall-clock frame pacing" to
"wall-clock load-phase tick count." User-observed side effect, consistent
with this: with the fallback active the game visibly runs at a different
apparent frame rate and sped up — because the tick loop is no longer paced
to real 60/50 Hz at all once it starts free-running on empty-queue polls,
it advances (and lets the sim advance) as fast as the poll thread schedules,
not at any fixed rate.
**D117 — M-52 2nd attempt (same session): moved generation from a polled
fallback to a synchronous one. Root-caused precisely why that still isn't
enough. Confidence: HIGH (live-tested, mechanism traced through sched.c).**
Traced the actual consumer chain instead of guessing: `sched.c` `__scMain`
is the **sole** consumer of `g_viRetraceMQ` (`sc->interruptQ`), and every
retrace it processes drives task execution (`osSpTaskStartGo`), `joyPoll()`
(which is what unblocks `joyCheckStatusThreadSafe` too — the other M-52
1st-attempt hang site, for free), and the forward to `mainThread`, all
**synchronously on that one thread** before it asks for the next message.
So replaced the poll-driven tick-thread fallback with generation **inside
`osRecvMesg()` itself**: when `GE_DETERM` is on and the sole consumer of
`g_viRetraceMQ` finds it empty, synthesize the message inline (advance
`g_determTicks`, enqueue) instead of blocking — driven by call sequencing,
not by an independent thread's wall-clock poll.
Result: still boots (no regression on the deadlock fix), and the divergence
profile changed but did not go to ~0%: two runs, `framediff.py --exact`:
```
FAIL frame_000200: 101582/307200 px over tol (33.067%, maxchan=150)
FAIL frame_000320: 116844/307200 px over tol (38.035%, maxchan=161)
FAIL frame_000440: 43617/307200 px over tol (14.198%, maxchan=117)
```
Better than the 1st attempt's 90/28/16% at frame 200, but still nowhere
near the ~0% acceptance target. **Root cause, found by diffing the two
boot logs line-for-line** (not guessed): `boss.c`'s boot sequence has a
genuine, bounded, wall-clock real-time wait —
`for (i = 0; i != MAXCONTROLLERS; i++) { osSetTimer(100ms); osRecvMesg(BLOCK); }`
(`src/boss.c:188-190`, controller detection) — untouched by `GE_DETERM` by
design (`osGetTime()`/real timers are explicitly out of scope). During
that ~400 ms real window, **nothing is yet consuming `__scMain`'s forwarded
retraces** (`mainThread` hasn't reached its own retrace-consuming loop
yet), so the new synchronous-generation code has nothing throttling it —
`__scMain` free-spins through `osRecvMesg` as fast as the OS schedules that
thread, and *how many* virtual ticks accumulate during that fixed 400 ms of
real time depends on real thread-scheduling throughput. Same nondeterminism
class as both prior attempts, relocated a third time: generation-on-ask is
only deterministic when something else deterministically paces the asking,
and right now nothing does during any window where a client isn't actively
mid-frame.
**Disposition:** kept in the tree, env-gated (`GE_DETERM` unset by default,
zero behavior change confirmed via `verify.sh bunker1` before/after across
both attempts — worst cell 12.1–12.5 throughout, within existing noise).
The single-consumer synchronous-generation mechanism in `osRecvMesg()` is
the right shape and should stay — it's strictly better than polling and
fixed a real deadlock class cleanly. What's still missing: a genuine
**rate limit** on `__scMain`'s synthetic-retrace generation, decoupled from
real time — e.g. only synthesize the next one once the client has actually
finished processing the previous forward (a real request/response coupling
to `mainThread`'s progress, not just "the queue looked empty"), with a
separate, explicitly-bounded allowance for pre-first-frame boot code that
legitimately needs to service its own `osSetTimer` waits without the
scheduler racing ahead. That is a genuine design task, not a quick
follow-up — leaving D117 OPEN. `porting-notes.md` not updated (this
addendum's lesson is already exactly what §D117 above says, restated at
one more layer: any unthrottled or wall-clock-throttled generator racing
against a genuinely real-time-bound consumer reintroduces the same
divergence class, no matter how many layers deep you push it).
**D117 — M-52 4th pass: instrumented tracing (`GE_DETERM_TRACE=1`) precisely
localizes what's left — and it is NOT the virtual clock. Confidence: HIGH,
directly measured, not inferred.**
Rather than keep auditing code paths by inspection (two dispatches -- one to
the local delegate, one done directly -- had just spent a round ruling out
the level-load path and the audio-thread shared-globals angle with nothing
to show for it), added a temporary trace: every `g_determTicks`
advance/cap event and the `first_task_run` transition get a monotonic
sequence number + timestamp-free log line (`port/src/libultra.c`, gated by
`GE_DETERM_TRACE=1`, zero cost when unset). Ran `-level_09` twice, diffed
the two trace logs directly instead of guessing.
**Result: the tick mechanism is now proven fully deterministic.** Both runs
are byte-identical (same `ticks=` value at every logged step) all the way
through the `first_task_run` transition — the only difference is *which
spin iteration* it happens on (run 1: spin 4020, run 2: spin 4086 — 66 more
capped no-op spins in run 2, real-OS-scheduling-dependent as expected), but
the **virtual clock value at that moment is identical in both** (1551750 =
`2 × g_determQuantum`). Re-aligning the two logs by that spin-count offset
shows the entire subsequent tick progression is byte-for-byte identical.
The M-52 3rd-attempt fix (cap pre-task ticks to a fixed constant) works
exactly as designed — this is not where the remaining divergence comes
from.
**The actual mechanism, found by reading `sched.c` with the trace numbers
in hand:** every synthesized retrace — capped ones included — is a real
`VIDEO_MSG` that `__scMain` processes via `__scHandleRetrace()`
(`src/sched.c`), which unconditionally does `sc->frameCount++`
(`sched.c:319`) and then, per registered client, gates forwarding on
`(*((s32*)client + 2) == 0) || ((sc->frameCount & 1) == 0)`
(`sched.c:334`) — i.e. some clients only receive every *other* frame's
retrace by `frameCount` parity. The audio client is registered as exactly
this kind of half-rate client: `osScAddClient(&os_scheduler,
&g_AudioClient[0], &g_AudioManager.frameMessageQueue, 1)` (`src/audi.c:437`,
the trailing `1` is the half-rate flag). Since `frameCount` increments on
*every* capped spin — not gated by the virtual clock at all — and the total
spin count before the first real task varies run-to-run by a genuinely
real-time-scheduling-dependent amount, **`frameCount`'s parity at the
moment real gameplay begins is not guaranteed to match between runs**, even
though the clock value is now provably identical. This run pair happened to
land on a same-parity gap (66, even) — a different pair easily could not.
If it lands on opposite parities, the audio client's very first retrace
forward shifts by one frame's phase between runs, and audio-task scheduling
(which shares the same `osSpTaskStartGo`/tick-gating machinery) diverges
from there.
**Why no 5th live-coded attempt this session:** the natural next lever —
don't call `__scHandleRetrace` (and thus don't increment `frameCount`) for
a purely-capped "keep `__scMain`/`joyPoll` alive" spin — reopens the exact
chicken-and-egg the 1st attempt hit: `joyCheckStatusThreadSafe`'s handshake
and `__scMain`'s own unblocking need *something* processed during that
window, and `sc->frameCount` is decomp-internal state with no port-visible
accessor to correct after the fact. A real fix needs `frameCount`'s parity
(or the half-rate audio client's phase) to be made deterministic
independent of the real-time-dependent capped-spin count — a genuine
4th-layer design task, not a variant of any of the first three attempts.
Stopping here deliberately rather than rushing a live guess under momentum,
per the same discipline the earlier attempts were written up under.
**Disposition:** `GE_DETERM_TRACE` tracing kept in the tree alongside
`GE_DETERM`, same env-gating, zero cost when unset — it's the tool that
should be reused for the next attempt rather than re-instrumented from
scratch. D117 stays OPEN. porting-notes.md not updated yet (the
generalisable lesson here — "a per-frame parity/half-rate dispatch gate
fed by an unconditionally-incrementing counter inherits whatever
nondeterminism feeds that counter, even after the counter's *primary*
consumer is made deterministic" — is specific enough to this scheduler
that it's better captured here than genericized prematurely).
**D118 (session M-9) — SDL input layer implemented (Phase 3).**
`port/src/input.c` was an unimplemented stub; input only worked via
`libultra.c`'s `contSnapshotFromKeyboard()` (Z/Space=A, X=B, LCtrl=Z,
+116
View File
@@ -86,8 +86,46 @@ OSTime osGetTime(void)
return (OSTime)sysGetMicroseconds();
}
/* GE_DETERM=1 — fixed-tick deterministic mode (speed-ups plan Step 7 / R1,
* design in docs/dev/findings.md §D117). Test-only, default OFF: replaces
* the wall-clock osGetCount() below with a virtual clock advanced exactly
* once per virtual VI retrace (generated synchronously in osRecvMesg() —
* see the GE_DETERM block there — when __scMain, the sole consumer of
* g_viRetraceMQ, asks for the next message; NOT paced by an independent
* thread) instead of real elapsed time, so two runs of the same build take
* the same simulation path. Never the shipping timing model — the default
* (GE_DETERM unset) path below is byte-for-byte what it always was. */
static int g_determEnabled = 0;
static u32 g_determQuantum = 775875; /* NTSC; portKernelInit sets 931050 PAL */
static u32 g_determTicks = 0;
/* M-52 3rd attempt: __scMain is the sole consumer of g_viRetraceMQ, but
* before the first real gfx/audio task ever runs (src/boss.c's bounded
* osSetTimer(100ms)-based controller-detection loop -- genuinely real-time,
* out of scope by design), NOTHING is consuming its forwards, so unbounded
* per-ask generation free-spins for that whole real-time window and however
* many ticks accumulate is real-scheduling-dependent (confirmed: 2nd
* attempt's 33/38/14% divergence). waitForNextFrame() (frametiming.c) is a
* tight busy-spin on osGetCount(), not a queue wait -- so FREEZING the
* clock during that window (0 extra ticks) hangs it forever, and letting it
* free-run is exactly the bug. The fix: cap the clock to exactly ONE extra
* quantum beyond the seed before the first task runs -- fixed, identical
* every run, and >=1 quantum is already enough to clear
* waitForNextFrame()'s first-call threshold (see the arithmetic in
* frametiming.c), so it can't hang either. Set true by osSpTaskStartGo. */
static int g_determTaskEverRun = 0;
static int g_determPreTaskTicksGranted = 0;
/* GE_DETERM_TRACE=1 (with GE_DETERM=1): log every virtual-clock advance with a
* monotonic sequence number, for diffing two runs' logs to find the exact
* first point they diverge -- see docs/dev/findings.md §D117 M-52. Test-only,
* both env-gated off by default; zero cost when unset. */
static int g_determTraceEnabled = 0;
static u32 g_determTraceSeq = 0;
u32 osGetCount(void)
{
if (g_determEnabled) {
return g_determTicks;
}
/* The N64 RSP core counter advances at ~OS_CPU_COUNTER (~46.5 MHz), NOT
* microseconds. GE's pacing assumes this rate: waitForNextFrame() in
* frametiming.c waits for 775,875 - 387,937 ticks per NTSC frame (931,050
@@ -234,6 +272,25 @@ static void *portTickThread(void *arg)
{
(void)arg;
for (;;) {
/* GE_DETERM (§D117, M-52 2nd attempt): retrace generation lives in
* osRecvMesg() now (see there) -- synchronous with the sole
* consumer asking for the next message, not paced by this thread.
* The M-52 FIRST attempt polled g_viRetraceMQ's empty/non-empty
* state from here on a real-time cadence; that poll's own
* OS-scheduling latency varied run-to-run and leaked directly into
* the tick count (measured: 90%/28%/16% frame divergence between
* two runs, worse than the port's baseline wall-clock
* nondeterminism this mode exists to remove). This thread still
* only does what osGetTime()-based real-time bookkeeping needs
* (timers, hang-heartbeat) -- deliberately NOT touching
* g_viRetraceMQ at all in this mode. */
if (g_determEnabled) {
portServiceTimers();
portHeartbeatCheck();
sysSleep(g_tickIntervalUs);
continue;
}
uint64_t now = sysGetMicroseconds();
if (!g_nextTickUs) g_nextTickUs = now + g_tickIntervalUs;
@@ -272,8 +329,25 @@ void portKernelInit(void)
if (osTvType == OS_TV_MPAL || osTvType == OS_TV_PAL) {
g_tickIntervalUs = 1000000 / 50; /* PAL: 50 frames/s -> 20ms */
g_determQuantum = 931050;
} else {
g_tickIntervalUs = 1000000 / 60; /* NTSC: 60 frames/s -> ~16.7ms */
g_determQuantum = 775875;
}
/* GE_DETERM=1: seed so the first waitForNextFrame() computes exactly
* (quantum + 387937) / quantum == 1 tick, per the §D117 design. */
g_determEnabled = getenv("GE_DETERM") != NULL;
if (g_determEnabled) {
g_determTicks = g_determQuantum;
g_determTraceEnabled = getenv("GE_DETERM_TRACE") != NULL;
sysLogPrintf(LOG_NOTE,
"GE_DETERM=1: fixed-tick deterministic mode (test-only, "
"quantum=%u) -- osGetCount() is now frame-locked, not wall-clock",
g_determQuantum);
if (g_determTraceEnabled) {
sysLogPrintf(LOG_NOTE, "DETERMTRACE seq=0 ticks=%u event=seed", g_determTicks);
}
}
pthread_t th;
@@ -577,6 +651,42 @@ s32 osRecvMesg(OSMesgQueue *mq, OSMesg *msg, s32 flag)
pthread_mutex_unlock(&pq->lock);
return -1;
}
/* GE_DETERM (§D117, M-52 2nd attempt): __scMain (sched.c) is the
* SOLE consumer of g_viRetraceMQ, and everything the rest of the
* boot/frame chain waits on (task execution via osSpTaskStartGo,
* joyPoll() -- which is also what unblocks joyCheckStatusThreadSafe
* -- and the forward to mainThread's gfxFrameMsgQ) happens
* synchronously inside __scMain's handling of THAT message, on this
* same thread, before it comes back to ask for the next one. So
* "the consumer is asking and none exists" is itself the correct,
* purely call-sequenced trigger for the next virtual retrace --
* driven by program order, not by an independent thread polling on
* a wall-clock cadence (the M-52 first attempt's mistake: that
* poll's timing varied run-to-run and leaked into the tick count).
* Enqueue inline (not via osEnqueueMesg -- would re-lock pq->lock,
* which we already hold). */
if (g_determEnabled && mq == g_viRetraceMQ) {
/* Still synthesize the message every time (keeps __scMain/
* joyPoll unblocked -- no deadlock), but only advance the clock
* up to a fixed cap before the first real task runs. See the
* g_determTaskEverRun comment above. */
if (g_determTaskEverRun || g_determPreTaskTicksGranted < 1) {
g_determTicks += g_determQuantum;
if (!g_determTaskEverRun) ++g_determPreTaskTicksGranted;
if (g_determTraceEnabled) {
sysLogPrintf(LOG_NOTE,
"DETERMTRACE seq=%u ticks=%u event=advance taskEverRun=%d",
++g_determTraceSeq, g_determTicks, g_determTaskEverRun);
}
} else if (g_determTraceEnabled) {
sysLogPrintf(LOG_NOTE,
"DETERMTRACE seq=%u ticks=%u event=capped taskEverRun=%d",
++g_determTraceSeq, g_determTicks, g_determTaskEverRun);
}
mq->msg[(mq->first + mq->validCount) % mq->msgCount] = g_viRetraceMsg;
++mq->validCount;
break;
}
/* Log each queue's first blocking call site (the return address is
* the caller); symbolicate with addr2line to find where in game code
* this wait happens. */
@@ -1118,6 +1228,12 @@ void osSpTaskLoad(OSTask *t) { (void)t; /* nothing to load on the host */ }
void osSpTaskStartGo(OSTask *t)
{
if (g_determTraceEnabled && !g_determTaskEverRun) {
sysLogPrintf(LOG_NOTE,
"DETERMTRACE seq=%u ticks=%u event=first_task_run tasktype=%d",
++g_determTraceSeq, g_determTicks, (int)t->t.type);
}
g_determTaskEverRun = 1; /* GE_DETERM: §D117 M-52 3rd attempt */
if (t->t.type == M_AUDTASK) {
/* Phase 3: execute the audio ucode against t->t.data_ptr (an Acmd
* list). For now the task simply completes; libaudio's amMain still