diff --git a/DeepDrftPublic.Client/Services/AudioPlayerService.cs b/DeepDrftPublic.Client/Services/AudioPlayerService.cs index df069e7..c33fe8f 100644 --- a/DeepDrftPublic.Client/Services/AudioPlayerService.cs +++ b/DeepDrftPublic.Client/Services/AudioPlayerService.cs @@ -186,10 +186,6 @@ public abstract class AudioPlayerService : IPlayerService, IAsyncDisposable var result = await _audioInterop.UnloadAsync(PlayerId); if (result.Success) { - // [RELOAD-DIAG] One of two base-class sites that null Duration (the other is - // OnPlaybackEndCallback). Logged so a run can attribute a "Duration set from header" - // re-fire to this path vs the spurious end-callback. Trivially removable. - OnDurationNulledDiag("Unload"); IsPlaying = false; IsPaused = false; CurrentTime = 0; @@ -282,12 +278,6 @@ public abstract class AudioPlayerService : IPlayerService, IAsyncDisposable private async Task OnPlaybackEndCallback() { - // [RELOAD-DIAG] The second base-class Duration-null site — the JS PlaybackScheduler's - // end-of-playback callback. A false (mid-stream) fire here is the Opus-startup bug: it nulls - // Duration (forcing a second "Duration set from header"), sets IsLoaded=false/CurrentTime=0, - // and raises TrackEnded (premature queue auto-advance). After the scheduler fix this must fire - // only on genuine end-of-track. Trivially removable. - OnDurationNulledDiag("OnPlaybackEndCallback"); IsPlaying = false; IsPaused = false; IsLoaded = false; @@ -318,15 +308,6 @@ public abstract class AudioPlayerService : IPlayerService, IAsyncDisposable /// protected virtual void OnPlaybackEnded() { } - /// - /// [RELOAD-DIAG] Diagnostic seam — invoked at each base-class site that nulls - /// ( and ), naming the caller. The streaming - /// subclass overrides this to emit a tagged log via its logger so a run can attribute a re-fired - /// "Duration set from header" to its true cause. No-op in the base; trivially removable. - /// - protected virtual void OnDurationNulledDiag(string caller) { } - - protected async Task EnsureInitializedAsync() { if (!IsInitialized) diff --git a/DeepDrftPublic.Client/Services/StreamingAudioPlayerService.cs b/DeepDrftPublic.Client/Services/StreamingAudioPlayerService.cs index 0db0a7c..0d8c79a 100644 --- a/DeepDrftPublic.Client/Services/StreamingAudioPlayerService.cs +++ b/DeepDrftPublic.Client/Services/StreamingAudioPlayerService.cs @@ -64,14 +64,6 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS private readonly ILogger _logger; private string? _currentTrackId; - // Monotonic load-generation counter (diagnostic). Incremented on every LoadTrackStreaming entry and - // stamped into the load's logs so two loads for ONE user play action — the "Duration set from header - // logged twice" double-load hypothesis that needs in-browser confirmation — are unmistakable: a - // single play should show exactly one "Streaming load #N started"/"finished" pair. If two overlapping - // starts appear for one click, the generation ids pin the re-entrancy. Cheap (an int per load) and - // never gates behavior. - private int _loadGeneration; - // The delivery format the active load resolved to (Phase 18). Captured once per LoadTrackStreaming and // reused by the seek-beyond-buffer re-fetch so the Range continuation requests the SAME artifact the // initial stream did — a seek must never switch formats mid-track (the JS decoder, the cached setup @@ -138,12 +130,6 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS // Organic end-of-stream closes the session; the bucket reflects the high-water fraction reached. protected override void OnPlaybackEnded() => _playTracker?.Close(); - // [RELOAD-DIAG] Emit the tagged log at each base-class Duration-null site so a run unambiguously - // shows which path nulled Duration between two "Duration set from header" lines. Trivially removable. - protected override void OnDurationNulledDiag(string caller) => - _logger.LogInformation( - "[RELOAD-DIAG] Base nulling Duration caller={Caller} (gen={Gen})", caller, _loadGeneration); - public override async Task SelectTrack(TrackDto track) { await SelectTrackStreaming(track); @@ -205,24 +191,12 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS private async Task LoadTrackStreaming(TrackDto track, double? startPosition = null) { - // [RELOAD-DIAG] Entry probe — captures every LoadTrackStreaming with its startPosition so a - // same-track reload (format switch) is distinguishable from a fresh play. _loadGeneration here - // is the PREVIOUS load's id (incremented below); it pins which generation this entry follows. - _logger.LogInformation( - "[RELOAD-DIAG] LoadTrackStreaming ENTRY track={TrackId} startPosition={StartPosition} (prevGen={Gen})", - track.EntryKey, startPosition?.ToString("F2") ?? "null", _loadGeneration); - // Always reset to clean state before loading new track. ResetToIdle // both cancels and awaits any in-flight streaming loop, so by the time // we return from it the previous loop is guaranteed to have exited and // there is no risk of interleaved ProcessStreamingChunk calls against // the single-instance JS StreamDecoder. - await ResetToIdle("prologue"); - - // Stamp this load with a fresh generation id (diagnostic — see _loadGeneration). Logged at - // start and finish so a double-load shows as two overlapping start/finish pairs for one play. - var loadGeneration = ++_loadGeneration; - _logger.LogInformation("Streaming load #{Gen} started for track {TrackId}", loadGeneration, track.EntryKey); + await ResetToIdle(); // Save track ID for seek operations _currentTrackId = track.EntryKey; @@ -387,8 +361,6 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS finally { IsLoading = false; - _logger.LogInformation("Streaming load #{Gen} finished for track {TrackId} (superseded={Superseded})", - loadGeneration, track.EntryKey, !ReferenceEquals(_streamingCancellation, loadCts)); // Only notify if this load is still the active operation. A superseding seek // owns state notifications; firing here mid-seek would push a stale snapshot. if (ReferenceEquals(_streamingCancellation, loadCts)) @@ -419,11 +391,6 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS double startPosition, CancellationToken cancellationToken) { - // [RELOAD-DIAG] Positioned-start entry (the format-switch / load-at-timestamp path). - _logger.LogInformation( - "[RELOAD-DIAG] StartFromPositionAsync ENTRY track={TrackId} startPosition={StartPosition:F2} (gen={Gen})", - trackId, startPosition, _loadGeneration); - // Resolve the byte offset for the target time. Opus answers immediately from its sidecar; WAV // returns failure until its header is parsed, so we probe the byte-0 segment and retry. The // byte-0 segment is disposed once it has served its purpose (header probe / nothing for Opus), @@ -520,10 +487,6 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS // Capture the once-only duration the header yields so the UI and play session have it. if (result.Duration.HasValue && Duration == null) { - // [RELOAD-DIAG] Header duration set via the probe path (StartFromPositionAsync probe). - _logger.LogInformation( - "[RELOAD-DIAG] Duration set from header (PROBE path) {Duration:F2}s (gen={Gen})", - result.Duration.Value, _loadGeneration); Duration = result.Duration.Value; _playTracker?.SetDuration(result.Duration.Value); } @@ -669,13 +632,6 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS double? seekPosition, CancellationToken cancellationToken) { - // [RELOAD-DIAG] Distinguishes a fresh forward load (seekPosition null) from a seek/refill re-entry - // (seekPosition non-null), which reinitializes the decoder — a candidate for a second header parse. - _logger.LogInformation( - "[RELOAD-DIAG] RunSegmentedStreamAsync ENTRY track={TrackId} cursor={Cursor} seekPosition={SeekPosition} kind={Kind} (gen={Gen})", - trackId, cursor, seekPosition?.ToString("F2") ?? "null", - seekPosition is null ? "forward-load" : "seek/refill-reentry", _loadGeneration); - byte[]? buffer = null; var segment = firstSegment; try @@ -742,12 +698,6 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS if (chunkResult.Duration.HasValue && Duration == null) { Duration = chunkResult.Duration.Value; - // [RELOAD-DIAG] Header duration set via the stream-loop path. The gen + seekPosition - // context (logged at RunSegmentedStreamAsync entry) tells whether this is the fresh - // forward load or a seek/refill re-entry re-parsing the header. - _logger.LogInformation( - "[RELOAD-DIAG] Duration set from header (STREAM-LOOP path) {Duration:F2}s (gen={Gen})", - Duration, _loadGeneration); _logger.LogInformation("Duration set from header: {Duration:F2} seconds", Duration); // Feed the once-only duration to the play session for the completion // fraction. No-op when no session is open; idempotent otherwise. @@ -946,7 +896,7 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS public override async Task Stop() { // In streaming mode, Stop = Unload (data is consumed, can't replay) - await ResetToIdle("stop"); + await ResetToIdle(); } /// @@ -954,7 +904,7 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS /// public override async Task Unload() { - await ResetToIdle("unload"); + await ResetToIdle(); } /// @@ -964,9 +914,6 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS { if (!IsLoaded || !IsStreamingMode) return; - // [RELOAD-DIAG] Seek entry — precedes the within-buffer vs beyond-buffer branch below. - _logger.LogInformation("[RELOAD-DIAG] Seek ENTRY position={Position:F2} (gen={Gen})", position, _loadGeneration); - try { var result = await _audioInterop.SeekAsync(PlayerId, position); @@ -1007,11 +954,6 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS /// private async Task SeekBeyondBuffer(double seekPosition, long byteOffset) { - // [RELOAD-DIAG] Seek-beyond-buffer entry — re-streams from an offset and reinitializes the decoder. - _logger.LogInformation( - "[RELOAD-DIAG] SeekBeyondBuffer ENTRY seekPosition={SeekPosition:F2} byteOffset={ByteOffset} (gen={Gen})", - seekPosition, byteOffset, _loadGeneration); - if (string.IsNullOrEmpty(_currentTrackId)) { ErrorMessage = "Cannot seek - no track loaded"; @@ -1149,11 +1091,6 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS /// private async Task RecoverFromFailedRefill(double seekPosition, string userFacingError) { - // [RELOAD-DIAG] Refill-failure recovery entry — a mid-stream re-fetch failed and we are halting. - _logger.LogInformation( - "[RELOAD-DIAG] RecoverFromFailedRefill ENTRY seekPosition={SeekPosition:F2} (gen={Gen})", - seekPosition, _loadGeneration); - // Halt the starved scheduler JS-side (stop sources, drop stale buffers, anchor at the target). // Best-effort: if even this interop fails the player is no worse off, and we still surface the // error and settle C# state below. @@ -1182,14 +1119,8 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS /// Single method to reset all state - called by both Stop and Unload, and as the prologue of a new /// load. /// - /// [RELOAD-DIAG] Diagnostic label naming the call site (prologue / stop / unload - /// / dispose) so a trace shows WHICH reset nulled Duration. Removable with the rest of the - /// instrumentation; defaults so existing call shapes are unaffected. - private async Task ResetToIdle(string caller = "unspecified") + private async Task ResetToIdle() { - // [RELOAD-DIAG] Which caller is resetting, and at which generation. - _logger.LogInformation("[RELOAD-DIAG] ResetToIdle caller={Caller} (gen={Gen})", caller, _loadGeneration); - // 0. Close any open play session BEFORE tearing down (§2.1). ResetToIdle is the single funnel // for stop / unload / dispose / track-switch (a new LoadTrackStreaming calls it first), so a // superseded listen is recorded here with its high-water bucket. Close is idempotent — if the @@ -1222,9 +1153,6 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS IsLoaded = false; IsLoading = false; CurrentTime = 0; - // [RELOAD-DIAG] Duration nulled here — the only site that nulls it. If "Duration set from header" - // appears after this line for the SAME generation, a reset ran mid-load. - _logger.LogInformation("[RELOAD-DIAG] ResetToIdle nulling Duration (gen={Gen})", _loadGeneration); Duration = null; LoadProgress = 0; ErrorMessage = null; @@ -1292,25 +1220,11 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS /// private async Task DrainBackpressureAsync(CancellationToken cancellationToken) { - // [BP-DIAG] Time how long the read loop is actually parked here. A drain that releases in a few - // hundred ms is healthy throttling; a drain that holds for many seconds (paired with the JS - // PAUSED line) confirms back-pressure is parking production — whereas NO drain lines alongside - // frequent JS underrun PARK/RESUME lines means the loop never throttled and decode simply could - // not keep up. Logged only when it actually waited, so steady-state no-op drains add no noise. - var stopwatch = System.Diagnostics.Stopwatch.StartNew(); - var waited = false; while (IsPaused || await _audioInterop.IsProductionPaused(PlayerId)) { - waited = true; cancellationToken.ThrowIfCancellationRequested(); await Task.Delay(BackpressurePollMs, cancellationToken); } - if (waited) - { - _logger.LogInformation( - "[BP-DIAG] DrainBackpressure released after {Ms} ms (isPaused={IsPaused}, gen={Gen})", - stopwatch.ElapsedMilliseconds, IsPaused, _loadGeneration); - } } private async Task ThrottledNotifyStateChanged() @@ -1334,7 +1248,7 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS try { // ResetToIdle closes any open play session, so a dispose mid-play still records the listen. - await ResetToIdle("dispose"); + await ResetToIdle(); } catch { diff --git a/DeepDrftPublic/Interop/audio/OpusStreamDecoder.ts b/DeepDrftPublic/Interop/audio/OpusStreamDecoder.ts index be02c45..eb4fcde 100644 --- a/DeepDrftPublic/Interop/audio/OpusStreamDecoder.ts +++ b/DeepDrftPublic/Interop/audio/OpusStreamDecoder.ts @@ -29,6 +29,7 @@ */ import { AudioContextManager } from './AudioContextManager.js'; +import { decodePressure } from './decodePressure.js'; import { IStreamingDecoder } from './IStreamingDecoder.js'; import { OggDemuxer, OpusPacket, extractOpusHead, opusHeadChannelCount } from './OggDemuxer.js'; import { OpusSeekData, OPUS_SAMPLE_RATE } from './OpusSidecar.js'; @@ -163,11 +164,6 @@ export class OpusStreamDecoder implements IStreamingDecoder { // order-sensitive). configure() is deferred too — no need to spin up the decoder while // throttled. The C# loop also stops reading above high-water, so the stash stays small. if (this.isSchedulerFull?.()) { - // [BP-DIAG] First stash since last drain — production is now throttled and decode is parked. - // Trivially removable. - if (this.pendingBytes.length === 0) { - console.log('[BP-DIAG] Opus stash START (scheduler full, decode parked)'); - } this.pendingBytes.push(chunk); return []; } @@ -178,8 +174,6 @@ export class OpusStreamDecoder implements IStreamingDecoder { // the new chunk, through the demuxer as one contiguous feed. const out: AudioBuffer[] = []; if (this.pendingBytes.length > 0) { - // [BP-DIAG] Scheduler drained below low-water — replaying the stash. Trivially removable. - console.log(`[BP-DIAG] Opus stash DRAIN ${this.pendingBytes.length} chunks`); const stashed = this.pendingBytes; this.pendingBytes = []; for (const bytes of stashed) { @@ -382,12 +376,12 @@ export class OpusStreamDecoder implements IStreamingDecoder { let iters = 0; const poll = () => { if (!this.decoder || this.decoder.decodeQueueSize === 0 || iters >= MAX_YIELD_ITERS) { - // [BP-DIAG] If we hit the 200 ms ceiling with the decode queue still non-empty, the - // WebCodecs decoder is falling behind realtime (the throughput suspect for sustained - // underrun — worse with HW accel off). Frequent CAP lines pin decode, not back-pressure, - // as the block. Trivially removable. + // Hitting the 200 ms ceiling with the decode queue still non-empty means the WebCodecs + // decoder is falling behind realtime — the decode-starvation symptom that worsens with + // HW accel off (software WebGL render contending for the main thread). Report it as + // decode pressure so the visualizer throttles and yields the main thread back to decode. if (this.decoder && iters >= MAX_YIELD_ITERS && this.decoder.decodeQueueSize > 0) { - console.log(`[BP-DIAG] Opus yield CAP hit, decodeQueueSize=${this.decoder.decodeQueueSize} (decoder behind realtime)`); + decodePressure.report(); } resolve(); return; diff --git a/DeepDrftPublic/Interop/audio/PlaybackScheduler.ts b/DeepDrftPublic/Interop/audio/PlaybackScheduler.ts index 244b018..597bc07 100644 --- a/DeepDrftPublic/Interop/audio/PlaybackScheduler.ts +++ b/DeepDrftPublic/Interop/audio/PlaybackScheduler.ts @@ -27,6 +27,7 @@ */ import { AudioContextManager } from './AudioContextManager.js'; +import { decodePressure } from './decodePressure.js'; /** * Provisional back-retain default. The window-size POLICY (OQ1/OQ3) is not decided yet, so @@ -58,15 +59,17 @@ const DEFAULT_BACK_RETAIN_SECONDS = 10; * footprint is tiny (48 kHz stereo ≈ 0.37 MB/s, so 60 s ≈ 23 MB — a fraction of the 96 MB cap) * yet whose per-packet decode jitter (HW-accel-off software decode, main-thread AudioData copies) * needs a deeper buffer to stay ahead of the playhead. Doubling the window lets Opus use the memory - * headroom the byte cap already permits. The byte cap is UNCHANGED, so high-density formats - * (lossless) still pause at exactly the same footprint as before — the OOM fix does not regress. + * headroom the byte cap already permits. The byte cap is UNCHANGED, so a high-footprint stream + * still pauses at exactly the same footprint as before — the OOM fix does not regress. * * OQ3 hard memory ceiling: an absolute byte cap on total decoded float held, independent of the * time window. This is the guard-rail that makes "1 GB never OOMs" a guarantee rather than a * tuning hope — production pauses on `lookahead >= high OR bytes > cap`, whichever fires first, so - * the footprint can never exceed the cap regardless of the time window. For dense lossless the - * byte cap fires before 60 s (bounding memory exactly as the old 30 s window's byte estimate did); - * for sparse Opus the time window fires first, at ~23 MB. Estimated as channels × frames × 4 (f32). + * the footprint can never exceed the cap regardless of the time window. The decoded f32 footprint + * scales with sample rate × channels (not source codec), so for high-sample-rate / multichannel + * audio the byte cap fires before 60 s (bounding memory exactly as the old 30 s window's byte + * estimate did); for sparse 48 kHz stereo Opus the time window fires first, at ~23 MB. Estimated + * as channels × frames × 4 (f32). */ const DEFAULT_FORWARD_HIGH_WATER_SECONDS = 60; const DEFAULT_FORWARD_LOW_WATER_SECONDS = 30; @@ -83,7 +86,7 @@ const BYTES_PER_FLOAT_SAMPLE = 4; * resumed on the next ~20 ms, and so on — the audible start/stop thrash during the WebCodecs decode * ramp. Gating on a fixed LEAD in seconds gives a resume the same cushion a fresh start has, * independent of format. 1 s is the same order as the lossless playback-start lead (~6 segments) and - * sits far below the 30 s forward high-water, so back-pressure never throttles production while the + * sits far below the 60 s forward high-water, so back-pressure never throttles production while the * scheduler is still re-accumulating this lead. Tunable; not magic. */ const DEFAULT_MIN_PLAYBACK_LEAD_SECONDS = 1.0; @@ -305,7 +308,6 @@ export class PlaybackScheduler { evaluateProductionPause(): boolean { const lookahead = this.getForwardLookaheadSeconds(); const overByteCeiling = this.maxDecodedBytes > 0 && this.getDecodedByteEstimate() > this.maxDecodedBytes; - const wasPaused = this.productionPaused_; if (this.productionPaused_) { // Stay paused until BOTH the time window has drained below low-water AND the byte @@ -317,19 +319,6 @@ export class PlaybackScheduler { this.productionPaused_ = true; } - // [BP-DIAG] Log only the latch TRANSITIONS (not per-call) so a browser run shows exactly when - // production was throttled and the live numbers at that instant — the test for "production - // paused while decoded audio is actually low" (the prime block hypothesis). If a PAUSED line - // ever shows a small lookahead, the lookahead computation is the culprit; if it always shows - // ~high-water, back-pressure is innocent and the symptom is decode throughput. Trivially removable. - if (wasPaused !== this.productionPaused_) { - console.log( - `[BP-DIAG] production ${this.productionPaused_ ? 'PAUSED' : 'RESUMED'} ` + - `lookahead=${lookahead.toFixed(2)}s bytes=${(this.getDecodedByteEstimate() / 1048576).toFixed(1)}MB ` + - `buffers=${this.buffers.length} nextIdx=${this.nextBufferIndex} ` + - `pos=${this.getCurrentPosition().toFixed(2)}s overByteCeiling=${overByteCeiling}`); - } - return this.productionPaused_; } @@ -500,12 +489,6 @@ export class PlaybackScheduler { if (!this.streamComplete && !this.hasMinimumPlaybackLead()) { return; // still re-accumulating the rebuffer lead — remain parked } - // [BP-DIAG] Underrun resume — the playhead drained mid-stream and we have now rebuilt the - // lead. Frequent RESUME lines (paired with the PARK lines below) are the "repeatedly hits end - // of buffer" thrash: decode is not staying ahead. Trivially removable. - console.log( - `[BP-DIAG] underrun RESUME lead=${this.getForwardLookaheadSeconds().toFixed(2)}s ` + - `buffers=${this.buffers.length} nextIdx=${this.nextBufferIndex} streamComplete=${this.streamComplete}`); this.underrun_ = false; this.isActive_ = true; this.playbackAnchorTime = this.contextManager.currentTime; @@ -610,12 +593,11 @@ export class PlaybackScheduler { this.finishPlayback(); } else { this.underrun_ = true; - // [BP-DIAG] Mid-stream underrun: the scheduled queue drained and decode has not caught up. - // This is the symptom Daniel reports. The paired RESUME line above shows how long the gap - // lasted and what lead it rebuilt to. Trivially removable. - console.log( - `[BP-DIAG] underrun PARK pos=${this.getCurrentPosition().toFixed(2)}s ` + - `buffers=${this.buffers.length} nextIdx=${this.nextBufferIndex}`); + // Mid-stream underrun: the scheduled queue drained and decode has not caught up. Report it + // as decode pressure so the visualizer throttles — a sustained run of these is exactly the + // HW-accel-off starvation the auto-throttle protects against. The hysteresis in the signal + // ignores a lone startup-ramp underrun; only a sustained run engages the throttle. + decodePressure.report(); // Hold the playhead at the decoded tail so getCurrentPosition stays exact during // the gap. isActive_ goes false so no stale-anchor scheduling occurs; resume // re-anchors at currentTime when buffers arrive. diff --git a/DeepDrftPublic/Interop/audio/decodePressure.test.ts b/DeepDrftPublic/Interop/audio/decodePressure.test.ts new file mode 100644 index 0000000..72776b1 --- /dev/null +++ b/DeepDrftPublic/Interop/audio/decodePressure.test.ts @@ -0,0 +1,157 @@ +/** + * decodePressure hysteresis tests — the Part-1 auto-throttle signal logic. + * + * These cover the four named behaviours that make the visualizer-throttle safe: it engages only on + * SUSTAINED pressure, releases only after SUSTAINED recovery, never flaps on/off, and is a complete + * no-op when decode is healthy. The clock is injected so every transition is asserted at an exact + * timestamp — no real timers, fully deterministic. + * + * Run (no test runner configured; Node 22+ strips TS types natively — see OpusStreamDecoder.test.ts): + * dotnet build DeepDrftPublic/DeepDrftPublic.csproj + * cp DeepDrftPublic/Interop/audio/decodePressure.test.ts DeepDrftPublic/wwwroot/js/audio/ + * node DeepDrftPublic/wwwroot/js/audio/decodePressure.test.ts + * + * A thrown error / non-zero exit signals failure; "ALL TESTS PASSED" signals success. + */ + +import { + DecodePressureSignal, + ENGAGE_EVENTS, + ENGAGE_WINDOW_MS, + RELEASE_QUIET_MS, + MIN_ENGAGED_MS, +} from './decodePressure.js'; + +// --- tiny inline harness (no dependencies) --------------------------------------------------- +let passed = 0; +const failures: string[] = []; +function test(name: string, fn: () => void): void { + try { + fn(); + passed++; + } catch (e) { + failures.push(`FAIL: ${name}\n ${(e as Error).message}`); + } +} +function assertTrue(actual: boolean, msg?: string): void { + if (actual !== true) throw new Error(`${msg ?? 'assertTrue'}: expected true, got ${String(actual)}`); +} +function assertFalse(actual: boolean, msg?: string): void { + if (actual !== false) throw new Error(`${msg ?? 'assertFalse'}: expected false, got ${String(actual)}`); +} + +/** A signal driven by a hand-advanced clock, so every transition is asserted at an exact time. */ +function makeSignal() { + let now = 1000; // start at a non-zero base so "no prior stress" (-Infinity) is unambiguous + const sig = new DecodePressureSignal(() => now); + return { + sig, + at(ms: number) { now = ms; }, + advance(ms: number) { now += ms; }, + now() { return now; }, + }; +} + +// --- no engage when healthy ------------------------------------------------------------------ + +test('healthy stream never engages (no reports at all)', () => { + const { sig, advance } = makeSignal(); + for (let i = 0; i < 10; i++) { + advance(1000); + assertFalse(sig.isUnderPressure(), 'healthy must never be under pressure'); + } +}); + +test('a single transient stress does not engage', () => { + const { sig, advance } = makeSignal(); + sig.report(); + assertFalse(sig.isUnderPressure(), 'one event is not sustained'); + advance(500); + assertFalse(sig.isUnderPressure(), 'still not sustained'); +}); + +test('fewer than ENGAGE_EVENTS within the window does not engage', () => { + const { sig, advance } = makeSignal(); + for (let i = 0; i < ENGAGE_EVENTS - 1; i++) { + sig.report(); + advance(10); + } + assertFalse(sig.isUnderPressure(), 'one short of the threshold must not engage'); +}); + +test('stress spread wider than the window never accumulates enough to engage', () => { + const { sig, advance } = makeSignal(); + // One report per full window: the prune drops each before the next, so the live count never + // reaches ENGAGE_EVENTS even after many reports. + for (let i = 0; i < ENGAGE_EVENTS * 3; i++) { + sig.report(); + assertFalse(sig.isUnderPressure(), 'spread-out stress is not sustained'); + advance(ENGAGE_WINDOW_MS); + } +}); + +// --- engages on sustained pressure ----------------------------------------------------------- + +test('ENGAGE_EVENTS within the window engages', () => { + const { sig, advance } = makeSignal(); + for (let i = 0; i < ENGAGE_EVENTS; i++) { + sig.report(); + advance(10); // all comfortably inside ENGAGE_WINDOW_MS + } + assertTrue(sig.isUnderPressure(), 'sustained pressure must engage'); +}); + +// --- releases after recovery ----------------------------------------------------------------- + +test('releases after sustained quiet past the min dwell', () => { + const { sig, advance } = makeSignal(); + for (let i = 0; i < ENGAGE_EVENTS; i++) { sig.report(); advance(10); } + assertTrue(sig.isUnderPressure(), 'engaged'); + + // Quiet long enough to satisfy BOTH the min engaged dwell and the release-quiet window. + advance(Math.max(MIN_ENGAGED_MS, RELEASE_QUIET_MS) + 1); + assertFalse(sig.isUnderPressure(), 'sustained recovery must release'); +}); + +test('re-engages after a release when a fresh burst arrives', () => { + const { sig, advance } = makeSignal(); + for (let i = 0; i < ENGAGE_EVENTS; i++) { sig.report(); advance(10); } + assertTrue(sig.isUnderPressure(), 'engaged first time'); + advance(Math.max(MIN_ENGAGED_MS, RELEASE_QUIET_MS) + 1); + assertFalse(sig.isUnderPressure(), 'released'); + + for (let i = 0; i < ENGAGE_EVENTS; i++) { sig.report(); advance(10); } + assertTrue(sig.isUnderPressure(), 'a fresh sustained burst re-engages'); +}); + +// --- no flap --------------------------------------------------------------------------------- + +test('stays engaged during a brief quiet shorter than the release window', () => { + const { sig, advance } = makeSignal(); + for (let i = 0; i < ENGAGE_EVENTS; i++) { sig.report(); advance(10); } + assertTrue(sig.isUnderPressure(), 'engaged'); + + // A gap shorter than RELEASE_QUIET_MS must NOT release — that is the anti-flap guarantee. + advance(RELEASE_QUIET_MS - 100); + assertTrue(sig.isUnderPressure(), 'a brief quiet must not drop the throttle'); +}); + +test('continued stress holds the throttle engaged indefinitely', () => { + const { sig, advance } = makeSignal(); + for (let i = 0; i < ENGAGE_EVENTS; i++) { sig.report(); advance(10); } + assertTrue(sig.isUnderPressure(), 'engaged'); + + // Keep reporting at a cadence under the release window; it must never release. + for (let i = 0; i < 20; i++) { + advance(RELEASE_QUIET_MS - 100); + sig.report(); + assertTrue(sig.isUnderPressure(), 'ongoing stress keeps it engaged'); + } +}); + +// --- report ---------------------------------------------------------------------------------- +if (failures.length > 0) { + console.error(failures.join('\n')); + throw new Error(`${failures.length} test(s) failed, ${passed} passed`); +} +console.log(`ALL ${passed} TESTS PASSED`); diff --git a/DeepDrftPublic/Interop/audio/decodePressure.ts b/DeepDrftPublic/Interop/audio/decodePressure.ts new file mode 100644 index 0000000..5c7deab --- /dev/null +++ b/DeepDrftPublic/Interop/audio/decodePressure.ts @@ -0,0 +1,93 @@ +/** + * Shared decode-pressure signal — the seam that lets the audio decode pipeline protect itself + * from the WebGL visualizer under CPU contention. + * + * THE PROBLEM (browser-confirmed): with hardware acceleration OFF the WaveformVisualizer's WebGL2 + * lava-lamp software-renders on the main thread. WebCodecs Opus decode also runs on the main thread, + * so a 60 fps software render starves decode → it falls behind realtime → playback underruns. Turning + * the visualizer off makes decode keep up perfectly. With HW accel ON the render is on the GPU and + * there is no contention; WAV/lossless decodes synchronously and never pressures decode either. + * + * THE SEAM: this module is a singleton shared by two otherwise-independent browser module graphs — + * the audio pipeline (`js/audio/*`, the PRODUCER) and the visualizer (`js/visualizer/*`, the + * CONSUMER) — because an ES module is instantiated once per URL. The producer reports decode stress; + * the consumer reads {@link DecodePressureSignal.isUnderPressure} each frame and throttles its render + * cadence so the main thread yields time back to decode. No routing through C#, no constructor growth. + * + * HYSTERESIS (no flap): the signal engages only on SUSTAINED stress (≥ ENGAGE_EVENTS reports within + * ENGAGE_WINDOW_MS) and releases only after SUSTAINED recovery (no stress for RELEASE_QUIET_MS, and + * never before a MIN_ENGAGED_MS dwell). A lone startup-ramp blip never engages; once engaged the + * throttle cannot toggle off frame-to-frame. + * + * HEALTHY-CASE NO-OP: when decode keeps up nothing ever calls report(), so {@link isUnderPressure} + * stays false forever and the consumer runs at full quality. This protection only activates under + * genuine, sustained decode starvation. + */ + +/** Stress reports required within {@link ENGAGE_WINDOW_MS} to engage the throttle. */ +export const ENGAGE_EVENTS = 5; +/** Sliding window (ms) over which {@link ENGAGE_EVENTS} stress reports count toward engaging. */ +export const ENGAGE_WINDOW_MS = 2500; +/** Stress-free dwell (ms) required before the throttle releases. */ +export const RELEASE_QUIET_MS = 1500; +/** Minimum engaged dwell (ms) before release is even considered — the anti-flap floor. */ +export const MIN_ENGAGED_MS = 1000; + +type Clock = () => number; + +export class DecodePressureSignal { + // Timestamps of recent stress reports, pruned to the engage window. Length ≥ ENGAGE_EVENTS is the + // "sustained pressure" condition. Bounded by the window, so this never grows unbounded. + private stressTimestamps: number[] = []; + private lastStressMs = Number.NEGATIVE_INFINITY; + private engaged = false; + private engagedAtMs = 0; + + // Clock injectable purely for deterministic unit tests; production uses performance.now(). + constructor(private readonly now: Clock = () => performance.now()) {} + + /** + * Report one unit of decode stress — decode falling behind realtime. Called by the producer at + * each genuine lag event: the WebCodecs decode queue staying non-empty past its yield ceiling + * (OpusStreamDecoder) and the scheduler parking on a mid-stream underrun (PlaybackScheduler). + */ + report(): void { + const t = this.now(); + this.lastStressMs = t; + this.stressTimestamps.push(t); + this.prune(t); + } + + /** + * Whether decode is under sustained pressure right now. Pure read for the caller, but it ADVANCES + * the hysteresis latch (engage on sustained stress, release on sustained quiet past the min dwell) + * — so the transition is evaluated lazily on the clock, identical whether called once or per frame. + */ + isUnderPressure(): boolean { + const t = this.now(); + this.prune(t); + + if (this.engaged) { + const engagedFor = t - this.engagedAtMs; + const quietFor = t - this.lastStressMs; + if (engagedFor >= MIN_ENGAGED_MS && quietFor >= RELEASE_QUIET_MS) { + this.engaged = false; + } + } else if (this.stressTimestamps.length >= ENGAGE_EVENTS) { + this.engaged = true; + this.engagedAtMs = t; + } + return this.engaged; + } + + /** Drop stress timestamps older than the engage window so the count reflects only the live window. */ + private prune(t: number): void { + const cutoff = t - ENGAGE_WINDOW_MS; + while (this.stressTimestamps.length > 0 && this.stressTimestamps[0] < cutoff) { + this.stressTimestamps.shift(); + } + } +} + +/** The process-wide signal both the audio pipeline and the visualizer share. */ +export const decodePressure = new DecodePressureSignal(); diff --git a/DeepDrftPublic/Interop/visualizer/WaveformVisualizer.ts b/DeepDrftPublic/Interop/visualizer/WaveformVisualizer.ts index c8f978b..7877cdc 100644 --- a/DeepDrftPublic/Interop/visualizer/WaveformVisualizer.ts +++ b/DeepDrftPublic/Interop/visualizer/WaveformVisualizer.ts @@ -44,6 +44,8 @@ * position while !isPlaying). The loop stops only on tab-hidden (visibilitychange) and dispose. */ +import { decodePressure } from '../audio/decodePressure.js'; + // ── Tuning anchors (see spec §B). These are the load-bearing constants. ────────── /** @@ -148,6 +150,16 @@ const RIBBON_HALF_WIDTH_FRAC = 0.92; */ const MAX_DPR = 2; +/** + * Minimum milliseconds between drawn frames WHILE decode is under sustained pressure (Part 1 — + * auto-protect audio). 1000/15 ≈ 66.7 ms caps the loop at ~15 fps, cutting the main-thread WebGL + * software-render + physics cost by ~75% so the synchronous WebCodecs Opus decode (which shares the + * main thread when HW accel is off) gets the time it needs to keep up. The decodePressure signal is + * false in the common case (HW accel on, or lossless), so this cap never applies and the loop draws + * every frame at full quality. Tunable; the exact fps that clears starvation is browser-confirmed. + */ +const PRESSURE_THROTTLE_FRAME_MS = 1000 / 15; + // ════════════════════════════════════════════════════════════════════════════════════ // R2 — the wax-blob lava physics (CPU step + uniform upload). The lava is now a real // Lagrangian particle system integrated each frame on the JS side and rendered as @@ -1679,6 +1691,10 @@ export function create(canvas: HTMLCanvasElement): WaveformVisualizerHandle { let rafId: number | null = null; let disposed = false; const startTimeMs = performance.now(); + // Wall-clock of the last DRAWN continuous-loop frame, for the decode-pressure throttle (Part 1). + // While decodePressure.isUnderPressure() the loop draws at most once per PRESSURE_THROTTLE_FRAME_MS + // so the main thread yields time back to a starved decode; unthrottled it draws every frame. + let lastDrawMs = performance.now(); // Wall-clock anchor for the physics dt (separate from the playhead decay clock). let lastPhysicsMs = performance.now(); @@ -1923,9 +1939,30 @@ export function create(canvas: HTMLCanvasElement): WaveformVisualizerHandle { rafId = null; return; } + + // Auto-protect audio under decode pressure (Part 1). When the WebCodecs Opus decode pipeline + // reports SUSTAINED lag (decodePressure.isUnderPressure()), throttle the draw cadence to + // ~PRESSURE_THROTTLE_FRAME_MS so this loop's main-thread GL + physics cost yields time back to + // decode; we still reschedule every frame so full cadence resumes the instant decode recovers. + // A no-op when decode is healthy — isUnderPressure() stays false, the gate is always open, and + // every frame draws exactly as before. Skipping a draw also skips the physics step (it runs + // inside draw()), and its dt is clamped to PHYSICS_MAX_DT, so a throttled gap never lurches the + // lava. redrawOnce() (idle/control-tweak stills) is intentionally NOT throttled — those are rare + // one-shots, not the continuous loop. + const nowMs = performance.now(); + if (!decodePressure.isUnderPressure() || nowMs - lastDrawMs >= PRESSURE_THROTTLE_FRAME_MS) { + lastDrawMs = nowMs; + drawFrame(); + } + + rafId = requestAnimationFrame(frame); + } + + /** One drawn continuous-loop frame: the GL draw plus the gated FPS/lava diagnostic tally. */ + function drawFrame(): void { draw(); - // FPS tally: count this callback, and once per elapsed second emit the rate. + // FPS tally: count this drawn frame, and once per elapsed second emit the rate. // performance.now() is cheap (no GPU stall, unlike gl.getError); the gated log // fires at most once/sec, so this adds no meaningful per-frame cost. if (DEBUG) { @@ -1968,10 +2005,6 @@ export function create(canvas: HTMLCanvasElement): WaveformVisualizerHandle { fpsWindowStartMs = nowMs; } } - - // Reschedule unconditionally — the loop runs continuously now (lava reframe Part C); it is - // stopped only by dispose() or the tab going hidden, never by audio pausing. - rafId = requestAnimationFrame(frame); } // ── Tab-visibility gating (lava reframe Part C power-saving). ────────────────────