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{}

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 }

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}