D322: log issue #87 long-session audio degradation + ship GE_D322 pool-telemetry probe

User report (v0.3.0 full campaign): audio progressively degrades from Silo;
by Caverns/Cradle the OST is inaudible and SFX come and go; restarting the
game restores it. Logged as D322 with static triage: level teardown audit
clean, mixer stateless per frame, D202's covered leak class is one shape
only (ownerless count==-1 loops) validated single-level only, and D305
already records a pool/list accounting desync. Ranked hypotheses:
voice-pool exhaustion/counter drift > queue starvation > evtq saturation.

Probe: GE_D322=1 prints sfx=n/8 (SFX soft cap), evtq=n/64, pv free/lame/alloc
(24 physical synth voices) + pipeline depth/drops every 5 s of wall clock,
read with GE_D204. sndD322PoolSummary() walks the ALSynth lists under the
D285 lock; NB drvr is a pointer field (first build faulted on &drvr).
Smoke-tested 40 s headless -level_09: pools coherent, no crash.

Also adds the missing D321 row to the findings index (entry existed at file
tail with no table row, so it was absent from the CSV too).
This commit is contained in:
James Dansereau committed 2026-09-20 23:09:03 -04:00
1 parent fbc48899ec
commit 2d9e673129
5 files changed
+123 -1

No files matched your search

+2 -1
View File
@@ -3,7 +3,7 @@
Every `getenv("GE_…")` in the tree. The table prose is hand-curated;
**`tools_pc/gen_env_probes.py`** re-greps the live sites and reports drift
(NEW / GONE vars + a fresh file:line map) — run it before trusting the
File:line cells. Last reconciled 2026-09-20 (v0.3.0 release review). All are **env-gated**: unset = zero behavior
File:line cells. Last reconciled 2026-09-21 (D322 probe added; v0.3.0 release review was 2026-09-20). All are **env-gated**: unset = zero behavior
change, so they are safe to leave in a release build (they only cost a
`getenv` on the guarded path). "Dead" below means *the finding it was built
for is closed* — the probe is strip-candidate scaffolding, not that it does
@@ -110,6 +110,7 @@ Two classes:
| `GE_RSEED` | `port/src/random.c:134` (`#ifdef PORT`) | Test-only boot-seed override: `GE_RSEED=<hex64>` pins `g_randomSeed` at first seed instead of the wall-clock-derived value — for determinism and N64-parity tests. Inert unset. | **live, test-only** |
| `GE_RSEED_LV` | `port/src/d318watchdog.c:232` (`#ifdef PORT`) | One-shot level-start seed log: logs `g_randomSeed` at the first tick after level start (optionally armed for a specific tick via `<hex>@<tick>`) — ties a saved/loaded game's PRNG state to a level for D318-class repro. Inert unset. | **live** (D318 verification) |
| `GE_D318T` | `port/src/d318watchdog.c:270` (`#ifdef PORT`) | D318 watchdog timeline probe: per-tick log of the Facility ai_22 softlock signature window (c78 list/offset/attack state, c67 health) while the watchdog watches. Inert unset. | **live** (D318 verification) |
| `GE_D322` | `port/src/audio.c` (`audioSetNextBuffer`), `src/snd.c` (`sndD322PoolSummary`) | D322 pool-telemetry probe: one line per 5 s of wall clock with the three pool layers a long session can exhaust — `sfx=count/max` (8-voice SFX soft cap), `evtq=n/64` (event queue occupancy; full = silent post drops, M-71), `pv free/lame/alloc` (24 physical synth voices shared by SFX + music; `-1`s before sndInit), plus the D204 pipeline fields. Cheap (~30 reads/s), campaign-safe; read together with `GE_D204=1`. | **live** (D322 capture) |
| `GE_D318W` | `port/src/d318watchdog.c:136` (`#ifdef PORT`) | **Not a probe — the D318 port-side watchdog itself, ON by default.** Detects the Facility ai_22 hold-pose softlock signature (a latent N64 race, see findings.md D318) for 600 consecutive ticks and re-seeds c78's attack via the game's own fresh-attack entry point. `GE_D318W=0` opts out; logs `D318W:` lines when it acts. **Permanent fix, not strip-candidate.** | **live** (D318 fix — permanent) |
## Notes
+2
View File
@@ -198,3 +198,5 @@ D317,CLOSED,"Crash when toggling Game.AllUnlocked back and forth in-game (user r
D318,RESOLVED,Facility (regular play path):,RESOLVED (2026-09-19):
D319,FIXED,"Frame cap slider was mostly a dead zone; replaced with a plain 30/60 toggle (user ask, 2026-09-18).",FIXED — new ROW_FPSCAP cycle (30/60 only) in port/src/optionsoverlay.c; default changed to 60 in port/src/video.c.
D320,OPEN,"D318-class sweep: aim-hold → _update AI lists in 8 levels carry the same as-authored softlock race (static analysis, 2026-09-20).","OPEN — static sweep complete (Facility ai_19, Control ai_9, Depot ai_12 flagged high/med-high; Bond-combat loops likely safe); no live confirmation beyond D318 itself; probe-verify path + generalized…"
D321,CLOSED,D318 trigger chain fully mapped:,CLOSED — trigger chain mapped and faithful; D318 watchdog validated in live play.
D322,OPEN,Long-session audio degradation:,"OPEN — static triage done (teardown audit, mixer statelessness, D202-coverage check); ranked hypotheses:"
1 # GENERATED by tools_pc/gen_findings_index.py -- do not hand-edit.
198 D318
199 D319
200 D320
201 D321
202 D322
+43
View File
@@ -606,6 +606,8 @@ covers D24–D69; the log continues in §H (D32 procedure, D70–D121).
| D318 | **Facility (regular play path): after Objective C (destroying the bottling tanks) completes, Ourumov freezes and does not shoot Trevelyan as he should (user report, 2026-09-18).** — full `## D318` entry at file tail | RESOLVED (2026-09-19): as-authored latent race (gas bit mid-monologue derails c78's pre-aim hold into a permanent ACT_ATTACK anim pin; N64-identical), NOT a port bug; port-side watchdog `port/src/d318watchdog.c` re-inits the attack on confirm. D263 mechanism map stands (different failure mode). |
| D319 | **Frame cap slider was mostly a dead zone; replaced with a plain 30/60 toggle (user ask, 2026-09-18).** — full `## D319` entry at file tail | FIXED — new `ROW_FPSCAP` cycle (30/60 only) in `port/src/optionsoverlay.c`; default changed to 60 in `port/src/video.c`. Root cause was D186 (sim tick ceiling + low-cap guard); this just fixes the menu's exposure of it. Build-verified; interactive confirmation owed. |
| D320 | **D318-class sweep: aim-hold → `_update` AI lists in 8 levels carry the same as-authored softlock race (static analysis, 2026-09-20).** — full `## D320` entry at file tail | OPEN — static sweep complete (Facility ai_19, Control ai_9, Depot ai_12 flagged high/med-high; Bond-combat loops likely safe); no live confirmation beyond D318 itself; probe-verify path + generalized-watchdog recommendation documented. |
| D321 | **D318 trigger chain fully mapped: tanks → combat bit is an authored ~3.5 s gas-cascade delay (chr 254 script); derail lands same-tick; PC behavior confirmed faithful to N64 (probe captures, 2026-09-20).** — full `## D321` entry at file tail | CLOSED — trigger chain mapped and faithful; D318 watchdog validated in live play. Optional deferred tuning: `D318_DEADLOCK_TICKS` 600→300 (user's call). |
| D322 | **Long-session audio degradation: full campaign on v0.3.0 — audio progressively worsens from Silo, by Caverns/Cradle the OST is inaudible and SFX "come and go"; restarting the game restores it (issue #87, user report, 2026-09-21).** — full `## D322` entry at file tail | OPEN — static triage done (teardown audit, mixer statelessness, D202-coverage check); ranked hypotheses: voice-pool exhaustion/counter drift > queue starvation > evtq saturation. `GE_D322` pool-telemetry probe shipped; needs a campaign capture with `GE_D322=1 GE_D204=1`. |
Phase 2 replaced the Phase-1 demo loop with the real `mainproc()` on real OS
threads, compiled GE's real `src/sched.c`, and brought in PD's fast3d software
@@ -12196,3 +12198,44 @@ Verified: build clean (MSYS2 MINGW64/ninja); `tools_pc/verify.sh bunker1` — PA
**Optional tuning (deferred, user's call).** `D318_DEADLOCK_TICKS` 600→300 would halve the worst-case pin-branch pause (10 s → 5 s); the margin over the natural escape (<2 s; run B: 0 ticks) stays ≥2.5×. One-line `#define` in `port/src/d318watchdog.c`; not done pre-ship to avoid re-validating the watchdog on the release branch.
**Status:** CLOSED — trigger chain mapped and faithful; D318 watchdog validated in live play (fired + recovered in run A, correctly inert in run B). Cross-ref: D318 (pin mechanism + watchdog), D320 (sweep of the same race in 8 levels), D263 (ai_22 mechanism map), M-192 (release review).
## D322 — Long-session audio degradation: full campaign on v0.3.0, audio progressively worsens (Silo → Caverns/Cradle: OST inaudible, SFX "come and go"); restart restores it (issue #87, user report, 2026-09-21)
### Report (verbatim, issue #87 comment, v0.3.0 build)
> I just did a full run on 00 agent including Aztec and Egyptian in one shot :) It definitely felt better overall but the audio really started to struggle in the final levels again, but i made it through to the end. Interestingly, exiting the game and starting it back up again let the audio go back to normal. Feels like something about long gaming sessions throws off the audio after a while. [...] i think Silo was the first instance i noticed some audio sync issues popping up (possibly from me spamming the KF7). But it wasn't until the end around caverns / cradle that it became very noticeable (like to the point you couldn't hear the background OST and the audio felt like it came and went)
### Symptom profile (what the report tells us before any code)
- **Onset is gradual and session-scoped:** fine early, first wobble ~Silo (mission 2 of the campaign arc, heavy firefights), severe by Caverns/Cradle (final levels). Not level-specific — a fresh boot of any single level has never shown this (every `-level_XX` sweep + single-level audio run since D198–D207 is clean).
- **Two distinct perceptual halves:** (a) *music* — "couldn't hear the background OST"; (b) *SFX* — "came and went". On this port both music and SFX draw from the same 24-voice physical synth pool (`alSynAllocVoice`, `src/libultra/audio/synallocvoice.c`); SFX additionally sit under an 8-voice soft cap (`g_sndAllocatedVoicesCount` vs `maxSounds`, `src/snd.c:328`). One accumulator can therefore produce both halves at once: cap pinned → new SFX take the preempt/drop path ("come and go"); physical pool depleted → music note-ons steal from or fail against each other (OST inaudible).
- **Restart cures it** → process-lifetime accumulation, not a per-level fault and not a slow drift that a level reload would clear. (Level reloads during the run did NOT cure it — the user kept playing through.)
- Precedent: the v0.2.2-era report in the same issue showed the same shape ("audio got wonky right around streets [...] kept getting worse up until [...] control center") — so this is a long-standing class, improved by v0.3.0's audio fixes but not eliminated.
### Static triage (this session — what was checked and what it rules in/out)
1. **Level teardown IS thorough (and is N64-identical code).** The level-exit cleanup (`src/game/lv.c` ~1650–1675) deactivates: MP sound state, `cleanupObjectSounds()` (all `sfx_related[i]`), `cleanupAlarms()`, `cleanupSFXRelated()` (tank SFX), `cleanupplayersoundrelated()` (both hands per player). So the *owned* loop classes with known owners are released at level end — on PC and N64 alike. This does NOT rule out leaks: it rules out "teardown simply forgets a class".
2. **`port/src/mixer.c` is stateless per frame** (DMEM scratch + per-voice saved envelope state in DRAM; `mixerInit` zeroes everything at boot). No session accumulator lives in the mixer itself. Reverb delay lines are the only cross-frame DRAM state and were ruled out as a drone source in M-65 (`GE_NOWET`), though that was a short single-level run.
3. **D202's known leak class is covered — but only for one shape, and only validated on single-level runs.** M-65's guard reclaims *ownerless, non-retrigger, LOOPED* voices under pool pressure; M-66b's `AL_SNDP_PORT_EXPIRE_EVT` fades out ownerless infinite loops (ADPCM `count == -1`) ~2.5 s after start. Both were measured on `-level_09` only (≤134 s). Shapes NOT covered by either: (a) a looped voice whose owner pointer is non-NULL but whose owner record was freed without deactivating it; (b) an ownerless loop whose wave carries no `count == -1` ADPCM loop (finite-loop or non-looping sustained envelope that never reaches its end state); (c) any sound whose envelope/voice state machine wedges mid-decay so no END_EVT is ever posted. M-65 also explicitly banked: **"it is NOT known why the N64 does not leak here"** — the ownerless-loop accumulation is already a documented port deviation, and a full campaign is simply 10–15× more exposure of it.
4. **A pool/list desync is already on record.** The D305 guard comment in the preemption scan (`src/snd.c` ~352) records that `limitReached` was observed with the tracked-voice list EMPTY — "the pool-exhaustion accounting and this list have desynced by some still-unidentified mechanism." If `g_sndAllocatedVoicesCount` drifts high over hours (any missed decrement on a dispose path), `limitReached` becomes permanently true: every new SFX goes through the preempt scan, finds nothing stealable (all survivors looped/RETRIGGER/PREEMPT), and is dropped — exactly "came and went" — while the physical pool separately depletes for the music half.
5. **Queue starvation is the alternate class.** `port/src/audio.c`: if production falls below 22050 Hz real-time (the 30 Hz audio tick starved by a slowly-degrading main loop), the SDL queue underruns and the device pads silence → choppy "come and go" with music most affected (it is the only continuous signal). The D204 monitor (`rt=`, `q=`, `drop=`) distinguishes this in one capture. Note D248/D250 (frame-pacing) are fixed, but a *gradual* main-thread slowdown over hours (growing lists, leaked entities) would show up here rather than in any single-level test.
6. **evtq saturation (third candidate).** The ALEventQueue has 64 slots and `alEvtqPostEvent` silently drops posts when full (M-71). Anything that re-posts every 33 ms (WAIT_VOICE retries for looped sounds, D207's alarm) while the queue is busy can starve music/SFX event delivery. The new probe reports occupancy.
**Fidelity framing:** the N64 also runs a full campaign in one process, so hypothesis (1)-class leaks are either (a) port-side accumulation amplified by the documented M-65 deviation, or (b) an original quirk the N64's exact 30 Hz/VI-paced audio cadence never triggers. Diagnosis is unrestricted per AGENTS.md; the fix bucket (port vs rule-2) follows whichever mechanism the capture identifies. (5)/(6) are port-specific by construction.
### Probe shipped (this session)
`GE_D322=1` — one line per 5 s of wall clock from `port/src/audio.c` (`audioSetNextBuffer`, ~30 Hz cadence, campaign-safe): `sfx=count/max` (8-voice soft cap), `evtq=n/64`, `pv free/lame/alloc` (24 physical voices via new `sndD322PoolSummary()` in `src/snd.c`, lists walked under the D285 lock), plus `q=queued/limit drop=n` (pipeline). Read with `GE_D204=1` for `rt=` (production rate; <1.0 sustained = starvation).
**Probe smoke-tested 2026-09-21:** 40 s headless `-level_09` run, no crash, pools coherent (`pv free+alloc = 24`, `sfx=0/8` idle, `evtq=0`). (First build faulted: the probe took the address of `ALSndPlayer.drvr`, which is a *pointer* field, not an embedded synth — fixed with a NULL guard for pre-sndInit.)
### Evidence ask (user, next campaign run)
Full campaign (or at minimum Silo → Caverns/Cradle) with **`GE_D322=1 GE_D204=1`** set, sharing the resulting `ge007.log`. Decision rules:
- `sfx` ratchets up level-over-level and/or stays elevated through quiet sections → hypothesis 4 (counter drift / leaked SFX states). Follow-up: short `GE_AUDIOTRACE=1` run in a late level to pair `[VOICE+]`/`[VOICE-]` and name the holding soundIndex(es).
- `pv alloc` climbs and never returns to baseline → physical-voice leak (music half); same follow-up names the owners.
- `rt` < 1.0 sustained with `q` → 0 in the bad sections → hypothesis 5 (starvation); then profile what slows the main loop over a long session.
- `evtq` pinning at 64 → hypothesis 6; correlate with WAIT_VOICE re-posters.
- All pools healthy while audio is bad → back to the mixer/reverb state classes (re-open M-65's ruled-out list with a long-session `GE_AUDIODUMP`).
**Status:** OPEN — static triage complete, probe shipped, awaiting campaign capture. Cross-ref: D202/M-65+M-66b (ownerless-loop leak class + expiration), D207 (8-cap starvation design notes), D305 (pool/list desync observation), D204 (pipeline pacing + `GE_D204` monitor), D248/D250 (frame pacing, fixed), issue #87.