From 369cb86437046f64c743603f4492ef236d6815fd Mon Sep 17 00:00:00 2001 From: daniel-c-harvey Date: Wed, 24 Jun 2026 09:00:38 -0400 Subject: [PATCH] Add [BP-DIAG] back-pressure instrumentation for Phase 21.4 browser run Temporary, grep-tagged diagnostics at the read-loop pause, the scheduler latch, and the chunk-result path to show whether ProductionPaused latches, reaches C#, and parks the loop. Strip once the cause is confirmed. --- .../Services/StreamingAudioPlayerService.cs | 47 +++++++++++++++++++ DeepDrftPublic/Interop/audio/AudioPlayer.ts | 30 +++++++++++- .../Interop/audio/PlaybackScheduler.ts | 24 ++++++++++ 3 files changed, 99 insertions(+), 2 deletions(-) diff --git a/DeepDrftPublic.Client/Services/StreamingAudioPlayerService.cs b/DeepDrftPublic.Client/Services/StreamingAudioPlayerService.cs index d3b6439..3996dd0 100644 --- a/DeepDrftPublic.Client/Services/StreamingAudioPlayerService.cs +++ b/DeepDrftPublic.Client/Services/StreamingAudioPlayerService.cs @@ -35,6 +35,14 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS public int BufferedChunks { get; private set; } = 0; public bool IsSeekingBeyondBuffer { get; private set; } = false; + // ─────────────────────────────────────────────────────────────────────────────────────────── + // [BP-DIAG] Phase 21.4 back-pressure diagnostic. TEMPORARY — strip once the cause is confirmed + // in Daniel's browser run. Logs every Nth chunk's ProductionPaused flag plus pause-poll + // enter/exit so a grep for "[BP-DIAG]" in the WASM console tells whether the read loop ever sees + // the pause signal and whether the poll actually holds. Throttled by chunk count to avoid flooding. + private const int BpDiagChunkLogEvery = 16; + // ─────────────────────────────────────────────────────────────────────────────────────────── + private bool _streamingPlaybackStarted = false; private CancellationTokenSource? _streamingCancellation; private Task? _activeStreamingTask; @@ -386,6 +394,7 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS buffer = ArrayPool.Shared.Rent(MaxBufferSize); // Rent larger buffer to accommodate adaptive sizing int currentBytes; var readTimer = System.Diagnostics.Stopwatch.StartNew(); + var bpDiagChunkIndex = 0; // [BP-DIAG] per-stream chunk counter for throttled logging do { @@ -420,6 +429,20 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS HeaderParsed = chunkResult.HeaderParsed; BufferedChunks = chunkResult.BufferCount; + // [BP-DIAG] Phase 21.4 — throttled per-chunk view of the back-pressure signal as + // the C# loop sees it. If ProductionPaused never logs True while bytes keep + // flowing, the break is upstream (JS latch / lookahead math); if it logs True but + // the transfer still races to 100%, the break is the transport (browser buffered + // the whole body, SetBrowserResponseStreamingEnabled not in effect). TEMPORARY. + if (bpDiagChunkIndex % BpDiagChunkLogEvery == 0) + { + _logger.LogInformation( + "[BP-DIAG] chunk #{Chunk} bytesRead={Bytes} totalRead={Total} bufferCount={BufCount} canStart={CanStart} productionPaused={Paused} isPaused={IsPaused}", + bpDiagChunkIndex, currentBytes, totalBytesRead, chunkResult.BufferCount, + chunkResult.CanStartStreaming, chunkResult.ProductionPaused, IsPaused); + } + bpDiagChunkIndex++; + // Set duration from WAV header when available (only set once) if (chunkResult.Duration.HasValue && Duration == null) { @@ -487,6 +510,15 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS // no separate cancellation path, no stale read racing a reinit. if (chunkResult.ProductionPaused) { + // [BP-DIAG] Phase 21.4 — the read loop is ENTERING the pause-poll: reads have + // stopped, the socket should now stall and the transfer should plateau. If you + // see this line but the network transfer still completes, the transport is + // buffered (streaming flag not in effect). TEMPORARY. + _logger.LogInformation( + "[BP-DIAG] ENTER pause-poll at chunk #{Chunk} totalRead={Total} isPaused={IsPaused}", + bpDiagChunkIndex, totalBytesRead, IsPaused); + var bpDiagPollCount = 0; + // UC5: while the user is paused, the playhead is frozen so forward lookahead // never shrinks and the poll would spin indefinitely. Wait here until playback // resumes (IsPaused clears) OR the fill drains on its own. Cancellation is @@ -495,8 +527,23 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS while (IsPaused || await _audioInterop.IsProductionPaused(PlayerId)) { cancellationToken.ThrowIfCancellationRequested(); + // [BP-DIAG] Phase 21.4 — heartbeat every ~1 s (10 × 100 ms) so a held poll + // is visible without flooding; shows the loop is genuinely parked. TEMPORARY. + if (bpDiagPollCount % 10 == 0) + { + _logger.LogInformation( + "[BP-DIAG] HOLD pause-poll iter={Iter} isPaused={IsPaused}", + bpDiagPollCount, IsPaused); + } + bpDiagPollCount++; await Task.Delay(BackpressurePollMs, cancellationToken); } + + // [BP-DIAG] Phase 21.4 — the read loop is EXITING the pause-poll and resuming + // ReadAsync: the fill drained below low-water. TEMPORARY. + _logger.LogInformation( + "[BP-DIAG] EXIT pause-poll at chunk #{Chunk} after {Iters} polls", + bpDiagChunkIndex, bpDiagPollCount); } } } while (currentBytes > 0); diff --git a/DeepDrftPublic/Interop/audio/AudioPlayer.ts b/DeepDrftPublic/Interop/audio/AudioPlayer.ts index d33572f..6577294 100644 --- a/DeepDrftPublic/Interop/audio/AudioPlayer.ts +++ b/DeepDrftPublic/Interop/audio/AudioPlayer.ts @@ -269,13 +269,19 @@ export class AudioPlayer { const headerParsed = decoder.ready; const canStart = headerParsed && this.scheduler.hasMinimumBuffers(this.minBuffersForPlayback); + // [BP-DIAG] Phase 21.4 — value of productionPaused actually placed on the Opus chunk + // result handed to C#. Confirms the flag is populated on THIS path (not just the WAV + // path). TEMPORARY — strip once confirmed. + const opusPaused = this.scheduler.evaluateProductionPause(); + this.bpDiagLogChunkResult('opus', canStart, opusPaused); + return { success: true, canStartStreaming: canStart, headerParsed, bufferCount: this.scheduler.getBufferCount(), duration: this.duration, - productionPaused: this.scheduler.evaluateProductionPause() + productionPaused: opusPaused }; } catch (error) { return { success: false, error: (error as Error).message }; @@ -314,13 +320,18 @@ export class AudioPlayer { const canStart = this.streamDecoder.headerParsed && this.scheduler.hasMinimumBuffers(this.minBuffersForPlayback); + // [BP-DIAG] Phase 21.4 — value of productionPaused actually placed on the WAV/MP3/FLAC + // chunk result handed to C#. TEMPORARY — strip once confirmed. + const formatPaused = this.scheduler.evaluateProductionPause(); + this.bpDiagLogChunkResult('format', canStart, formatPaused); + return { success: true, canStartStreaming: canStart, headerParsed: this.streamDecoder.headerParsed, bufferCount: this.scheduler.getBufferCount(), duration: this.duration, - productionPaused: this.scheduler.evaluateProductionPause() + productionPaused: formatPaused }; } catch (error) { return { success: false, error: (error as Error).message }; @@ -731,6 +742,21 @@ export class AudioPlayer { // ==================== Private Methods ==================== + // ───────────────────────────────────────────────────────────────────────────────────────── + // [BP-DIAG] Phase 21.4 back-pressure diagnostic. TEMPORARY — strip once confirmed in Daniel's + // browser run. Logs the productionPaused flag on the chunk result handed back to C#, throttled + // to ~4 Hz so it does not flood. Grep "[BP-DIAG] chunk-result" in the browser console. + private bpDiagChunkResultLastMs = 0; + private bpDiagLogChunkResult(path: 'opus' | 'format', canStart: boolean, paused: boolean): void { + const now = (typeof performance !== 'undefined' ? performance.now() : Date.now()); + if (now - this.bpDiagChunkResultLastMs < 250) return; + this.bpDiagChunkResultLastMs = now; + console.log( + `[BP-DIAG] chunk-result path=${path} productionPaused=${paused} canStart=${canStart} ` + + `bufCount=${this.scheduler.getBufferCount()} streamingStarted=${this.streamingStarted} isPlaying=${this.isPlaying}`); + } + // ───────────────────────────────────────────────────────────────────────────────────────── + private resetState(): void { this.isPlaying = false; this.isPaused = false; diff --git a/DeepDrftPublic/Interop/audio/PlaybackScheduler.ts b/DeepDrftPublic/Interop/audio/PlaybackScheduler.ts index 5379130..341e0e3 100644 --- a/DeepDrftPublic/Interop/audio/PlaybackScheduler.ts +++ b/DeepDrftPublic/Interop/audio/PlaybackScheduler.ts @@ -107,6 +107,14 @@ export class PlaybackScheduler { // Mutated by evaluateProductionPause() — named to signal the state-advance on each call. private productionPaused_: boolean = false; + // ───────────────────────────────────────────────────────────────────────────────────────── + // [BP-DIAG] Phase 21.4 back-pressure diagnostic. TEMPORARY — strip once the cause is confirmed + // in Daniel's browser run. Throttles evaluateProductionPause() logging to one line per ~250 ms + // so the console shows the live lookahead / byte-estimate / latch without flooding (the signal + // is evaluated on every chunk + every poll). Grep "[BP-DIAG]" in the browser console. + private bpDiagLastLogMs: number = 0; + // ───────────────────────────────────────────────────────────────────────────────────────── + // Callbacks public onPlaybackEnded: (() => void) | null = null; @@ -237,6 +245,22 @@ export class PlaybackScheduler { this.productionPaused_ = true; } + // [BP-DIAG] Phase 21.4 — the single source of truth for the latch decision. If `paused` + // never goes true while bytes keep arriving, the lookahead is not growing as expected: + // inspect `lookahead` vs `high` (should cross 30 during a fast fill) and `bufCount`/`bytes` + // (decode must actually be populating the scheduler). Throttled to ~4 Hz. TEMPORARY — strip + // once the cause is confirmed. (Uses performance.now when present; Date.now fallback.) + const bpNow = (typeof performance !== 'undefined' ? performance.now() : Date.now()); + if (bpNow - this.bpDiagLastLogMs >= 250) { + this.bpDiagLastLogMs = bpNow; + console.log( + `[BP-DIAG] evaluateProductionPause paused=${this.productionPaused_} ` + + `lookahead=${lookahead.toFixed(2)}s high=${this.forwardHighWaterSeconds} low=${this.forwardLowWaterSeconds} ` + + `bytes=${(this.getDecodedByteEstimate() / (1024 * 1024)).toFixed(1)}MB cap=${(this.maxDecodedBytes / (1024 * 1024)).toFixed(0)}MB ` + + `overByteCeiling=${overByteCeiling} bufCount=${this.buffers.length} pos=${this.getCurrentPosition().toFixed(2)}s ` + + `decodedEnd=${(this.getTotalDuration() + this.playbackOffset).toFixed(2)}s active=${this.isActive_}`); + } + return this.productionPaused_; }