daniel/deepdrft
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases 13 Wiki Activity

Auto-throttle visualizer under sustained Opus decode pressure; strip streaming investigation instrumentation

Browse Source
This commit is contained in:
daniel-c-harvey
2026-06-26 06:00:05 -04:00
parent 76f7f389a3
commit 374f09150f
7 changed files with 313 additions and 159 deletions
Download Patch File Download Diff File Expand all files Collapse all files
DeepDrftPublic.Client/Services/AudioPlayerService.cs
-19
View File
@@ -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
/// </summary>
protected virtual void OnPlaybackEnded() { }
/// <summary>
/// [RELOAD-DIAG] Diagnostic seam — invoked at each base-class site that nulls <see cref="Duration"/>
/// (<see cref="Unload"/> and <see cref="OnPlaybackEndCallback"/>), 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.
/// </summary>
protected virtual void OnDurationNulledDiag(string caller) { }
protected async Task EnsureInitializedAsync()
{
if (!IsInitialized)
DeepDrftPublic.Client/Services/StreamingAudioPlayerService.cs
+5 -91
View File
@@ -64,14 +64,6 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS
private readonly ILogger<StreamingAudioPlayerService> _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();
}
/// <summary>
@@ -954,7 +904,7 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS
/// </summary>
public override async Task Unload()
{
await ResetToIdle("unload");
await ResetToIdle();
}
/// <summary>
@@ -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
/// </summary>
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
/// </summary>
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.
/// </summary>
/// <param name="caller">[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.</param>
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
/// </summary>
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
{