From fb0d37e3c87eefe73364f2fecdf551cf4322817d Mon Sep 17 00:00:00 2001 From: grom Date: Sun, 1 Nov 2026 12:59:18 -0700 Subject: [PATCH] sound: a stream whose callback stopped is rebuilt, whatever the device layer said MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit cpal's ALSA loop exits on a `POLLERR` out of `alsa::poll()`, which reaches us as a `BackendSpecific` error — classified non-fatal there, because an xrun must not tear the stream down. So `device_died` was never set, nothing rebuilt, the ring filled, the render thread parked on a full ring and kira's renderer stopped advancing every sound in the mix. In grom's 2026-10-18 log that was four minutes of silence out of one `soggyplace-zone5.mp3`, cleared only by a worldport replacing the slot; the `3D sound(s) never played — the spatial-voice arena was full` count climbing to 267 in the same session is the proof that nothing at all was completing, music included. `StallWatch` reads the cycle count instead of the error string: a running stream that reports no cycle for 2 s is dead however it died, including with nothing raised at all, and `service` closes and reopens it exactly as it does a lost device. Reclassifying the error could not have worked — an xrun arrives in the same variant and the string is all we get. A window with no cycles is not a wall clock with no cycles. `service` runs once a frame on the main thread and a 4 s load hitch is one window the callback ran right through, so the span is taken between two `Instant`s and any window that saw a cycle resets it, however long that window was. That is the same trap as `510dda3d3`, one layer down. Measured while verifying it, and the reason for the other two pieces here: the rebuild held the main thread 4.5 s with the audio server down. Attributed with `WOW_SYSTEM_TIMING=1 WOW_STALL_MS=400` to `sound::poll_mix_health`, then split — close 5 ms, finding the default 2 ms, `Stream::open` 4521 ms. Opening a device is a blocking call into the host's audio stack. `SLOW_OPEN` now says so in the log, and the reopen wait backs off to 8 s while opens are slow or refused, so an outage costs one blocked frame per attempt instead of one a second. It did not happen in grom's own failure, where the server stayed up and the reopen would be instant. Taking the open off the main thread needs a device thread owning every open and close; not done here. Verified: four offline tests — a stream calling back at 3 ms frames, the 4.1 s login hitch arriving as one window of 380 cycles, a real stop named once on the limit, and the backoff's escalation — plus two live runs on Linux/PipeWire, restarting pipewire under a running client at the glue screen. Both read the same: position frozen, two genuine starve warns, `output stream dropped — the stream stopped calling back; reopening`, a reopen in the same frame, music advancing again. Before this, that was permanent. Built and run on Linux only; the device layer's own files are untouched apart from the comment that pointed the wrong way. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01SgstFWtn1RxEJ5kVrpgYwn --- crates/benilla-app/src/sound/output/cpal.rs | 11 +- crates/benilla-app/src/sound/output/mod.rs | 215 +++++++++++++++++++- 2 files changed, 218 insertions(+), 8 deletions(-) diff --git a/crates/benilla-app/src/sound/output/cpal.rs b/crates/benilla-app/src/sound/output/cpal.rs index 2b17985b..3a839d71 100644 --- a/crates/benilla-app/src/sound/output/cpal.rs +++ b/crates/benilla-app/src/sound/output/cpal.rs @@ -296,7 +296,11 @@ impl Stream { let errors = Arc::clone(notices); // Only `DeviceNotAvailable` and `StreamInvalidated` are fatal, as kira draws it; an ALSA - // xrun (`BufferUnderrun`) or `BackendSpecific` must not tear the stream down. + // xrun (`BufferUnderrun`) must not tear the stream down. `BackendSpecific` is not read + // either way: a `POLLERR` out of `alsa::poll()` arrives in it and does end cpal's ALSA + // loop, while an xrun arrives in it too and does not, and the string is all we get. What + // happened to the callback is the thing that matters, so `super::StallWatch` reads that + // instead and rebuilds a stream that went quiet, whatever was raised. let reported = std::sync::atomic::AtomicBool::new(false); let on_error = move |e: cpal::StreamError| { match e { @@ -307,7 +311,10 @@ impl Stream { // already counted as an underrun. _ => { if !reported.swap(true, Ordering::Relaxed) { - bevy::log::warn!("audio: output stream reported {e} (stream kept)"); + bevy::log::warn!( + "audio: output stream reported {e} — keeping the stream; the stall \ + watchdog rebuilds it if the callback stopped" + ); } return; } diff --git a/crates/benilla-app/src/sound/output/mod.rs b/crates/benilla-app/src/sound/output/mod.rs index a218cb32..53d97988 100644 --- a/crates/benilla-app/src/sound/output/mod.rs +++ b/crates/benilla-app/src/sound/output/mod.rs @@ -25,8 +25,10 @@ //! - overloads: `kAudioDeviceProcessorOverload`, macOS only; zero elsewhere. //! //! Default-output changes, device loss and rate changes raise a notice, and `service` rebuilds -//! the stream on the new default. The callback and the render loop are allocation-free, checked -//! in debug builds by `assert_no_alloc`. +//! the stream on the new default. A stream whose callback stops without any of that — the device +//! layer cannot always tell — is caught by its cycle count going quiet ([`StallWatch`]) and +//! rebuilt the same way. The callback and the render loop are allocation-free, checked in debug +//! builds by `assert_no_alloc`. // The device layer, one file per platform behind one name. #[cfg(target_os = "macos")] @@ -56,6 +58,35 @@ const RENDER_CHUNK_FRAMES: usize = 256; /// How long an unopenable device waits before the next attempt. const REOPEN_EVERY: Duration = Duration::from_secs(1); +/// The ceiling that wait backs off to while opens are slow or refused ([`next_reopen_wait`]). +const REOPEN_MAX: Duration = Duration::from_secs(8); + +/// The wait before the next open attempt: back off while the device is not answering, snap back as +/// soon as one open is quick. An open blocks the main thread for as long as the host's audio stack +/// takes (see [`SLOW_OPEN`]), so retrying once a second through an audio-server outage would freeze +/// the game over and over; the game instead runs silent and costs one blocked frame per attempt. +fn next_reopen_wait(current: Duration, slow: bool) -> Duration { + if slow { + (current * 2).min(REOPEN_MAX) + } else { + REOPEN_EVERY + } +} + +/// How long [`Stream::open`] may block the main thread before it is logged. Opening a device is a +/// blocking call into the host's audio stack and can take seconds: measured at **4521 ms** with the +/// audio server (PipeWire) restarting under a running client, against 5 ms to close the old stream +/// and 2 ms to find the default device — so the whole of such a freeze is this one call. Moving it +/// off the main thread means a device thread that owns every open and close, since `Stream` must be +/// created and dropped on one thread on some hosts; until then the log says when it happened. +const SLOW_OPEN: Duration = Duration::from_millis(100); + +/// How long a running stream may hand the callback no cycle at all before [`StallWatch`] calls it +/// dead. The device wakes every [`DEVICE_BUFFER_FRAMES`] (~11 ms at 48 kHz) and the ring holds +/// only [`MIX_AHEAD_MS`], so a stream this quiet has been silent at the speaker for most of it; +/// the margin is for a host that wakes us late, not for us. +const STALL_LIMIT: Duration = Duration::from_secs(2); + /// How long the main thread waits for the IO closure to hand the ring consumer back after a /// stream drops; the stop is synchronous, so this is a defence. const HANDBACK_WAIT: Duration = Duration::from_millis(250); @@ -250,6 +281,50 @@ impl Drop for Returning { } } +/// Watches a running stream for the one failure the device layer cannot report: the callback +/// simply stops. cpal's ALSA loop exits on a `POLLERR` out of `alsa::poll()`, which reaches us as +/// a `BackendSpecific` error — classified non-fatal there because an xrun must not tear the stream +/// down (`cpal.rs`'s `on_error`). So `device_died` is never set, nothing rebuilds, the ring fills, +/// the render thread parks, and every sound in the mix stops advancing: one logged session lost +/// four minutes of music that way, cleared only by a worldport replacing the slot. +/// +/// The trigger is therefore the cycle count and not an error string, which also catches a stream +/// that dies raising nothing at all. +/// +/// **A window with no cycles is not a wall clock with no cycles.** [`OutputBackend::service`] runs +/// on the main thread, once a frame, and frames are neither evenly spaced nor promised: a 4 s load +/// hitch is one window, and the callback ran right through it. Only the span between two +/// [`Instant`]s counts, and any window that saw a cycle resets it, however long that window was. +#[derive(Default)] +struct StallWatch { + /// When a cycle was last seen, on the clock the span is measured against; `None` with no + /// stream running. + seen: Option, +} + +impl StallWatch { + /// Fold in one `service` window: `true` the once, when the stream is to be called dead. + fn observe(&mut self, running: bool, cycles: u64, now: Instant) -> bool { + if !running { + // Between a teardown and the next open there is nothing to starve. + self.seen = None; + return false; + } + let seen = *self.seen.get_or_insert(now); + if cycles > 0 { + self.seen = Some(now); + return false; + } + if now.duration_since(seen) < STALL_LIMIT { + return false; + } + // Disarmed rather than latched: the caller tears this stream down, and the next one is + // judged from its own first window. + self.seen = None; + true + } +} + enum Stage { /// `setup` ran; `start` has not. Set(Device), @@ -271,6 +346,10 @@ pub(super) struct OutputBackend { settings: OutputSettings, shared: Arc, stage: Stage, + /// Rebuilds a stream whose callback stopped, whatever the device layer made of it. + stall: StallWatch, + /// How long to wait before the next open attempt ([`next_reopen_wait`]). + reopen_wait: Duration, sample_rate: u32, buffer_frames: u32, render: Option>, @@ -295,6 +374,8 @@ impl Backend for OutputBackend { settings, shared, stage: Stage::Set(device), + stall: StallWatch::default(), + reopen_wait: REOPEN_EVERY, sample_rate, buffer_frames: settings.device_buffer_frames, render: None, @@ -360,6 +441,9 @@ impl OutputBackend { /// drain the window's meters. pub(super) fn service(&mut self) -> (Window, Vec) { let mut events = std::mem::take(&mut self.pending); + // Drained first: the window belongs to the stream that just ran, which this call may + // close, and the watchdog is read off its cycle count. + let window = self.take_window(); let notices = &self.shared.notices; let lost = if notices.device_died.swap(false, Ordering::AcqRel) { Some("the output device went away") @@ -370,6 +454,12 @@ impl OutputBackend { } else { None }; + let running = matches!(self.stage, Stage::Running { .. }); + let lost = lost.or_else(|| { + self.stall + .observe(running, window.cycles, Instant::now()) + .then_some("the stream stopped calling back") + }); if let Some(why) = lost { if matches!(self.stage, Stage::Running { .. }) { self.stream_errors += 1; @@ -381,7 +471,7 @@ impl OutputBackend { } } if let Stage::Idle { since, .. } = &self.stage { - if since.elapsed() >= REOPEN_EVERY { + if since.elapsed() >= self.reopen_wait { match device::default_output() { Ok(device) => { if let Some(event) = self.open(device) { @@ -392,13 +482,14 @@ impl OutputBackend { if let Stage::Idle { since, .. } = &mut self.stage { *since = Instant::now(); } + self.reopen_wait = next_reopen_wait(self.reopen_wait, true); self.stream_errors += 1; events.push(Event::OpenFailed(format!("{e:#}"))); } } } } - (self.take_window(), events) + (window, events) } /// Open a stream on `device` with the ring consumer held in `Stage::Idle`; on failure the @@ -425,12 +516,25 @@ impl OutputBackend { let on_cycle = move |cycle: Cycle<'_>| { io_cycle(cycle, returning.get_mut(), &shared, &mut last_output_ns); }; - match Stream::open( + let at = Instant::now(); + let opened = Stream::open( &device, self.settings.device_buffer_frames, &self.shared.notices, on_cycle, - ) { + ); + let took = at.elapsed(); + // A device that is slow or refusing is not asked again at the normal cadence, since the + // asking is what blocks. + self.reopen_wait = next_reopen_wait(self.reopen_wait, took >= SLOW_OPEN || opened.is_err()); + if took >= SLOW_OPEN { + warn!( + "audio: opening a stream on {} held the main thread {} ms", + device.name, + took.as_millis() + ); + } + match opened { Ok(stream) => { self.buffer_frames = stream.buffer_frames(); // The render thread joins the new device's workgroup on its next pass. @@ -493,6 +597,8 @@ impl OutputBackend { drop(_listeners); drop(stream); let consumer = take_back(handback).context("the IO closure never returned the ring")?; + // Due at once while opens are quick, so a rebuild lands in this same `service` call; once + // [`Self::reopen_wait`] has backed off it waits, which is the point of the backoff. self.stage = Stage::Idle { consumer, since: Instant::now() - REOPEN_EVERY, @@ -742,6 +848,103 @@ fn render_loop( mod tests { use super::*; + /// A stream whose callback is running is never called dead, however the windows land. At any + /// frame rate above the device's wake rate most windows carry no cycle at all, and the IO + /// buffer is ~11 ms against frames that can be 3. + #[test] + fn stall_watch_keeps_a_stream_that_calls_back() { + let mut watch = StallWatch::default(); + let t0 = Instant::now(); + for frame in 0..600u32 { + let now = t0 + Duration::from_millis(u64::from(frame) * 3); + // One cycle every fourth frame: 12 ms apart, one device buffer. + let cycles = u64::from(frame % 4 == 0); + assert!( + !watch.observe(true, cycles, now), + "a live stream was called dead at frame {frame}" + ); + } + } + + /// The hitch case, and the reason the span is clocked rather than counted in windows: the + /// main thread blocks for seconds, so one window carries every cycle of it. The callback never + /// missed a wake, and nothing may be rebuilt. + #[test] + fn stall_watch_does_not_charge_a_main_thread_hitch() { + let mut watch = StallWatch::default(); + let t0 = Instant::now(); + for frame in 0..60u64 { + assert!(!watch.observe(true, 1, t0 + Duration::from_millis(frame * 16))); + } + // benilla's own login hitch: 4.1 s in one frame, ~380 device cycles inside it. + let after = t0 + Duration::from_millis(60 * 16) + Duration::from_millis(4100); + assert!( + !watch.observe(true, 380, after), + "a 4.1 s load hitch read as a dead stream" + ); + assert!(!watch.observe(true, 1, after + Duration::from_millis(16))); + } + + /// The reopen backoff: the asking is what blocks the main thread, so a device that is not + /// answering is asked less and less often, and one quick open puts it back to the base rate. + #[test] + fn the_reopen_wait_backs_off_while_opens_are_slow_and_snaps_back() { + let mut wait = REOPEN_EVERY; + let mut seen = Vec::new(); + for _ in 0..5 { + wait = next_reopen_wait(wait, true); + seen.push(wait); + } + assert_eq!( + seen, + vec![ + Duration::from_secs(2), + Duration::from_secs(4), + REOPEN_MAX, + REOPEN_MAX, + REOPEN_MAX, + ], + "the wait doubles to the ceiling and stays there" + ); + assert_eq!( + next_reopen_wait(wait, false), + REOPEN_EVERY, + "one quick open is enough to come back" + ); + } + + /// A running stream that stops calling back is named once [`STALL_LIMIT`] has passed, and + /// named once: the caller closes the stream, and the next one is judged from its own window. + #[test] + fn stall_watch_names_a_stream_that_stopped() { + let mut watch = StallWatch::default(); + let t0 = Instant::now(); + assert!(!watch.observe(true, 7, t0)); + let mut fired_at = None; + for tick in 1..40u64 { + let now = t0 + Duration::from_millis(tick * 100); + if watch.observe(true, 0, now) { + fired_at = Some(now.duration_since(t0)); + break; + } + } + let fired_at = fired_at.expect("a stream with no cycles at all was never called dead"); + assert!( + fired_at >= STALL_LIMIT && fired_at < STALL_LIMIT + Duration::from_millis(100), + "named {fired_at:?} in, not on the limit" + ); + // The teardown, then the reopen: silence while no stream runs is not a stall, and the + // fresh stream gets the whole limit again. + let closed = t0 + fired_at; + for tick in 0..40u64 { + assert!(!watch.observe(false, 0, closed + Duration::from_millis(tick * 100))); + } + let reopened = closed + Duration::from_millis(4000); + assert!(!watch.observe(true, 0, reopened)); + assert!(!watch.observe(true, 0, reopened + STALL_LIMIT / 2)); + assert!(watch.observe(true, 0, reopened + STALL_LIMIT)); + } + /// Opt-in (`WOW_AUDIO_LIVE=1`) since it opens the real output device: does the device layer /// open a stream, does the callback run, and does the render thread keep ahead? Off macOS it /// is the only run of this code.