diff --git a/backend/player/buffered_streamer.go b/backend/player/buffered_streamer.go index 993286e..2408182 100644 --- a/backend/player/buffered_streamer.go +++ b/backend/player/buffered_streamer.go @@ -47,6 +47,39 @@ type BufferedStreamer struct { // seek bar and suppresses its interpolation. starved int starvedSince time.Time + + // underruns accumulates for the life of this streamer, where + // starved is reset by every arriving sample. + // + // The two answer different questions and only the first was being + // asked. starved is a *stall* detector: it exists to end a track + // whose source has died, so it forgets a run the moment audio + // resumes -- which is exactly the case this counts. A hundred 20ms + // underruns a minute never approach the give-up threshold and were + // invisible to the log, the UI and every test tier, while being + // audible as static: an underrun is served as a run of zeros + // spliced into the waveform, and a step discontinuity at each edge + // is what a click is. + underruns UnderrunStats +} + +// UnderrunStats is what the ring buffer missed, cumulatively. +// +// Samples rather than milliseconds because this type does not know the +// sample rate -- the player does, and converts at the point of +// reporting. +type UnderrunStats struct { + // Runs is the number of *episodes*: transitions from healthy into + // starved. Calls is how many Stream calls were served with + // silence, and Samples is how much silence that was. + // + // Runs is the count that means something audible. One episode is + // one pop however many calls it spans, and the ratio of the two is + // how long the average episode was -- which is what separates + // "clicking" from "dropping out". + Runs int64 + Calls int64 + Samples int64 } // The silence fill is bounded by both a duration and a run of calls, @@ -226,6 +259,13 @@ func (bs *BufferedStreamer) Stream( // but only for a bounded stretch, because "forever" is // reported upward as healthy playback and there is no watchdog // above this to notice otherwise. + if bs.starved == 0 { + bs.underruns.Runs++ + } + + bs.underruns.Calls++ + bs.underruns.Samples += int64(len(samples)) + bs.starved++ if bs.starvedSince.IsZero() { @@ -269,6 +309,20 @@ func (bs *BufferedStreamer) Stream( return n, true } +// Underruns returns the cumulative underrun count. +// +// It is a snapshot rather than a live view, and it is read from +// outside the audio callback: counting happens in Stream, under the +// lock it already takes, because that path has a real-time deadline +// and anything that allocates or formats on it is a cause of the +// defect it is measuring rather than a measurement of it. +func (bs *BufferedStreamer) Underruns() UnderrunStats { + bs.mu.Lock() + defer bs.mu.Unlock() + + return bs.underruns +} + // Err returns any error encountered by the source streamer. func (bs *BufferedStreamer) Err() error { bs.mu.Lock() @@ -298,6 +352,10 @@ func (bs *BufferedStreamer) Flush() { // resetStarvationLocked forgets an underrun run. Must be called with // bs.mu held. +// +// Deliberately does not touch bs.underruns: forgetting the run is what +// makes starved a stall detector, and remembering it is the whole +// point of the counter beside it. func (bs *BufferedStreamer) resetStarvationLocked() { bs.starved = 0 bs.starvedSince = time.Time{} diff --git a/backend/player/buffered_underrun_test.go b/backend/player/buffered_underrun_test.go new file mode 100644 index 0000000..ca26705 --- /dev/null +++ b/backend/player/buffered_underrun_test.go @@ -0,0 +1,279 @@ +package player + +import ( + "sync" + "testing" + "time" +) + +// An underrun is audible and nothing counted it (#135). +// +// The distinction these tests exist for is that `starved` and +// `underruns` disagree on purpose. `starved` is a stall detector: it is +// reset by every arriving sample, because its job is to end a track +// whose source has died and a source that is merely slow must not be +// cut short (TestUnderrunsDoNotAccumulateAcrossASlowSource, next +// door). That reset is exactly what made the audible case invisible -- +// a hundred short underruns a minute never approach the give-up +// threshold, and each one is a run of zeros spliced into the waveform +// with a step discontinuity at both edges. + +// TestAnEmptyRingIsCounted is the measurement itself: silence served +// for a missing sample is recorded rather than merely tolerated. +func TestAnEmptyRingIsCounted(t *testing.T) { + t.Parallel() + + // A source that never produces is the cleanest way to make the + // ring empty on demand; the stall budget is far longer than the + // handful of calls below. + bs := NewBufferedStreamer(stalledStreamer{}, 1024) + defer bs.Close() + + if got := bs.Underruns(); got != (UnderrunStats{}) { + t.Fatalf("a fresh streamer already reports %+v", got) + } + + buf := make([][2]float64, 256) + + for range 3 { + if _, ok := bs.Stream(buf); !ok { + t.Fatal("the stall budget ran out before the test did") + } + } + + got := bs.Underruns() + + if got.Calls != 3 { + t.Errorf("Calls = %d, want 3", got.Calls) + } + + if got.Samples != int64(3*len(buf)) { + t.Errorf("Samples = %d, want %d", got.Samples, 3*len(buf)) + } + + // Three consecutive silent calls are one episode, not three. That + // is the number that means something audible: one interruption is + // one pop however many callbacks it spans. + if got.Runs != 1 { + t.Errorf("Runs = %d, want 1 -- an unbroken run is one episode", got.Runs) + } +} + +// TestSilenceIsWhatIsCounted pins what an underrun actually does to the +// waveform, which is the reason to count it at all. +func TestSilenceIsWhatIsCounted(t *testing.T) { + t.Parallel() + + bs := NewBufferedStreamer(stalledStreamer{}, 1024) + defer bs.Close() + + buf := make([][2]float64, 64) + for i := range buf { + buf[i] = [2]float64{0.5, 0.5} + } + + n, ok := bs.Stream(buf) + if !ok || n != len(buf) { + t.Fatalf("Stream = (%d, %v), want (%d, true)", n, ok, len(buf)) + } + + for i := range buf { + if buf[i] != ([2]float64{}) { + t.Fatalf("sample %d is %v, want silence", i, buf[i]) + } + } + + if got := bs.Underruns().Samples; got != int64(len(buf)) { + t.Errorf("counted %d samples of silence, wrote %d", got, len(buf)) + } +} + +// TestSeparateEpisodesAreSeparateRuns is the counter's whole shape: +// audio arriving between two underruns makes them two, because that is +// two interruptions and two clicks. +func TestSeparateEpisodesAreSeparateRuns(t *testing.T) { + t.Parallel() + + // A source that yields nothing until it is fed, so the ring can be + // emptied, filled and emptied again on demand. + src := &gatedStreamer{} + + bs := NewBufferedStreamer(src, 1024) + defer bs.Close() + + buf := make([][2]float64, 128) + + starve := func() { + t.Helper() + + for range 2 { + if _, ok := bs.Stream(buf); !ok { + t.Fatal("the stall budget ran out before the test did") + } + } + } + + // feed lets exactly one bufferful through and drains it, so the + // ring is empty again on return. Allowing more would mean the + // starve() after it drained real audio instead of underrunning, + // which is what the first version of this test did -- it reported + // one episode and looked like the counter was wrong. + feed := func() { + t.Helper() + + src.allow(len(buf)) + + // The read-ahead is a goroutine, so wait for real samples + // rather than assuming they have landed. + deadline := time.Now().Add(2 * time.Second) + for time.Now().Before(deadline) { + n, ok := bs.Stream(buf) + if ok && n > 0 && buf[0] != ([2]float64{}) { + return + } + + time.Sleep(time.Millisecond) + } + + t.Fatal("the source never delivered a sample") + } + + starve() + feed() + starve() + + if got := bs.Underruns().Runs; got < 2 { + t.Errorf( + "Runs = %d, want at least 2 -- audio in between makes two "+ + "episodes, not one", + got, + ) + } +} + +// TestTheStallResetDoesNotClearTheCounter is the regression this file +// is really about. +// +// resetStarvationLocked runs on every arriving sample and on every +// Flush. If it cleared the cumulative count too, the counter would +// report zero on exactly the workload it exists to measure -- a stream +// that underruns repeatedly but always recovers -- which is +// indistinguishable from healthy playback and is what the code did +// before #135. +func TestTheStallResetDoesNotClearTheCounter(t *testing.T) { + t.Parallel() + + bs := NewBufferedStreamer(stalledStreamer{}, 1024) + defer bs.Close() + + buf := make([][2]float64, 128) + + if _, ok := bs.Stream(buf); !ok { + t.Fatal("the stall budget ran out before the test did") + } + + before := bs.Underruns() + if before.Runs == 0 { + t.Fatal("nothing was counted, so the reset cannot be tested") + } + + // Both of the ways a run is forgotten. + bs.mu.Lock() + bs.resetStarvationLocked() + bs.mu.Unlock() + + bs.Flush() + + if got := bs.Underruns(); got != before { + t.Errorf( + "forgetting the stall run also discarded the count: %+v, "+ + "want %+v", + got, before, + ) + } +} + +// TestUnderrunDeltaNeverGoesBackwards covers the one arithmetic trap in +// the reporting side. +// +// The counter belongs to the streamer and the streamer is replaced on +// every track, so a baseline carried across a track change is the +// previous track's total subtracted from a fresh zero. The load path +// resets the baseline, and this clamps as well -- a negative count in a +// log line reads as a broken instrument, which would discredit the +// measurement rather than merely mis-state it. +func TestUnderrunDeltaNeverGoesBackwards(t *testing.T) { + t.Parallel() + + tests := []struct { + name string + now UnderrunStats + last UnderrunStats + want UnderrunStats + }{ + { + name: "ordinary progress", + now: UnderrunStats{Runs: 5, Calls: 40, Samples: 4000}, + last: UnderrunStats{Runs: 2, Calls: 10, Samples: 1000}, + want: UnderrunStats{Runs: 3, Calls: 30, Samples: 3000}, + }, + { + name: "nothing happened", + now: UnderrunStats{Runs: 5, Calls: 40, Samples: 4000}, + last: UnderrunStats{Runs: 5, Calls: 40, Samples: 4000}, + want: UnderrunStats{}, + }, + { + name: "a new streamer, with a stale baseline", + now: UnderrunStats{}, + last: UnderrunStats{Runs: 9, Calls: 90, Samples: 9000}, + want: UnderrunStats{}, + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + t.Parallel() + + if got := underrunDelta(tt.now, tt.last); got != tt.want { + t.Errorf("underrunDelta = %+v, want %+v", got, tt.want) + } + }) + } +} + +// gatedStreamer produces only what it has been allowed to, and +// otherwise stalls without ending -- so a test can decide exactly when +// the ring runs dry. +type gatedStreamer struct { + mu sync.Mutex + remaining int +} + +func (g *gatedStreamer) allow(n int) { + g.mu.Lock() + defer g.mu.Unlock() + + g.remaining += n +} + +func (g *gatedStreamer) Stream(samples [][2]float64) (int, bool) { + g.mu.Lock() + defer g.mu.Unlock() + + if g.remaining <= 0 { + return 0, true + } + + n := min(len(samples), g.remaining) + + for i := range n { + samples[i] = [2]float64{0.25, 0.25} + } + + g.remaining -= n + + return n, true +} + +func (g *gatedStreamer) Err() error { return nil } diff --git a/backend/player/player.go b/backend/player/player.go index 1779438..2bc952d 100644 --- a/backend/player/player.go +++ b/backend/player/player.go @@ -39,16 +39,21 @@ type Player struct { // via the queue). mu sync.Mutex - ctx context.Context - logger *slog.Logger - db *database.DB - state State - currentFile *os.File - format beep.Format - baseStreamer beep.Streamer - seeker beep.StreamSeeker - resampled beep.Streamer - buffered *BufferedStreamer + ctx context.Context + logger *slog.Logger + db *database.DB + state State + currentFile *os.File + format beep.Format + baseStreamer beep.Streamer + seeker beep.StreamSeeker + resampled beep.Streamer + buffered *BufferedStreamer + + // lastUnderruns is the previous report, so the 1 Hz log can say + // what happened in the last second and stay quiet when nothing did. + // It is reset with the streamer, in loadFileLocked. + lastUnderruns UnderrunStats control *beep.Ctrl volume *effects.Volume speakerStreamer beep.Streamer @@ -292,9 +297,78 @@ func (p *Player) emitPositionIfPlaying() { return } + p.reportUnderrunsLocked() p.emitPositionLocked() } +// underrunDelta is what happened since the last report. +// +// It clamps at zero rather than subtracting blind, because the counter +// belongs to the *streamer* and the streamer is replaced on every +// track: a baseline carried across that boundary is the previous +// track's total subtracted from a fresh zero, which is negative. That +// is repaired at the load (lastUnderruns is reset with the streamer) +// and clamped here as well, because a negative count in a log line +// reads as a broken instrument and would discredit the measurement +// this exists to make. +func underrunDelta(now, last UnderrunStats) UnderrunStats { + return UnderrunStats{ + Runs: max(0, now.Runs-last.Runs), + Calls: max(0, now.Calls-last.Calls), + Samples: max(0, now.Samples-last.Samples), + } +} + +// reportUnderrunsLocked logs what the ring buffer missed, at most once +// a second and only when the number moved. Must be called with p.mu +// held. +// +// **An underrun is audible and nothing counted it** (#135). The ring +// serves silence when it is empty, so a run of zeros is spliced into +// the waveform and the step discontinuity at each edge is a click; a +// series of short ones is static. Everything that makes one likelier +// is worse on a phone than on a desktop -- slower storage, a governor +// that parks cores, background work, GC -- and no tier here can see it, +// since CI's audio device is a null sink chosen because it keeps time. +// +// Three things about the reporting are deliberate. +// +// **It is on the 1 Hz position ticker rather than in Stream.** Stream +// runs on the speaker callback's real-time deadline, and a log line +// there would allocate, format and write on the exact path whose +// missed deadline is the defect -- measuring by making it worse. +// +// **An unchanged count is not logged.** That is emitStatus' rule one +// package over: a healthy player is silent, so anything in the log is +// news, and the line appears exactly while it is popping. Reading it +// off a device means `make android-logs` with the audio audible. +// +// **It is Info rather than Debug**, because the default level is Info +// and a phone has no convenient way to set YJ_LOG_LEVEL -- a debug +// line here would be a counter nobody on the affected platform can +// read, which is the shape of the bug that made #160 necessary. +func (p *Player) reportUnderrunsLocked() { + if p.buffered == nil { + return + } + + stats := p.buffered.Underruns() + if stats == p.lastUnderruns { + return + } + + since := underrunDelta(stats, p.lastUnderruns) + p.lastUnderruns = stats + + slog.Info("audio underrun", + "runs", since.Runs, + "calls", since.Calls, + "silenceMs", speakerSampleRate.D(int(since.Samples)).Milliseconds(), + "trackRuns", stats.Runs, + "trackSilenceMs", speakerSampleRate.D(int(stats.Samples)).Milliseconds(), + ) +} + // emitPositionLocked pushes the current position to the frontend. // Must be called with p.mu held. func (p *Player) emitPositionLocked() { @@ -484,6 +558,12 @@ func (p *Player) updateStreamers( p.resampled, int(speakerSampleRate)*2, ) + // The counter belongs to the streamer, so the baseline it is + // reported against has to go with it -- otherwise the first report + // of a new track is the previous track's total subtracted from + // zero, which is negative and looks like the instrument is broken. + p.lastUnderruns = UnderrunStats{} + // wrap in ctrl streamer to allow play/pause p.control = &beep.Ctrl{Streamer: p.buffered}