From 510dda3d3c954c46c5452323341d71bcb2ac2735 Mon Sep 17 00:00:00 2001 From: grom Date: Sun, 1 Nov 2026 11:27:18 -0700 Subject: [PATCH] =?UTF-8?q?sound:=20the=20glue-music=20crackle=20never=20h?= =?UTF-8?q?appened=20=E2=80=94=20a=20meter=20that=20summed=20frame=20delta?= =?UTF-8?q?s?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `StreamWatch` asked "did this stream play as much audio as wall time passed?" by summing each frame's `Time` delta into `expected` and comparing it against the stream's own advanced position. But a Bevy clock delta describes the interval *ending* where the frame began, while `window_start` is stamped with `Instant::now()` part-way *through* a frame. So a window opened inside the 4 s world-entry frame was handed that entire 4 s by the next frame, as audible time that should have played — while the position, which tracks the speaker honestly, had advanced only by the window's real span. The difference was logged as injected silence. The tell was in the log all along: `position advanced` equalled the window `span` to the centisecond. When those two agree the audio was perfect, whatever `counted` says. All 101 "glue music stream starved" lines in every log to date are this artifact, plus 104 of 395 zone-music ones. Replaying the new formula over those logs silences all 205 and keeps all 291 real events — streams genuinely frozen with `position advanced 0.00 s`. Fixed by taking both ends of the window off one clock (`now - window_start`) and deleting the `dt` parameter outright, so the counted interval and the reported span are the same number by construction and no caller can supply an inconsistent delta. The old test `stream_watch_spans_the_window_it_counted` asserted exactly this invariant and passed, because its fixture fed a delta that agreed with its own wall clock — a fixture that supplies both sides of a relationship cannot test it. Replaced with the regression that matters: a stream which keeps up across a 4.1 s main-thread stall must not be reported, and one genuinely frozen through the same stall must still be named, or the fix has just deleted the meter. The warn now reports what it measured; "this is what a crackle sounds like" was read as evidence of a crackle and written into the defect backlog as one. `examples/stream_probe.rs` decodes a track through the chain exactly as kira's decoder does and compares the container's declared frame count against frames actually decoded — it killed the first hypothesis for the real dropout: 43 of 43 zone tracks are clean. The real dropout is still open and is not a crackle: one `alsa::poll()` POLLERR, which `output/cpal.rs` classifies as non-fatal and reports as "stream kept", and no sound advances again for the rest of the session. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01SgstFWtn1RxEJ5kVrpgYwn --- crates/benilla-app/examples/stream_probe.rs | 148 ++++++++++++++++ crates/benilla-app/src/sound/glue.rs | 10 +- crates/benilla-app/src/sound/mixer.rs | 176 ++++++++++---------- crates/benilla-app/src/sound/zone.rs | 8 +- 4 files changed, 239 insertions(+), 103 deletions(-) create mode 100644 crates/benilla-app/examples/stream_probe.rs diff --git a/crates/benilla-app/examples/stream_probe.rs b/crates/benilla-app/examples/stream_probe.rs new file mode 100644 index 00000000..a5907f2b --- /dev/null +++ b/crates/benilla-app/examples/stream_probe.rs @@ -0,0 +1,148 @@ +//! `cargo run -p benilla-app --example stream_probe -- […]` — does a streamed track +//! decode as many frames as it declares? +//! +//! The question behind the zone-music dropouts. A streaming sound's transport runs to the frame +//! count the container *declares* (`codec_params.n_frames`), while the audio it can actually play +//! is whatever the decoder yields. When the declaration overstates the content, the stream spends +//! the difference audible with nothing to play: `third_party/kira`'s decode scheduler asks +//! `frame_at_index` for a frame past the real end, which decodes chunk after chunk looking for an +//! index that will never arrive. The renderer's frame ring drains, the position stops advancing, +//! and — because no error was raised and the transport never reached its end — the sound stays +//! `Playing`, so benilla's reap-and-schedule-the-next-track pass never fires +//! (`sound/zone.rs`'s music transport). That is a silent music slot that only a zone change clears. +//! +//! Reads every copy through the chain, so it answers for the bytes the client actually plays +//! ([`benilla_formats::Chain`]), not a copy on disk. With no argument it probes the tracks named +//! on stdin, one chain path per line. +//! +//! Prints, per track: the declared frame count, the frames actually decoded, and the number of +//! chunks that came back empty on the way. `declared > decoded` is the defect; the empty-chunk +//! tally says whether the decoder stalls before it reports EOF. + +use std::io::BufRead; + +use symphonia::core::codecs::Decoder; +use symphonia::core::formats::FormatReader; +use symphonia::core::io::MediaSourceStream; +use symphonia::core::probe::Hint; + +/// The decoder's own frame count for one buffer, matching kira's `load_frames_from_buffer_ref`. +fn frames_in(buf: &symphonia::core::audio::AudioBufferRef) -> usize { + use symphonia::core::audio::Signal; + match buf { + symphonia::core::audio::AudioBufferRef::U8(b) => b.frames(), + symphonia::core::audio::AudioBufferRef::U16(b) => b.frames(), + symphonia::core::audio::AudioBufferRef::U24(b) => b.frames(), + symphonia::core::audio::AudioBufferRef::U32(b) => b.frames(), + symphonia::core::audio::AudioBufferRef::S8(b) => b.frames(), + symphonia::core::audio::AudioBufferRef::S16(b) => b.frames(), + symphonia::core::audio::AudioBufferRef::S24(b) => b.frames(), + symphonia::core::audio::AudioBufferRef::S32(b) => b.frames(), + symphonia::core::audio::AudioBufferRef::F32(b) => b.frames(), + symphonia::core::audio::AudioBufferRef::F64(b) => b.frames(), + } +} + +fn main() { + let Some(data) = benilla_formats::wow_data() else { + eprintln!("no install"); + std::process::exit(1); + }; + let chain = benilla_formats::Chain::open(&data).expect("chain opens"); + + let args: Vec = std::env::args().skip(1).collect(); + let names: Vec = if args.is_empty() { + std::io::stdin() + .lock() + .lines() + .map_while(Result::ok) + .map(|l| l.trim().to_string()) + .filter(|l| !l.is_empty()) + .collect() + } else { + args + }; + + println!( + "{:<58} {:>10} {:>10} {:>9} {:>6} verdict", + "track", "declared", "decoded", "short by", "empty" + ); + let mut bad = 0usize; + for name in &names { + let path = name.replace('/', "\\"); + let Ok(bytes) = chain.read(&path) else { + println!("{:<58} not in the chain", short(&path)); + continue; + }; + match probe(bytes) { + Err(e) => println!("{:<58} {e}", short(&path)), + Ok((declared, decoded, empty)) => { + let verdict = if declared > decoded { + bad += 1; + "DECLARES MORE THAN IT HAS" + } else { + "ok" + }; + println!( + "{:<58} {declared:>10} {decoded:>10} {:>9} {empty:>6} {verdict}", + short(&path), + declared.saturating_sub(decoded), + ); + } + } + } + println!( + "\n{bad} of {} track(s) declare more frames than they decode", + names.len() + ); +} + +fn short(p: &str) -> String { + p.rsplit('\\').next().unwrap_or(p).to_string() +} + +/// `(declared, decoded, empty_chunks)` for one track, decoded exactly as kira's decoder does. +fn probe(bytes: Vec) -> Result<(usize, usize, usize), String> { + let source = std::io::Cursor::new(bytes); + let mss = MediaSourceStream::new(Box::new(source), Default::default()); + let probed = symphonia::default::get_probe() + .format( + &Hint::default(), + mss, + &Default::default(), + &Default::default(), + ) + .map_err(|e| format!("probe: {e}"))?; + let mut format_reader: Box = probed.format; + let track = format_reader.default_track().ok_or("no default track")?; + let declared: usize = track + .codec_params + .n_frames + .ok_or("no declared frame count")? + .try_into() + .map_err(|_| "frame count does not fit usize")?; + let track_id = track.id; + let mut decoder: Box = symphonia::default::get_codecs() + .make(&track.codec_params, &Default::default()) + .map_err(|e| format!("codec: {e}"))?; + + let mut decoded = 0usize; + let mut empty = 0usize; + // The read ends where kira's decoder would report an error, which is what stops the sound. + while let Ok(packet) = format_reader.next_packet() { + if packet.track_id() != track_id { + continue; + } + match decoder.decode(&packet) { + Ok(buf) => { + let n = frames_in(&buf); + if n == 0 { + empty += 1; + } + decoded += n; + } + Err(_) => empty += 1, + } + } + Ok((declared, decoded, empty)) +} diff --git a/crates/benilla-app/src/sound/glue.rs b/crates/benilla-app/src/sound/glue.rs index 047615cd..34c7c1cb 100644 --- a/crates/benilla-app/src/sound/glue.rs +++ b/crates/benilla-app/src/sound/glue.rs @@ -144,13 +144,7 @@ fn hand_off_glue_music( /// The starvation watch over the held theme, and the handle's drop once it reaches `Stopped`. /// On the glue screens [`start_glue_music`] then restarts it; in the world it runs out and stays /// out. -fn watch_glue_music( - mut music: NonSendMut, - // Wall time: the watch compares against the stream's own position, and the paced virtual - // clock is snapped and capped by `frame_pace`. - time: Res>, - config: Res, -) { +fn watch_glue_music(mut music: NonSendMut, config: Res) { let music = &mut *music; // The Music slider rescales the playing theme in place (the `MusicVolume` re-apply walker // `0x7a6660(ecx=2)` matches the glue stream), except while the stop-fade runs. @@ -173,7 +167,7 @@ fn watch_glue_music( music.watch.reset(); return; } - music.watch.feed(h, f64::from(time.delta_secs())); + music.watch.feed(h); } /// Report the glue theme's voice into the global budget; it plays into `InWorld` too. diff --git a/crates/benilla-app/src/sound/mixer.rs b/crates/benilla-app/src/sound/mixer.rs index ab9ef67c..b50e0ee2 100644 --- a/crates/benilla-app/src/sound/mixer.rs +++ b/crates/benilla-app/src/sound/mixer.rs @@ -570,11 +570,21 @@ const STREAM_START_MAX_SECS: f64 = 3.0; /// Every stream opens frozen until the decoder has two frames ready; that spin-up is not a /// dropout, so counting starts once the position moves. A stream that starves and stops inside /// one main-thread stall is never counted; the mix tap covers that. +/// +/// **The window is measured between two [`std::time::Instant`]s, never summed from frame +/// deltas.** It used to add each frame's `Time` delta, and that reported a crackle on +/// every long frame that there was never any sound of: a Bevy clock delta describes the interval +/// *ending* where the frame began ([`crate::perf`]), so a window stamped part-way through a +/// 4 s world-entry frame was handed that whole 4 s by the next frame, as audible time that +/// should have played. The position — which tracks the speaker honestly — had only advanced by +/// the window's real span, so the difference read as injected silence. It accounted for every +/// one of the 101 "glue music stream starved" lines in the logs up to 2026-11-01, each with +/// `position advanced` equal to the span to the centisecond. Taking both ends off the same +/// clock makes the counted interval and the reported span the same number by construction, and +/// leaves no delta for a caller to get wrong. pub(crate) struct StreamWatch { label: &'static str, phase: Phase, - /// Wall time counted into the open window, summed from the fed frame deltas. - expected: f64, advanced: f64, } @@ -599,12 +609,7 @@ enum Phase { /// What [`StreamWatch::observe`] found this frame. enum Verdict { /// A window closed having lost more than [`STREAM_STARVED_MIN_SECS`] of audible time. - Starved { - lost: f64, - counted: f64, - advanced: f64, - span: f64, - }, + Starved { lost: f64, advanced: f64, span: f64 }, /// The stream went audible and its position never moved. NeverStarted { waited: f64 }, /// The stream began advancing this long after it went audible: its spin-up. @@ -616,28 +621,29 @@ impl StreamWatch { Self { label, phase: Phase::Idle, - expected: 0.0, advanced: 0.0, } } /// Per-frame feed from the held handle, every frame it exists. - pub(crate) fn feed(&mut self, handle: &StreamingSoundHandle, dt: f64) { + pub(crate) fn feed(&mut self, handle: &StreamingSoundHandle) { use kira::sound::PlaybackState as S; let audible = matches!(handle.state(), S::Playing | S::Stopping); - match self.observe(audible, handle.position(), dt, std::time::Instant::now()) { + match self.observe(audible, handle.position(), std::time::Instant::now()) { Some(Verdict::Starved { lost, - counted, advanced, span, }) => { - // No cause is named: a starved decoder, a render thread that did not run and a - // rebuilding device freeze the position identically. + // The numbers, not a conclusion drawn from them: a starved decoder, a render + // thread that did not run and a rebuilding device freeze the position + // identically, and the one occurrence traced end to end was the device — an + // `alsa::poll()` POLLERR this backend classifies as non-fatal, after which no + // sound advances again (`sound/output/cpal.rs`'s `on_error`). Naming the cause + // wants the output window's own meters (`cycles`, `underruns`) folded in here. warn!( - "audio: {} stream starved — ~{:.0} ms of injected silence over a {span:.2} s \ - window (counted {counted:.2} s, position advanced {advanced:.2} s) — this is \ - what a crackle sounds like", + "audio: {} stream starved — its position advanced only {advanced:.2} s across \ + a {span:.2} s window, so ~{:.0} ms of silence reached the speaker", self.label, lost * 1000.0, ); @@ -661,7 +667,6 @@ impl StreamWatch { /// Drop the baseline when the watched handle is dropped or replaced. pub(crate) fn reset(&mut self) { self.phase = Phase::Idle; - self.expected = 0.0; self.advanced = 0.0; } @@ -671,17 +676,10 @@ impl StreamWatch { last_pos: pos, window_start: now, }; - self.expected = 0.0; self.advanced = 0.0; } - fn observe( - &mut self, - audible: bool, - pos: f64, - dt: f64, - now: std::time::Instant, - ) -> Option { + fn observe(&mut self, audible: bool, pos: f64, now: std::time::Instant) -> Option { // Stopped or paused: the position legitimately holds. if !audible { self.reset(); @@ -728,26 +726,23 @@ impl StreamWatch { pos, warned: false, }; - self.expected = 0.0; self.advanced = 0.0; return None; } - self.expected += dt; self.advanced += pos - last_pos; self.phase = Phase::Running { last_pos: pos, window_start, }; - if self.expected < STREAM_WATCH_WINDOW_SECS { + let span = now.duration_since(window_start).as_secs_f64(); + if span < STREAM_WATCH_WINDOW_SECS { return None; } - let (counted, advanced) = (self.expected, self.advanced); - let span = now.duration_since(window_start).as_secs_f64(); + let advanced = self.advanced; self.begin(pos, now); - let lost = counted - advanced; + let lost = span - advanced; (lost > STREAM_STARVED_MIN_SECS).then_some(Verdict::Starved { lost, - counted, advanced, span, }) @@ -1282,7 +1277,7 @@ mod tests { pos += dt; assert!( !matches!( - w.observe(true, pos, dt, wall(t0, f64::from(i) * dt)), + w.observe(true, pos, wall(t0, f64::from(i) * dt)), Some(Verdict::Starved { .. }) ), "healthy stream reported" @@ -1297,14 +1292,10 @@ mod tests { if !(30..48).contains(&i) { pos += dt; } - if let Some(Verdict::Starved { - lost, - counted, - span, - .. - }) = w.observe(true, pos, dt, wall(t0, f64::from(i) * dt)) + if let Some(Verdict::Starved { lost, span, .. }) = + w.observe(true, pos, wall(t0, f64::from(i) * dt)) { - reports.push((lost, counted, span)); + reports.push((lost, span)); } } assert_eq!(reports.len(), 1, "one starved window: {reports:?}"); @@ -1322,7 +1313,7 @@ mod tests { } assert!( !matches!( - w.observe(true, pos, dt, wall(t0, f64::from(i) * dt)), + w.observe(true, pos, wall(t0, f64::from(i) * dt)), Some(Verdict::Starved { .. }) ), "slot swap reported as freeze" @@ -1335,16 +1326,16 @@ mod tests { let mut pos = 70.0; for i in 0..30 { assert!(w - .observe(true, pos, dt, wall(t0, f64::from(i) * dt)) + .observe(true, pos, wall(t0, f64::from(i) * dt)) .is_none_or(|v| matches!(v, Verdict::Began { .. }))); pos += dt; } - assert!(w.observe(false, pos, dt, wall(t0, 0.5)).is_none()); + assert!(w.observe(false, pos, wall(t0, 0.5)).is_none()); let mut pos = 0.0; for i in 30..120 { assert!( !matches!( - w.observe(true, pos, dt, wall(t0, f64::from(i) * dt)), + w.observe(true, pos, wall(t0, f64::from(i) * dt)), Some(Verdict::Starved { .. }) ), "restart read as freeze" @@ -1353,52 +1344,61 @@ mod tests { } } - /// A 298 ms hitch at the head of a window, the stream frozen through it, is both counted and - /// spanned. + /// A world-entry frame blocks the main thread for 4.1 s while the theme plays on through it. + /// This is grom's login, which the watch called a crackle 101 times over. + /// + /// The window gets stamped part-way into that frame, so summing the *next* frame's + /// `Time` delta charged the whole stall as audible time that should have played, while + /// the position — which tracks the speaker — had honestly advanced by the window's real span. + /// Both ends now come off one clock. A stream that kept up must be silent in the log, and one + /// that genuinely froze through the same stall must still be named, or the fix has just + /// deleted the meter. #[test] - fn stream_watch_spans_the_window_it_counted() { + fn stream_watch_does_not_charge_a_healthy_stream_for_a_main_thread_stall() { let dt = 1.0 / 60.0; + let stall = 4.095; + // One login's observation times: ordinary frames, the world-entry frame, then ordinary. + let ticks = { + let mut t: Vec = (0..40).map(|i| f64::from(i) * dt).collect(); + let base = *t.last().expect("40 frames"); + t.push(base + stall); + t.extend((1..=180).map(|i| base + stall + f64::from(i) * dt)); + t + }; + + // Kept up: the position advances with wall time, the stall included. let t0 = std::time::Instant::now(); - let hitch = 0.298; let mut w = StreamWatch::new("test"); - - assert!(w.observe(true, 0.0, dt, wall(t0, 0.0)).is_none()); - // The first sample lands and the window opens. - assert!(matches!( - w.observe(true, 0.001, dt, wall(t0, 0.010)), - Some(Verdict::Began { .. }) - )); - // The hitch: its delta reaches back to the instant the window opened. - assert!(w - .observe(true, 0.001, hitch, wall(t0, 0.010 + hitch)) - .is_none()); - - let mut pos = 0.001; - let mut report = None; - for i in 0..90 { - pos += dt; - let t = 0.010 + hitch + f64::from(i + 1) * dt; - if let Some(v) = w.observe(true, pos, dt, wall(t0, t)) { - report = Some(v); - break; + let mut reports = Vec::new(); + for t in &ticks { + if let Some(Verdict::Starved { + lost, + span, + advanced, + }) = w.observe(true, *t, wall(t0, *t)) + { + reports.push((lost, span, advanced)); } } - let Some(Verdict::Starved { - lost, - counted, - span, - .. - }) = report - else { - panic!("the frozen hitch went unreported"); - }; assert!( - (counted - span).abs() < 1e-6, - "the window must span the interval it counted: counted {counted}, span {span}" + reports.is_empty(), + "a stream that kept up was reported as a crackle: {reports:?}" ); + + // Frozen from just before the stall: still named, and the stall is the loss. + let t0 = std::time::Instant::now(); + let mut w = StreamWatch::new("test"); + let frozen_at = ticks[39]; + let mut worst = 0.0f64; + for t in &ticks { + let pos = t.min(frozen_at); + if let Some(Verdict::Starved { lost, .. }) = w.observe(true, pos, wall(t0, *t)) { + worst = worst.max(lost); + } + } assert!( - (lost - hitch).abs() < 0.01, - "the hitch is the whole loss: {lost}" + (worst - stall).abs() < 0.05, + "the stall is the whole loss: {worst}" ); } @@ -1421,18 +1421,16 @@ mod tests { for i in 1..=180 { ticks.push(hitch + f64::from(i) * dt); } - for (i, t) in ticks.iter().enumerate() { - let delta = if i == 0 { dt } else { t - ticks[i - 1] }; - match w.observe(true, pos_at(*t), delta, wall(t0, *t)) { + for t in &ticks { + match w.observe(true, pos_at(*t), wall(t0, *t)) { Some(Verdict::Began { after }) => began.push(after), Some(Verdict::Starved { lost, - counted, span, - .. + advanced, }) => { starved += 1; - eprintln!("starved: lost {lost} counted {counted} span {span}"); + eprintln!("starved: lost {lost} span {span} advanced {advanced}"); } Some(Verdict::NeverStarted { .. }) => { panic!("a playing stream read as never started") @@ -1460,7 +1458,7 @@ mod tests { let mut waited = Vec::new(); for i in 0..600 { if let Some(Verdict::NeverStarted { waited: s }) = - w.observe(true, 0.0, dt, wall(t0, f64::from(i) * dt)) + w.observe(true, 0.0, wall(t0, f64::from(i) * dt)) { waited.push(s); } diff --git a/crates/benilla-app/src/sound/zone.rs b/crates/benilla-app/src/sound/zone.rs index da26a5f7..090c9be1 100644 --- a/crates/benilla-app/src/sound/zone.rs +++ b/crates/benilla-app/src/sound/zone.rs @@ -249,8 +249,6 @@ fn zone_audio( config: Res, clock: Res, time: Res