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.
2026-06-24 09:00:38 -04:00
parent c7629c15a4
commit 369cb86437
3 changed files with 99 additions and 2 deletions
@@ -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<byte>.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);
@@ -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;
@@ -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_;
    }