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