From a9aa19ecddd4d63878f2c0f77d5019653ec507e2 Mon Sep 17 00:00:00 2001 From: EdisonJwa Date: Sun, 17 May 2026 02:47:35 +0800 Subject: [PATCH] diag(audio,ios): comprehensive producer + consumer ring-buffer metrics (rc.8+74) External reviewer correctly identified that the +73 ring-buffer commit didn't fix the symptom but the architecture is still right. We need to distinguish two possible causes: (a) Producer task isn't running (or running too rarely) so ring stays underfilled. (b) Producer IS running but fill_buffer returns zeros most of the time (AudioHandler stuck in buffering_samples state or no packets reaching it). The +73 render-side diagnostic was insufficient: we logged underruns + peak_out_i16 but not what the producer was actually pushing. This commit adds producer-side metrics rolled up every 5 s (250 ticks at 20 ms): Producer task: producer_ticks : timer firings (= ~250 per 5 s window; fewer = tokio scheduler stalled) produced_chunks : pushes into ring (= ticks - drops) fill_buffer_calls : AudioHandler queries fill_buffer_zero_returns : ticks where scratch came back all zeros (no decoded content to play) ring_full_drops : ticks where ring was full and we skipped the push ring_min/max_samples : depth envelope across window ring_min/max_ms : same in milliseconds window_peak_f32 : max scratch sample across window window_rms_f32 : RMS of all scratch samples across window Render callback (per-100-callback as before, plus new fields): ring_avail_before : Consumer::slots() before this read (= how many samples were sitting in the ring at callback entry) read_frames : samples successfully popped zero_filled : samples zero-filled because ring was empty (= num_frames - read_frames) underruns / underrun_samples / peak_out_i16 / clip_count_i16 : as before Reading the next iteration's log: If producer_ticks << 250 per 5 s window: tokio scheduler isn't running the task fast enough. Move producer to its own dedicated runtime, or use std::thread + std::sync::mpsc + std::thread::sleep instead of tokio. If producer_ticks ~= 250 AND fill_buffer_zero_returns is high (most ticks return silence): AudioHandler isn't decoding packets fast enough OR is stuck buffering. Bug is upstream in protocol layer packet delivery or AudioHandler's jitter state machine. The ring buffer architecture cannot fix this. If producer_ticks ~= 250 AND fill_buffer_zero_returns is low AND ring_min_ms stays >100ms AND underruns are low BUT consumer's peak_out_i16 is still 0: Something is wrong between push and pop. Lock-free ring corruption, or wrong stride. Pure diagnostic. No behavioural change beyond the logging. Producer scratch envelope scan is O(scratch.len()) = 1920 samples per 20 ms tick = ~96k iterations/sec on the audio producer thread \u2014 negligible CPU. Build counter 73 -> 74. --- apps/chanora_flutter/pubspec.yaml | 2 +- crates/chanora_audio/src/ios_voice_unit.rs | 185 ++++++++++++++++++--- 2 files changed, 167 insertions(+), 20 deletions(-) diff --git a/apps/chanora_flutter/pubspec.yaml b/apps/chanora_flutter/pubspec.yaml index ab5d739..6c1b6af 100644 --- a/apps/chanora_flutter/pubspec.yaml +++ b/apps/chanora_flutter/pubspec.yaml @@ -16,7 +16,7 @@ publish_to: 'none' # Remove this line if you wish to publish to pub.dev # https://developer.apple.com/library/archive/documentation/General/Reference/InfoPlistKeyReference/Articles/CoreFoundationKeys.html # In Windows, build-name is used as the major, minor, and patch parts # of the product and file versions while build-number is used as the build suffix. -version: 1.0.0-rc.8+73 +version: 1.0.0-rc.8+74 environment: sdk: ^3.11.5 diff --git a/crates/chanora_audio/src/ios_voice_unit.rs b/crates/chanora_audio/src/ios_voice_unit.rs index afb78bd..4f42075 100644 --- a/crates/chanora_audio/src/ios_voice_unit.rs +++ b/crates/chanora_audio/src/ios_voice_unit.rs @@ -578,24 +578,71 @@ impl IosVoiceUnit { let handler_for_producer = handler.clone(); let (producer_shutdown_tx, mut producer_shutdown_rx) = tokio::sync::oneshot::channel::<()>(); + // Use the consumer's `slots()` (= free slots = unwritten) + // to compute current ring fill level (= RING_BUFFER_SAMPLES + // - free). But the consumer end is in the render closure, + // not accessible here. rtrb exposes `Producer::slots()` + // which returns the FREE count, same arithmetic: + // fill_samples = RING_BUFFER_SAMPLES - producer.slots() + // fill_ms = fill_samples * 1000 / 48000 + // No locks needed; slots() is a relaxed atomic read. tokio::spawn(async move { let mut scratch_stereo = vec![0.0_f32; FRAME_SAMPLES_MONO * 2]; let mut interval = tokio::time::interval(Duration::from_millis(PRODUCER_TICK_MS)); interval.set_missed_tick_behavior(tokio::time::MissedTickBehavior::Skip); + // Per-tick counters (rolled up every PRODUCER_LOG_TICKS + // ticks = ~5 s of wall time). All u64 to avoid overflow + // across hours of session. + let mut producer_ticks: u64 = 0; let mut produced_chunks: u64 = 0; + let mut fill_buffer_calls: u64 = 0; + let mut fill_buffer_zero_returns: u64 = 0; let mut ring_full_drops: u64 = 0; + // Min/max ring level WITHIN the current logging + // window. Reset to extremes at each log emission so + // each window's report describes that window's + // behaviour. + let mut ring_min_samples: usize = usize::MAX; + let mut ring_max_samples: usize = 0; + // Accumulated scratch envelope across the window so + // we can emit window-average peak + RMS without + // doing a O(n) scan in the hot path \u2014 only an + // O(n) scan per producer tick (already affordable). + let mut window_peak_f32: f32 = 0.0; + let mut window_sumsq_f64: f64 = 0.0; + let mut window_sample_count: u64 = 0; + const PRODUCER_LOG_TICKS: u64 = 250; // 250 * 20 ms = 5 s loop { tokio::select! { _ = &mut producer_shutdown_rx => { debug!( target: "chanora_audio", produced_chunks, + fill_buffer_calls, + fill_buffer_zero_returns, ring_full_drops, "ios VPIO producer task shutting down" ); break; } _ = interval.tick() => { + producer_ticks = producer_ticks.wrapping_add(1); + // Measure ring level BEFORE the push so + // the diagnostic shows whether the + // consumer is keeping up. Slots = free + // slots; fill = capacity - free. + let free_before = ring_producer.slots(); + let fill_before = RING_BUFFER_SAMPLES.saturating_sub(free_before); + if fill_before < ring_min_samples { + ring_min_samples = fill_before; + } + if fill_before > ring_max_samples { + ring_max_samples = fill_before; + } + + // Zero scratch first (fill_buffer is + // additive over per-talker streams; it + // does NOT clear). for s in scratch_stereo.iter_mut() { *s = 0.0; } @@ -603,28 +650,117 @@ impl IosVoiceUnit { let mut h = handler_for_producer.lock().unwrap(); let _removed = h.fill_buffer(&mut scratch_stereo); } - let free = ring_producer.slots(); - if free < FRAME_SAMPLES_MONO { - ring_full_drops = ring_full_drops.wrapping_add(1); - if ring_full_drops.is_multiple_of(50) { - warn!( - target: "chanora_audio", - ring_full_drops, - free_slots = free, - "ios VPIO ring buffer overflow (consumer slow)" - ); + fill_buffer_calls = fill_buffer_calls.wrapping_add(1); + + // Measure scratch envelope. fill_buffer + // either filled with real content or + // left it at zero (we pre-zeroed). A + // zero-peak scratch means the handler + // had nothing to play \u2014 either no + // talker active, no packets in queue, or + // queue stuck in buffering_samples + // state. + let mut tick_peak: f32 = 0.0; + let mut tick_sumsq: f64 = 0.0; + for &s in scratch_stereo.iter() { + let a = s.abs(); + if a > tick_peak { + tick_peak = a; } - continue; + tick_sumsq += (s as f64) * (s as f64); } - for i in 0..FRAME_SAMPLES_MONO { - let l = scratch_stereo[i * 2]; - let r = scratch_stereo[i * 2 + 1]; - let mono_f32 = (l + r) * 0.5; - let clamped = mono_f32.clamp(-1.0, 1.0); - let sample = (clamped * i16::MAX as f32) as i16; - let _ = ring_producer.push(sample); + if tick_peak == 0.0 { + fill_buffer_zero_returns = + fill_buffer_zero_returns.wrapping_add(1); + } + if tick_peak > window_peak_f32 { + window_peak_f32 = tick_peak; + } + window_sumsq_f64 += tick_sumsq; + window_sample_count = + window_sample_count.wrapping_add(scratch_stereo.len() as u64); + + // Check ring has room then push. + if free_before < FRAME_SAMPLES_MONO { + ring_full_drops = ring_full_drops.wrapping_add(1); + // Don't push; ring would block / wrap. + } else { + for i in 0..FRAME_SAMPLES_MONO { + let l = scratch_stereo[i * 2]; + let r = scratch_stereo[i * 2 + 1]; + let mono_f32 = (l + r) * 0.5; + let clamped = mono_f32.clamp(-1.0, 1.0); + let sample = (clamped * i16::MAX as f32) as i16; + let _ = ring_producer.push(sample); + } + produced_chunks = produced_chunks.wrapping_add(1); + } + + // Emit rolled-up window diagnostic every + // ~5 s. All fields together let us tell + // exactly where audio is being lost: + // + // producer_ticks : how many times we + // ticked (should be + // ~250 per 5 s window; + // fewer = tokio + // scheduler stalled). + // produced_chunks : pushes into ring + // (= ticks - drops). + // fill_buffer_calls : AudioHandler queries + // (= ticks; always + // equal unless tokio + // panicked mid-loop). + // fill_buffer_zero_returns + // : ticks where fill_buffer + // left scratch at all + // zeros. High value = + // AudioHandler has no + // content to play. + // ring_full_drops : pushes skipped because + // ring was full (consumer + // slow). + // ring_min/max_samples : depth envelope across + // window. Should sit + // stable around the + // target_level + // (FRAME_SAMPLES_MONO). + // window_peak_f32 : max scratch sample + // across window. + // window_rms_f32 : RMS across all scratch + // samples in window. + if producer_ticks.is_multiple_of(PRODUCER_LOG_TICKS) { + let window_rms = if window_sample_count > 0 { + (window_sumsq_f64 / window_sample_count as f64).sqrt() as f32 + } else { + 0.0 + }; + let ring_min_ms = + (ring_min_samples * 1000) as f64 / 48000.0; + let ring_max_ms = + (ring_max_samples * 1000) as f64 / 48000.0; + info!( + target: "chanora_audio", + producer_ticks, + produced_chunks, + fill_buffer_calls, + fill_buffer_zero_returns, + ring_full_drops, + ring_min_samples, + ring_max_samples, + ring_min_ms = format!("{:.1}", ring_min_ms), + ring_max_ms = format!("{:.1}", ring_max_ms), + window_peak_f32, + window_rms_f32 = window_rms, + "ios VPIO producer task diagnostic sample" + ); + // Reset window-scope counters. + ring_min_samples = usize::MAX; + ring_max_samples = 0; + window_peak_f32 = 0.0; + window_sumsq_f64 = 0.0; + window_sample_count = 0; } - produced_chunks = produced_chunks.wrapping_add(1); } } } @@ -643,6 +779,13 @@ impl IosVoiceUnit { let out: &mut [i16] = args.data.buffer; let num_frames = out.len(); + // Measure ring buffer fill level BEFORE the read so + // the diagnostic shows whether the producer is keeping + // up. Consumer::slots() returns the number of + // AVAILABLE (= readable) samples; the inverse + // (free space) lives on the Producer end. + let ring_avail_before = ring_consumer.slots(); + // Pop up to num_frames samples from the ring buffer // into the output. Anything not filled stays at // whatever was there (we zero-fill the tail @@ -670,6 +813,7 @@ impl IosVoiceUnit { } } } + let zero_filled_this_call = num_frames - filled; // Post-process: mute then gain. Gain is applied // CONSUMER-SIDE (not producer-side) so user-driven @@ -713,6 +857,9 @@ impl IosVoiceUnit { cb = cb_count, num_frames, frames_changes = num_frames_changes, + ring_avail_before, + read_frames = filled, + zero_filled = zero_filled_this_call, underruns, underrun_samples, peak_out_i16 = peak_out,