app: extend OAK_DEBUG_AUDIO diagnostics to the render thread and output stream

Per-chunk submit->render wait and render time (audio_thread), the push
lead against the playhead, the negotiated stream config, and the true
device-side callback rate (outputdevice) -- the ground truth used to
localize the playback starvation to the sequence-rate/clock mismatch.
This commit is contained in:
2026-08-29 23:31:48 +08:00
parent 84caa3589b
commit 197212bc46
2 changed files with 52 additions and 2 deletions
+16 -2
View File
@@ -44,6 +44,8 @@ struct AudioJob {
params: AudioTicketParams,
start_ts: i64,
done: mpsc::Sender<(i64, RenderedAudio)>,
/// When the job was queued (diagnostics: submit→render latency).
enqueued: std::time::Instant,
}
/// The audio-render thread's job queue (set on first use; the sender is
@@ -59,8 +61,13 @@ pub fn submit(
done: mpsc::Sender<(i64, RenderedAudio)>,
) -> Result<(), String> {
let tx = ensure_thread();
tx.send(AudioJob { params, start_ts, done })
.map_err(|_| "the audio render thread has exited".to_string())
tx.send(AudioJob {
params,
start_ts,
done,
enqueued: std::time::Instant::now(),
})
.map_err(|_| "the audio render thread has exited".to_string())
}
/// The queue sender, starting the render thread on first use.
@@ -83,6 +90,8 @@ fn ensure_thread() -> mpsc::Sender<AudioJob> {
/// The render loop: one job at a time; failures degrade to silence.
fn render_loop(rx: mpsc::Receiver<AudioJob>) {
while let Ok(job) = rx.recv() {
let wait_ms = job.enqueued.elapsed().as_millis();
let t0 = std::time::Instant::now();
let data = match oak_render::eval::render_audio_samples(&job.params) {
Ok(TicketPayload::Audio(samples)) => RenderedAudio {
data: samples.samples,
@@ -91,6 +100,11 @@ fn render_loop(rx: mpsc::Receiver<AudioJob>) {
},
_ => silence_for(&job.params),
};
let ms = t0.elapsed().as_millis();
super::real::audio_dbg(&format!(
"chunk {} render: waited {wait_ms}ms, rendered in {ms}ms",
job.start_ts
));
let _ = job.done.send((job.start_ts, data));
}
}
+36
View File
@@ -39,6 +39,12 @@ use crate::previewdevice::PreviewAudioDevice;
/// (clamped to the device's supported range).
const FRAMES_PER_BUFFER: u32 = 512;
/// OAK_DEBUG_AUDIO-gated diagnostics for the output stream.
fn stream_dbg_enabled() -> bool {
static ENABLED: std::sync::OnceLock<bool> = std::sync::OnceLock::new();
*ENABLED.get_or_init(|| std::env::var_os("OAK_DEBUG_AUDIO").is_some())
}
/// An open (or openable) cpal output stream.
pub struct PortAudioOutput {
/// Audio host/session (created lazily; `None` when unavailable).
@@ -103,6 +109,14 @@ impl PortAudioOutput {
let output_device = resolve_device(&host, device)
.ok_or_else(|| "no output device available".to_string())?;
let config = pick_config(&output_device, rate, channels)?;
if stream_dbg_enabled() {
eprintln!(
"[audio-stream] config: {} Hz, {} ch, buffer {:?}",
u32::from(config.sample_rate),
config.channels,
config.buffer_size
);
}
// The callback pulls whole frames from the shared device and
// advances the output clock (underrun → silence). `read` locks
@@ -112,8 +126,30 @@ impl PortAudioOutput {
let channels_usize = channels.max(1) as usize;
let sink_cb = sink.clone();
let scratch = RefCell::new(Vec::<u8>::new());
// OAK_DEBUG_AUDIO: true device-side request rate (callbacks/s and
// frames/s), aggregated once per second — this is the ground truth
// for production/consumption mismatch hunts.
let dbg_stats = RefCell::new((0u64, 0u64, std::time::Instant::now()));
let callback = move |out: &mut [f32], _info: &cpal::OutputCallbackInfo| {
let total = out.len();
if stream_dbg_enabled() {
let mut st = dbg_stats.borrow_mut();
st.0 += total as u64;
st.1 += 1;
let el = st.2.elapsed();
if el >= std::time::Duration::from_secs(1) {
let secs = el.as_secs_f64();
eprintln!(
"[audio-stream] callback: {:.1} calls/s, {:.0} samples/s ({} ch)",
st.1 as f64 / secs,
st.0 as f64 / secs,
channels_usize
);
st.0 = 0;
st.1 = 0;
st.2 = std::time::Instant::now();
}
}
let mut scratch = scratch.borrow_mut();
scratch.resize(total * 4, 0);
let got = sink_cb.read(scratch.as_mut_slice());