edison/chanora
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

diag(audio,ios): comprehensive producer + consumer ring-buffer metrics (rc.8+74)

Browse Source 
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.
This commit is contained in:
EdisonJwa
2026-05-17 02:47:35 +08:00
parent 99584fbc1a
commit a9aa19ecdd
2 changed files with 167 additions and 20 deletions
Download Patch File Download Diff File Expand all files Collapse all files
apps/chanora_flutter/pubspec.yaml
+1 -1
View File
@@ -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
crates/chanora_audio/src/ios_voice_unit.rs
+166 -19
View File
@@ -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,