diff --git a/CMakeLists.txt b/CMakeLists.txt index 9aa2eaa..74919fd 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -38,6 +38,8 @@ if(BUILD_TESTING AND NOT ANDROID) target_include_directories(ppu_window_test PRIVATE ${SNESRECOMP_ROOT}/runner/src) add_test(NAME ppu_widescreen_windows COMMAND ppu_window_test) + add_test(NAME sm_door_audio_trace + COMMAND ${Python3_EXECUTABLE} ${CMAKE_CURRENT_SOURCE_DIR}/tests/door_audio_trace_test.py) endif() diff --git a/docs/door-audio-investigation.md b/docs/door-audio-investigation.md new file mode 100644 index 0000000..d107f2a --- /dev/null +++ b/docs/door-audio-investigation.md @@ -0,0 +1,147 @@ +# Door transition audio investigation + +The F1 fixture used on September 10, 2026 is immediately to the right of an open +door. Holding left changes room `$91F8` to `$92FD`, with game state +`8 -> 9 -> 11 -> 8`. Supply that save locally; saves and ROMs are not distributed. + +## Reproduce on the production path + +Build with `CMAKE_BUILD_TYPE=Release` and `SNESRECOMP_ENABLE_TRACE=OFF`. +Copy the fixture into `saves/save0.sav` next to the executable, keep audio on, +and use normal frame delay (no turbo). For the stock-renderer comparison, disable +both custom renderer and custom presentation FPS. Set `SM_RUN_FRAMES=1100` and +`SM_AUDIO_PROBE` to a CSV path. Launch with `--script` followed by the absolute +path to `tools/door_audio_repro.txt`. Paths to config, ROM cache, and saves are +anchored next to the executable. + +Run `python tools/check_door_audio.py path/to/trace.csv` afterward. A clean run +exits zero. Missing/dropped guest audio or excessive post-exit FPS exits one. An invalid +fixture (no actual door, same room after exit, incomplete post-exit window, or no +audio sample rate) exits two. The checker excludes all counters accumulated +before entering the door, including boot and loading the save. + +The probe is optional and works without the debug server. It samples game state, +wall time, CPU master cycles, APU clock mapping, and audio counters once after +each guest frame. `missing_frames` counts output stereo frames which lacked +guest PCM, including the recovery fade; milliseconds use the actual stream +sample rate. This measures producer starvation, not silence intentionally +generated by the guest music. `longest_no_pcm_ms` describes a pause in production, +which may be fully covered by already-buffered audio. + +## Findings + +The shared runner timestamps APU accesses using the host frame number plus the +current frame's CPU master-cycle offset. Long door routines legitimately advance +that offset beyond a nominal frame. For this fixture, the live APU reaches about +38 frames ahead of the next nominal frame-boundary target. Later short frames +then produce no PCM until that target catches up; a production trace measured +about 218 ms with no new PCM during door step `$E4A9`. + +This is not exclusively a single blocked host frame. The loader already advances +the APU during port reads. Adding synchronization at CPU block boundaries does +not address the subsequent backward frame timestamp. The shared timestamp +function must remain unclamped: NMI-disabled SPC uploads need to progress across +multiple frame periods to complete their handshakes. + +The Super Metroid host also presents every stock-renderer catch-up frame, even +when the presentation deadline is not due. Each presentation can wait for VSync, +slowing recovery while the audio buffer drains. An experiment applied the existing +presentation deadline to the stock renderer too. That shortened some recovery +windows, but repeat tests still failed, so the behavior change was removed. + +Loading also has limited CPU headroom. The room setup and tile-loading frames +took about 233 and 206 ms in a quiet run; a later run took 431 and 387 ms for the +same work and generated substantial underflows before the subsequent no-PCM +period. Wall-time measurements include scheduling and lock delays; they do not +by themselves identify why that later execution was slower. + +## Measured results + +These are Windows production builds with trace/debug-server code disabled, +stock renderer, a 32,000 Hz output stream, and the F1 fixture above. The older +policy comparison uses the same instrumented source with v0.3.1's unconditional +debt-discard policy, rather than claiming an untouched release ZIP was tested. + +| Timing policy | Crossing | Missing output during door | Missing output in following 120 frames | +|---|---:|---:|---:| +| v0.3.1 debt discard | 1 | 815.438 ms | 613.938 ms | +| v0.3.2 | Initial | 5.500 ms | 0 ms | +| v0.3.2 | Repeat 1 | 10.000 ms | 0 ms | +| v0.3.2 | Repeat 2 | 17.969 ms | 0 ms | +| v0.3.2 | Repeat 3 | 20.500 ms | 0 ms | +| Presentation experiment | Initial | 0 ms | 0 ms | +| Presentation experiment | Repeat 1 | 656.000 ms | 0 ms | +| Presentation experiment | Repeat 2 | 0 ms | 9.969 ms | +| Presentation experiment | Repeat 3 | 370.188 ms | 0 ms | + +Missing output is the sum of device frames lacking guest PCM, not necessarily +one uninterrupted silence. Every crossing traversed the same guest frames +(106 frames between entry and gameplay return) and produced 66,142 native +samples. Measured post-exit rates for v0.3.2 and the experiment were about +56-60 FPS, with no speed-up burst; the old policy run fell to about 46 FPS. +Execution time varied, so these runs establish failures and sensitivity to +scheduling; one zero-underflow pass does not validate a fix. + +Local evidence is in `build-release-v0.3.2/door-audio-*.csv`, particularly +`door-audio-v031-policy.csv`, `door-audio-v032-precise.csv`, +`door-audio-v032-repeat.csv`, and `door-audio-present-repeat.csv`. + +An initial release-path test was invalid: `loadstate 0` before the first guest +reset loaded the save, then reset erased it. That run stayed at the title screen. +The checked-in fixture loads after boot and the checker explicitly rejects this +false positive. + +## Clock correction + +The ordinary-cartridge interpreter was still advancing the SPC through relative +catch-up in addition to the absolute frame clock. Suppressing that path alone +removed the clock lead, but exposed the other half of the bug: long room-loading +code without APU port accesses produced only one frame's PCM at return. Three +crossings then lost about 412 ms each. That experiment was superseded. + +The retained shared-runner correction synchronizes the absolute clock in the +interpreter's existing periodic batches, including work without port accesses. +The end of an iteration is the greater of one nominal frame and its executed +guest duration. The next iteration starts there, so a multi-frame loader cannot +leave the SPC waiting for a backward frame-count timestamp. NMI-disabled upload +handshakes remain unclamped. Unmapped startup retains relative catch-up until +APU port time is established. + +Hosts opt in with `RtlEnableExtendedFrameTiming()` and must pace each iteration +using `RtlLastFramePeriods()`. Super Metroid now does that. Hosts that have not +adopted the duration contract retain their existing behavior, including SA-1's +existing absolute-clock policy. No sound is generated from wall time, resampler +speed is unchanged, and the normal-play policy still discards stale wall-time +debt. This fixes shared timing used by the title's LLE driver; it does not migrate +the entire driver to the hardware-frame scheduler. + +Production traces `door-audio-final-clock-c.csv` and `door-audio-final-clock-d.csv` +contain six consecutive clean crossings: +zero missing output during and after the door, zero dropped samples, and zero +frames without newly produced PCM. Post-exit speed is 60.068-60.076 FPS. The +transition now produces 94,602 samples over about 2.947 seconds, accounting for +the loader's guest duration instead of forcing it into one host frame. +The Debug build with TCP/trace enabled also passed the fixture with zero missing +or dropped output, zero no-PCM frames, and 60.073 FPS after exit +(`build-codex-debug-dev/door-audio-debug-clock.csv`). Its largest guest call was +298 ms; audio production continued throughout that work. + +Earlier candidate replays also recorded intermittent 123-821 ms gaps *between* +guest calls, including ordinary gameplay. Those runs are retained as +`door-audio-final-clock-a.csv` and `door-audio-final-clock-b.csv`; they are not +counted as clean passes. The B-run guest/raster/presentation timings do not +account for those pauses. The optional `SM_PROFILE` report now measures the event +pump and deadline waits as well, to help attribute any recurrence. The clean C +run measured at most 0.219 ms in the event pump and 73.839 ms in a deadline wait +(the latter includes intentional waiting after an extended loader). + +Regression tests run the real SPC for a synthetic 40-frame loader followed by 45 +short iterations, checking that each short iteration immediately produces 534 +samples. Interpreter tests cover periodic absolute sync without port accesses, +no duplicate relative advancement, bootstrap progress, and legacy policy. The +host-clock test verifies an 18-period loader advances its deadline by 18 periods +and returns to ordinary pacing without a catch-up burst. + +Track shared timing in `beads-8wg.2.33` and the player-visible doorway regression +in `beads-8wg.6.5`. Production measurements remain the acceptance gate; debug +instrumentation can materially change available execution headroom. diff --git a/docs/releases/v0.3.3.md b/docs/releases/v0.3.3.md new file mode 100644 index 0000000..7b022ca --- /dev/null +++ b/docs/releases/v0.3.3.md @@ -0,0 +1,19 @@ +# Super Metroid v0.3.3 + +- Fix audio interruptions during door transitions by advancing the sound + processor continuously through loading work and preserving its elapsed time. +- Pace long loading iterations by their guest duration, keeping normal gameplay + speed after the door. The tested F1 transition takes about 2.95 seconds. +- Keep fast loading work from overflowing the audio buffer and allow playback + to build a small cushion after startup or starvation. +- Use Linux's corrected monotonic clock for pacing so a drifting raw timer + cannot make gameplay fall behind the audio device. +- Add repeatable doorway audio checks and missing/dropped-output diagnostics. + +Available as a Windows x64 ZIP and a Linux x86_64 AppImage. Existing saves remain +compatible; keep your ROM, configuration, and saves when updating. + +The release pins snesrecomp `e2c75fd`, the framework revision validated with this +game and included in the history of framework PR #70. Advancing this title to all +newer framework changes requires a separate frame-driver compatibility update +tracked as `beads-8wg.6.7`. diff --git a/snesrecomp b/snesrecomp index 01f3c73..e2c75fd 160000 --- a/snesrecomp +++ b/snesrecomp @@ -1 +1 @@ -Subproject commit 01f3c7324bd0e9aa1d18557abe3157e65a8936ff +Subproject commit e2c75fd5876893d5450a35dba4b52ffbd114f905 diff --git a/src/main.c b/src/main.c index 48f69d6..22df629 100644 --- a/src/main.c +++ b/src/main.c @@ -26,10 +26,13 @@ #else #include #include +#include #include #endif #include "snes/ppu.h" +#include "snes/apu.h" +#include "audio_trace.h" #include "snes/ws_shadow.h" #include "types.h" @@ -159,12 +162,21 @@ static bool SmCustomRendererEnabled(void) { return g_sm_video.enhanced || g_sm_video.fps_enabled; } static double SmMonotonicSeconds(void) { +#if defined(__linux__) + /* Match the clock used by Linux sleep/audio scheduling. SDL's performance + * counter uses MONOTONIC_RAW, which excludes frequency corrections: on a + * drifting VM it can pace the guest slower than the audio device. */ + struct timespec now; + if (clock_gettime(CLOCK_MONOTONIC, &now) == 0) + return (double)now.tv_sec + (double)now.tv_nsec / 1e9; +#endif return (double)SDL_GetPerformanceCounter() / SDL_GetPerformanceFrequency(); } /* Opt-in wall-time diagnostics. No guest state is sampled or changed here. * Values include preemption/lock waits and are not CPU-time measurements. */ enum { kSmProfileGuest, kSmProfileRaster, kSmProfileAcquire, - kSmProfileCompose, kSmProfilePresent, kSmProfileTrace, kSmProfileCount }; + kSmProfileCompose, kSmProfilePresent, kSmProfileTrace, kSmProfileAudioTrace, + kSmProfileEvents, kSmProfileWait, kSmProfileCount }; static bool g_sm_profile; static unsigned g_sm_profile_frame; static struct { double total, maximum; unsigned count, maximum_frame; } g_sm_timings[kSmProfileCount]; @@ -182,6 +194,7 @@ static void SmProfileEnd(unsigned stage, double start) { ++g_sm_timings[stage].count; } static void SmWaitUntil(double deadline) { + double profile_start = SmProfileStart(); /* Same short deadline wait used by F-Zero. A fixed 1ms sleep on every * presentation-only iteration unnecessarily overshoots near deadlines. */ double now = SmMonotonicSeconds(); @@ -193,6 +206,7 @@ static void SmWaitUntil(double deadline) { SDL_Delay(0); now = SmMonotonicSeconds(); } + SmProfileEnd(kSmProfileWait, profile_start); } static double SmDisplayRefresh(void) { #if SNESRECOMP_SDL3 @@ -707,6 +721,15 @@ static uint8 *g_audiobuffer, *g_audiobuffer_cur, *g_audiobuffer_end; static int g_frames_per_block; static uint8 g_audio_channels; static SDL_AudioDeviceID g_audio_device; +/* Only the thread executing guest work may wait for the audio consumer. */ +static _Thread_local bool g_audio_producer_active; +static _Thread_local unsigned g_apu_lock_depth; +static _Thread_local bool g_audio_consumer_stalled; +static _Thread_local uint64_t g_audio_stalled_callback; +static uint64_t g_audio_callback_count; /* protected by g_audio_mutex */ +static bool g_audio_primed; /* protected by g_audio_mutex */ +#define SM_AUDIO_PREFILL 2136u +#define SM_AUDIO_HIGH_WATER 4096u #if SNESRECOMP_SDL3 /* SDL3 replaced the pull callback with an SDL_AudioStream the app pushes into, * so the mixer needs a scratch buffer sized to whatever the stream asks for. */ @@ -717,9 +740,36 @@ static size_t g_audio_stream_buffer_size; void RtlApuLock(void) { SDL_LockMutex(g_audio_mutex); + ++g_apu_lock_depth; } void RtlApuUnlock(void) { + --g_apu_lock_depth; + if (g_apu_lock_depth == 0 && g_audio_producer_active && + g_audio_consumer_stalled && + g_audio_callback_count != g_audio_stalled_callback) + g_audio_consumer_stalled = false; + if (g_apu_lock_depth == 0 && g_audio_producer_active && + !g_audio_consumer_stalled && + dsp_available(g_snes->apu->dsp) > SM_AUDIO_HIGH_WATER) { + /* Fast hosts can generate a multi-frame loader's PCM in milliseconds. + * Let the device drain it before the bounded ring overflows. Always + * release the mutex while waiting, and stop waiting if the device stalls. */ + double limit = SmMonotonicSeconds() + 0.25; + while (dsp_available(g_snes->apu->dsp) > SM_AUDIO_HIGH_WATER) { + SDL_UnlockMutex(g_audio_mutex); + SDL_Delay(1); + SDL_LockMutex(g_audio_mutex); + if (SmMonotonicSeconds() >= limit) { + /* A disconnected device must not add this timeout to every frame. + * Rearm only after the consumer has actually made progress. */ + g_audio_consumer_stalled = true; + g_audio_stalled_callback = g_audio_callback_count; + g_audio_producer_active = false; + break; + } + } + } SDL_UnlockMutex(g_audio_mutex); } @@ -732,9 +782,22 @@ static void FillAudioBuffer(Uint8 *stream, int len) { if (SDL_AtomicCAS(&first_cb, 0, 1)) host_report_breadcrumb("first audio callback (len=%d)", len); if (!snesrecomp_sdl_lock_mutex(g_audio_mutex)) Die("Mutex lock failed!"); + ++g_audio_callback_count; while (len != 0) { if (g_audiobuffer_end - g_audiobuffer_cur == 0) { - RtlRenderAudio((int16 *)g_audiobuffer, g_frames_per_block, g_audio_channels); + uint32_t available = dsp_available(g_snes->apu->dsp); + if (!g_audio_primed && available < SM_AUDIO_PREFILL) { + /* Startup/save-load starvation needs a cushion before playback + * resumes. Retain all native PCM; count the undelivered output just + * like any other underrun rather than hiding it from diagnostics. */ + memset(g_audiobuffer, 0, g_frames_per_block * g_audio_channels * sizeof(int16)); + audio_trace_on_output_underflow(available, g_frames_per_block); + } else { + g_audio_primed = true; + RtlRenderAudio((int16 *)g_audiobuffer, g_frames_per_block, g_audio_channels); + if (dsp_available(g_snes->apu->dsp) < 4) + g_audio_primed = false; + } g_audiobuffer_cur = g_audiobuffer; g_audiobuffer_end = g_audiobuffer + g_frames_per_block * g_audio_channels * sizeof(int16); } @@ -1498,6 +1561,7 @@ error_reading:; g_spc_player->initialize(g_spc_player); host_report_breadcrumb("SPC player initialized"); + int audio_output_rate = 0; if (g_config.enable_audio) { /* Enumerate output devices into the breadcrumb ring: which device * SDL picks (and what else was available) is exactly the per-machine @@ -1551,7 +1615,8 @@ error_reading:; * walked the output ring to its cap in under three minutes of play. */ /* The consumer converts the SPC's native 32040 Hz onto this rate and * cannot infer it; see RtlSetAudioOutputRate in common_rtl.h. */ - RtlSetAudioOutputRate(have.freq); + RtlSetAudioOutputRate(have.freq); + audio_output_rate = have.freq; g_frames_per_block = (534 * have.freq + 32040 / 2) / 32040; g_audiobuffer = (uint8 *)calloc(g_frames_per_block * have.channels * sizeof(int16), 1); host_report_breadcrumb( @@ -1619,12 +1684,23 @@ error_reading:; if (framedump_dir) FrameDump_Init(framedump_dir); + RtlEnableExtendedFrameTiming(); bool running = true; uint32 frameCtr = 0; const char *run_frames_env = getenv("SM_RUN_FRAMES"); unsigned run_frames = run_frames_env ? (unsigned)strtoul(run_frames_env, NULL, 10) : 0; const char *trace_path = getenv("SM_STATE_TRACE"); FILE *state_trace = trace_path ? fopen(trace_path, "w") : NULL; + /* Optional production-path measurement. Sample after guest execution so a + * trace proves that the saved doorway was crossed, and attributes missing + * PCM to the transition rather than boot or loading the save itself. */ + const char *audio_probe_path = getenv("SM_AUDIO_PROBE"); + FILE *audio_probe = audio_probe_path ? fopen(audio_probe_path, "w") : NULL; + /* Keep bounded doorway probes in memory until close: frequent small writes + * can block behind filesystem/antivirus work and create the very underruns + * being measured. Longer sessions flush this buffer periodically. */ + if (audio_probe) setvbuf(audio_probe, NULL, _IOFBF, 1024 * 1024); + if (audio_probe) fprintf(audio_probe, "frame,seconds,guest_ms,state,door_step,room,master,port_clock,guest_anchor,target_anchor,last_guest,last_target,produced,consumed,underflows,occupancy,missing_frames,dropped,output_rate\n"); uint64_t presentations = 0; bool profile_requested = getenv("SM_PROFILE") && atoi(getenv("SM_PROFILE")) != 0; unsigned profile_first = getenv("SM_PROFILE_START_FRAME") @@ -1649,6 +1725,7 @@ error_reading:; * whole crash-capture pipeline (minidump + report + crash copy). */ host_report_crash_test_tick(); + double event_profile_start = SmProfileStart(); while (SDL_PollEvent(&event)) { switch (event.type) { case SDL_CONTROLLERDEVICEADDED: @@ -1705,6 +1782,7 @@ error_reading:; } } + SmProfileEnd(kSmProfileEvents, event_profile_start); if (g_paused != audiopaused) { audiopaused = g_paused; SetAudioPaused(audiopaused); @@ -1806,10 +1884,31 @@ error_reading:; profile_window_start = SmMonotonicSeconds(); } double profile_start = SmProfileStart(); + double audio_probe_start = audio_probe ? SmMonotonicSeconds() : 0; if (SmCustomRendererEnabled()) SmRendererLatchObjectState(g_ram); + g_audio_producer_active = paced_realtime && g_audio_device != 0; RtlRunFrame(inputs | GetActiveControllers() | debug_server_get_controller_active_mask()); ApplyScriptForcePokes(); SmProfileEnd(kSmProfileGuest, profile_start); + if (audio_probe) { + profile_start = SmProfileStart(); + double now = SmMonotonicSeconds(); + AudioTraceStats st; + audio_trace_get_stats(&st); + Apu *apu = g_snes->apu; + fprintf(audio_probe, "%d,%.6f,%.3f,%u,%04x,%04x,%llu,%llu,%llu,%llu,%llu,%llu,%llu,%llu,%llu,%u,%llu,%llu,%d\n", + snes_frame_counter, now-run_start, (now-audio_probe_start)*1000, + g_ram[0x998] | g_ram[0x999]<<8, g_ram[0x99c] | g_ram[0x99d]<<8, + g_ram[0x79b] | g_ram[0x79c]<<8, + (unsigned long long)g_cpu.master_cycles, + (unsigned long long)apu->portClock, (unsigned long long)apu->portGuestAnchor, + (unsigned long long)apu->portTargetAnchor, (unsigned long long)apu->portLastGuest, + (unsigned long long)apu->portLastTarget, (unsigned long long)st.produced, + (unsigned long long)st.consumed, (unsigned long long)st.output_underflows, st.occupancy_current, + (unsigned long long)st.output_missing_frames, + (unsigned long long)st.dropped, audio_output_rate); + SmProfileEnd(kSmProfileAudioTrace, profile_start); + } #ifdef ENABLE_ORACLE_BACKEND // Step the oracle emulator with the same input. The runner's per-player @@ -1841,6 +1940,7 @@ error_reading:; profile_start = SmProfileStart(); SmCaptureSimulationFrame(frameCtr); + g_audio_producer_active = false; SmProfileEnd(kSmProfileRaster, profile_start); profile_start = SmProfileStart(); if (state_trace) @@ -1851,7 +1951,8 @@ error_reading:; if (paced_realtime) { uint8 game_state = g_ram[0x0998]; bool door_loading = game_state >= 9 && game_state <= 11; - SmClockSimulationDone(&video_clock, SmMonotonicSeconds(), door_loading); + SmClockSimulationDone(&video_clock, SmMonotonicSeconds(), door_loading, + RtlLastFramePeriods()); } else SmClockReset(&video_clock, SmMonotonicSeconds(), presentation_hz); @@ -1871,6 +1972,7 @@ error_reading:; } if (state_trace) fclose(state_trace); + if (audio_probe) fclose(audio_probe); host_report_breadcrumb("video totals: simulations=%u presentations=%llu seconds=%.3f", frameCtr, (unsigned long long)presentations, SmMonotonicSeconds() - run_start); @@ -1879,7 +1981,8 @@ error_reading:; host_report_breadcrumb("video profile window: first=%u last=%u seconds=%.6f presentations=%u", profile_first, frameCtr, profile_seconds, g_sm_timings[kSmProfilePresent].count); static const char *names[kSmProfileCount] = { - "guest", "raster-capture", "surface-acquire", "compose", "upload-present", "state-trace" + "guest", "raster-capture", "surface-acquire", "compose", "upload-present", "state-trace", "audio-trace", + "event-pump", "deadline-wait" }; for (unsigned i = 0; i < kSmProfileCount; ++i) host_report_breadcrumb("video profile: stage=%s count=%u total_ms=%.3f mean_ms=%.3f max_ms=%.3f max_frame=%u", diff --git a/src/sm_video.c b/src/sm_video.c index 9bdfd42..c1bc92f 100644 --- a/src/sm_video.c +++ b/src/sm_video.c @@ -133,8 +133,9 @@ void SmClockReset(SmClock *c, double now, double hz) { bool SmClockSimulationDue(const SmClock *c, double now) { return now >= c->next_simulation; } -void SmClockSimulationDone(SmClock *c, double now, bool preserve_debt) { - double deadline = c->next_simulation + 1.0 / SM_SIMULATION_HZ; +void SmClockSimulationDone(SmClock *c, double now, bool preserve_debt, + double elapsed_periods) { + double deadline = c->next_simulation + elapsed_periods / SM_SIMULATION_HZ; /* Keep ordinary sub-frame scheduling jitter on the original phase. A door * loader may preserve its backlog so its non-interactive frames refill the * guest-driven audio queue; all ordinary gameplay drops stale work. */ diff --git a/src/sm_video.h b/src/sm_video.h index 4d3bf86..33ff043 100644 --- a/src/sm_video.h +++ b/src/sm_video.h @@ -55,7 +55,8 @@ typedef struct SmClock { } SmClock; void SmClockReset(SmClock *clock, double now, double presentation_hz); bool SmClockSimulationDue(const SmClock *clock, double now); -void SmClockSimulationDone(SmClock *clock, double now, bool preserve_debt); +void SmClockSimulationDone(SmClock *clock, double now, bool preserve_debt, + double elapsed_periods); bool SmClockPresentationDue(const SmClock *clock, double now); void SmClockPresentationDone(SmClock *clock, double now); double SmClockAlpha(const SmClock *clock, double now); diff --git a/tests/door_audio_trace_test.py b/tests/door_audio_trace_test.py new file mode 100644 index 0000000..d3e414b --- /dev/null +++ b/tests/door_audio_trace_test.py @@ -0,0 +1,58 @@ +import sys +import unittest +from pathlib import Path + +sys.path.insert(0, str(Path(__file__).resolve().parents[1] / "tools")) +from check_door_audio import analyze + + +def fixture(): + return [dict(frame=i, seconds=i/60, state=11 if 60 <= i < 100 else 8, + room=0x91f8 if i < 70 else 0x92fd, produced=i*534, + underflows=42, missing_frames=32000, output_rate=32000) + for i in range(230)] + + +class DoorTraceTest(unittest.TestCase): + def test_title_screen_is_not_a_pass(self): + rows = fixture() + for row in rows: + row["state"] = 1 + with self.assertRaisesRegex(ValueError, "No gameplay-to-door"): + analyze(rows) + + def test_incomplete_transition_is_not_a_pass(self): + with self.assertRaisesRegex(ValueError, "Incomplete"): + analyze(fixture()[:90]) + + def test_boot_starvation_is_excluded(self): + result = analyze(fixture())[0] + self.assertEqual(result["missing_ms"], 0) + self.assertEqual(result["post_missing_ms"], 0) + self.assertAlmostEqual(result["post_fps"], 60) + + def test_transition_and_exit_gaps_are_measured(self): + rows = fixture() + for row in rows: + if row["frame"] >= 80: + row["missing_frames"] += 320 + row["underflows"] += 1 + if row["frame"] >= 110: + row["missing_frames"] += 160 + result = analyze(rows)[0] + self.assertEqual(result["missing_ms"], 10) + self.assertEqual(result["post_missing_ms"], 5) + self.assertEqual(result["underflows"], 1) + + def test_dropped_audio_is_measured_without_boot_drops(self): + rows = fixture() + for row in rows: + row["dropped"] = 1000 + (100 if row["frame"] >= 80 else 0) + row["dropped"] += 20 if row["frame"] >= 110 else 0 + result = analyze(rows)[0] + self.assertEqual(result["dropped_samples"], 100) + self.assertEqual(result["post_dropped_samples"], 20) + + +if __name__ == "__main__": + unittest.main() diff --git a/tests/sm_video_test.c b/tests/sm_video_test.c index 2bc9d6b..f2f174a 100644 --- a/tests/sm_video_test.c +++ b/tests/sm_video_test.c @@ -39,7 +39,7 @@ static void clock_invariance(void) { SmClockReset(&clock,0,rates[r]); for (int ms=0;ms<=10000;++ms) { double now=ms/1000.0; - while (SmClockSimulationDue(&clock,now)) SmClockSimulationDone(&clock,now,false); + while (SmClockSimulationDue(&clock,now)) SmClockSimulationDone(&clock,now,false,1); if (SmClockPresentationDue(&clock,now)) SmClockPresentationDone(&clock,now); double alpha=SmClockAlpha(&clock,now); assert(alpha >= 0 && alpha <= 1); @@ -51,12 +51,21 @@ static void clock_invariance(void) { SmClockReset(&stalled,0,144); SmClockPresentationDone(&stalled,5); assert(stalled.simulation_frames == 0 && SmClockSimulationDue(&stalled,5)); - while(SmClockSimulationDue(&stalled,5)) SmClockSimulationDone(&stalled,5,false); + while(SmClockSimulationDue(&stalled,5)) SmClockSimulationDone(&stalled,5,false,1); assert(stalled.simulation_frames == 1); /* Realtime play must discard stalled wall-time debt. */ SmClock loading; SmClockReset(&loading,0,144); - while(SmClockSimulationDue(&loading,5)) SmClockSimulationDone(&loading,5,true); + while(SmClockSimulationDue(&loading,5)) SmClockSimulationDone(&loading,5,true,1); assert(loading.simulation_frames == 301); /* Door loading deliberately repays its audio debt. */ + /* A loader that executed 18 hardware periods already generated their + * audio. Waiting those periods must not trigger 17 extra game iterations. */ + SmClock extended; + SmClockReset(&extended,0,165); + SmClockSimulationDone(&extended,0.23,true,18); + assert(fabs(extended.next_simulation - 18 / SM_SIMULATION_HZ) < 1e-9); + assert(!SmClockSimulationDue(&extended,0.29)); + SmClockSimulationDone(&extended,18 / SM_SIMULATION_HZ,false,1); + assert(fabs(extended.next_simulation - 19 / SM_SIMULATION_HZ) < 1e-9); assert(SmPresentationHz(0,165) == 165); assert(SmPresentationHz(0,1000) == 360); assert(SmPresentationHz(0,NAN) == 60); diff --git a/tools/check_door_audio.py b/tools/check_door_audio.py new file mode 100644 index 0000000..6688a1f --- /dev/null +++ b/tools/check_door_audio.py @@ -0,0 +1,99 @@ +"""Check an SM_AUDIO_PROBE CSV for a real doorway crossing and audio gaps.""" +import argparse +import csv +import json +from pathlib import Path + + +def read_trace(path): + with Path(path).open(newline="") as stream: + return [{key: float(value) if key in ("seconds", "guest_ms") else + int(value, 16 if key in ("door_step", "room") else 10) + for key, value in row.items()} + for row in csv.DictReader(stream)] + + +def analyze(rows, post_frames=120, output_rate=None): + # A successful process exit or zero underflows at the title screen must + # never count as a passing door test. Loading before guest reset used to + # erase the save and silently produce exactly that false positive. + starts = [i for i in range(1, len(rows)) + if rows[i-1]["state"] == 8 and 9 <= rows[i]["state"] <= 11] + if not starts: + raise ValueError("No gameplay-to-door transition; verify save load and input") + results = [] + for start in starts: + end = start + while end < len(rows) and 9 <= rows[end]["state"] <= 11: + end += 1 + if end + post_frames >= len(rows): + raise ValueError("Incomplete doorway or post-door measurement window") + before, after, post = rows[start-1], rows[end], rows[end+post_frames] + if after["state"] != 8 or after["room"] == before["room"]: + raise ValueError("Door did not return to gameplay in a different room") + if any(r["state"] != 8 for r in rows[end:end+post_frames+1]): + raise ValueError("Post-door window interrupted by another game state") + rate = output_rate or before.get("output_rate", 0) + if rate <= 0: + raise ValueError("Missing output sample rate") + # Counters are cumulative: exclude startup and loading the save. + def delta(key, a, b): + value = b[key] - a[key] + if value < 0: + raise ValueError("Counter reset inside measurement window") + return value + elapsed = post["seconds"] - after["seconds"] + if elapsed <= 0: + raise ValueError("Non-increasing wall clock") + zero_start = None + zero_ms = 0 + for prev, cur in zip(rows[start-1:end], rows[start:end+1]): + if cur["produced"] == prev["produced"]: + if zero_start is None: + zero_start = prev["seconds"] + zero_ms = max(zero_ms, (cur["seconds"]-zero_start)*1000) + else: + zero_start = None + results.append({ + "from_room": f"{before['room']:04x}", "to_room": f"{after['room']:04x}", + "first_frame": rows[start]["frame"], "exit_frame": after["frame"], + "transition_ms": round((after["seconds"]-before["seconds"])*1000, 3), + "underflows": delta("underflows", before, after), + "missing_ms": round(delta("missing_frames", before, after)*1000/rate, 3), + "post_missing_ms": round(delta("missing_frames", after, post)*1000/rate, 3), + "post_fps": round(delta("frame", after, post)/elapsed, 3), + "produced_samples": delta("produced", before, after), + "longest_no_pcm_ms": round(zero_ms, 3), + **({"dropped_samples": delta("dropped", before, after), + "post_dropped_samples": delta("dropped", after, post)} + if "dropped" in before else {}), + }) + return results + + +def main(): + parser = argparse.ArgumentParser(description=__doc__) + parser.add_argument("trace") + parser.add_argument("--post-frames", type=int, default=120) + parser.add_argument("--output-rate", type=int, help="For older traces without output_rate") + parser.add_argument("--max-missing-ms", type=float, default=0) + parser.add_argument("--max-post-fps", type=float, default=63) + args = parser.parse_args() + if args.post_frames < 60: + parser.error("--post-frames must cover at least 60 gameplay frames") + try: + results = analyze(read_trace(args.trace), args.post_frames, args.output_rate) + except (ValueError, KeyError, OSError) as error: + print(json.dumps({"valid": False, "error": str(error)})) + return 2 + passed = all(r["missing_ms"] <= args.max_missing_ms and + r["post_missing_ms"] <= args.max_missing_ms and + r.get("dropped_samples", 0) == 0 and + r.get("post_dropped_samples", 0) == 0 and + r["post_fps"] <= args.max_post_fps for r in results) + print(json.dumps({"valid": True, "passed": passed, "transitions": results}, indent=2)) + return 0 if passed else 1 + + +if __name__ == "__main__": + raise SystemExit(main()) diff --git a/tools/door_audio_repro.txt b/tools/door_audio_repro.txt new file mode 100644 index 0000000..c74e95e --- /dev/null +++ b/tools/door_audio_repro.txt @@ -0,0 +1,8 @@ +# Load only AFTER the first guest reset has executed. Loading at frame zero +# appears to succeed but reset immediately erases the saved gameplay state. +wait 180 +loadstate 0 +# Let save restoration and the audio queue settle before measuring the door. +wait 480 +press left 180 +wait 300