grom/benilla-octo
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

sound: a stream whose callback stopped is rebuilt, whatever the device layer said

Browse Source 
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 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01SgstFWtn1RxEJ5kVrpgYwn
This commit is contained in:
grom
2026-11-01 12:59:18 -07:00
co-authored by Claude Opus 5
parent 510dda3d3c
commit fb0d37e3c8
2 changed files with 218 additions and 8 deletions
Download Patch File Download Diff File Expand all files Collapse all files
crates/benilla-app/src/sound/output/cpal.rs
+9 -2
View File
@@ -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;
}
crates/benilla-app/src/sound/output/mod.rs
+209 -6
View File
@@ -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<T> Drop for Returning<T> {
}
}
/// 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<Instant>,
}
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<Shared>,
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<std::thread::JoinHandle<()>>,
@@ -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<Event>) {
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.