app: sync the playback clock to the sequence rate; heal underruns by trimming

Two playback-audio defects found while chasing periodic pops, clipped
words and repeated phrases:

1. The playback clocks are created at engine init with the fallback
   rate (hd_1080p25) and never updated, while audio chunks are sized by
   the SEQUENCE time base (30/1 from the broken default). The playhead
   advanced at 25 fps but each chunk carried only 1600 samples, so
   production ran at 40000 samples/s against the device's 48000 -- ~17%
   of playback time was zero-filled silence (clipped words). tick() now
   syncs both clocks to the sequence's actual rate.

2. The underrun self-heal cleared the whole device queue (~190 ms of
   unheard content skipped), reset the prefetch (whose first
   re-rendered chunk was then always dropped as late) and re-anchored
   the master clock, re-rendering already-played audio whenever the
   playhead lagged (audible as a pop plus a repeated phrase, every
   ~1.1 s). It now trims just the stale lead from the queue
   (PreviewAudioDevice::drop_front_frames): the zero-fill already
   advanced the output clock past that content, so the rest of the
   queue stays audible and the anchor stays valid.

Also adds the OAK_DEBUG_AUDIO event log used to diagnose all of this
(prefetch resets, late drops, underruns, heals, reanchor jumps,
per-tick queue state).

crates/oak-app/src/oakui/real.rs

@@ -393,7 +393,12 @@ impl AudioPrefetch {
 			let ts = *ts;
 			let (_, data) = self.buffered.pop_front().unwrap();
 			if ts >= playhead {
+				audio_dbg(&format!("push chunk {ts} (lead {} vs playhead {playhead})", ts - playhead));
 				out.push(data);
+			} else {
+				audio_dbg(&format!(
+					"chunk {ts} arrived late (playhead {playhead}) -> dropped"
+				));
 			}
 			self.front_ts = ts + self.chunk;
 			self.last_consumed = Some(ts);
@@ -402,6 +407,23 @@ impl AudioPrefetch {
 	}
 }
 
+/// OAK_DEBUG_AUDIO-gated playback diagnostics: the events below (prefetch
+/// resets, late-chunk drops, underrun heals) each produce an audible
+/// discontinuity, so their timestamps correlate with pops/crackles.
+pub(crate) fn audio_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())
+}
+
+pub(crate) fn audio_dbg(msg: &str) {
+	if !audio_dbg_enabled() {
+		return;
+	}
+	static T0: std::sync::OnceLock<std::time::Instant> = std::sync::OnceLock::new();
+	let ms = T0.get_or_init(std::time::Instant::now).elapsed().as_millis();
+	eprintln!("[audio {ms:>8}ms] {msg}");
+}
+
 /// One background full-resolution render request (built on the UI thread
 /// at schedule time; the worker thread owns it from there).
 struct FullResRequest {
@@ -1213,6 +1235,10 @@ impl RealEngine {
 		// Reset on seek / restart (see needs_reset): serving runs ahead of
 		// the playhead, so only genuine jumps re-arm the buffer.
 		if st.needs_reset(frame) {
+			audio_dbg(&format!(
+				"prefetch reset at frame {frame} (seek/restart; next_submit was {})",
+				st.next_submit
+			));
 			st.reset(frame, chunk);
 		}
 		// Submit chunks to cover [next_submit, frame + PREFETCH ahead). In
@@ -1224,6 +1250,7 @@ impl RealEngine {
 			.unwrap_or_else(|e| e.into_inner())
 			.clone();
 		let target = frame + chunk * AUDIO_PREFETCH_CHUNKS;
+		let mut submitted = 0i32;
 		while st.next_submit < target {
 			let ts = st.next_submit;
 			let p = project.clone();
@@ -1231,6 +1258,7 @@ impl RealEngine {
 				break;
 			}
 			st.next_submit += chunk;
+			submitted += 1;
 		}
 		// Drain completed chunks. With the M16 S3 audio thread the submit
 		// above only queues; the render lands here asynchronously, so the
@@ -1243,9 +1271,14 @@ impl RealEngine {
 		// Underrun self-heal: zero-padding advanced the output clock past
 		// the queued content, so everything audible from here on would
 		// play late (the classic "audio drifts behind video"). Resync by
-		// dropping the device queue and re-rendering from the playhead;
-		// the anchor is re-recorded at the next push. Cooldown prevents a
-		// resync storm while the fresh chunks are still rendering.
+		// trimming just the stale lead from the device queue — the rest
+		// stays audible and the master-clock anchor stays valid (the
+		// clock already advanced past the zero-fill). The old full
+		// clear + prefetch reset + re-anchor skipped ~190 ms of unheard
+		// content and re-rendered already-played audio whenever the
+		// playhead lagged (audible as a pop plus a repeated phrase), and
+		// the reset that followed always dropped its first re-rendered
+		// chunk as "late" — a ~1.1 s periodic skip/repeat cycle.
 		if self.audio_playback.is_some() {
 			let cooldown_ok = self
 				.last_audio_resync
@@ -1254,19 +1287,26 @@ impl RealEngine {
 			let underrun = oak_audio::manager::instance()
 				.map(|m| m.take_output_underrun_frames())
 				.unwrap_or(0);
+			if underrun > 0 {
+				let q = oak_audio::manager::instance()
+					.map(|m| m.output_queued_frames())
+					.unwrap_or(-1);
+				audio_dbg(&format!("underrun +{underrun} frames (device queue {q})"));
+			}
 			if cooldown_ok && underrun > 480 {
-				if let Some(mut manager) = oak_audio::manager::instance() {
-					let _ = manager.clear_buffered_output();
-				}
-				st.reset(frame, chunk);
-				self.audio_playback = None;
+				let dropped = oak_audio::manager::instance()
+					.map(|m| m.drop_output_frames(underrun))
+					.unwrap_or(0);
+				audio_dbg(&format!(
+					"underrun heal: trimmed {dropped} stale frames (underrun {underrun}) at frame {frame}"
+				));
 				self.last_audio_resync = Some(std::time::Instant::now());
-				return;
 			}
 		}
 		// Push every rendered chunk to the output device in ts order (the
 		// device queue is the cushion that rides out UI stalls); chunks
 		// whose time already passed are dropped inside drain_ready.
+		let mut pushed = 0i32;
 		for buf in st.drain_ready(frame) {
 			if buf.sample_rate <= 0 || buf.channel_count <= 0 || buf.data.is_empty() {
 				continue;
@@ -1284,6 +1324,7 @@ impl RealEngine {
 					&bytes,
 					&mut [],
 				);
+				pushed += 1;
 				// M12 P1a: anchor the audio master clock at the first push of a
 				// play run. Recording the CURRENT output clock (not 0) keeps the
 				// anchor honest on a replay — the device has been padding
@@ -1306,6 +1347,18 @@ impl RealEngine {
 				}
 			}
 		}
+		if audio_dbg_enabled() {
+			let mut secs = -1.0;
+			let mut q = -1i64;
+			if let Some(manager) = oak_audio::manager::instance() {
+				let _ = manager.seconds(&mut secs);
+				q = manager.output_queued_frames();
+			}
+			audio_dbg(&format!(
+				"tick f={frame} secs={secs:.3} buf={} sub={submitted} push={pushed} q={q}",
+				st.buffered.len()
+			));
+		}
 	}
 
 	/// Stop program playback: clear the play flag and silence the audio
@@ -3529,6 +3582,24 @@ impl EngineGateway for RealEngine {
 	}
 
 	fn tick(&mut self, cx: &mut Context<Self>) {
+		// Keep the playback clocks on the sequence's actual rate. The
+		// clocks are created at engine init with the fallback rate
+		// (hd_1080p25), before any sequence is loaded; a sequence whose
+		// video params say otherwise (e.g. 29.97 from the config default)
+		// would otherwise play on a stale clock — the audio chunks are
+		// sized by the SEQUENCE time base while the playhead advances at
+		// the CLOCK rate, and a mismatch chronically underfeeds the
+		// output device (every few words a slice of silence).
+		let seq_rate = self.frame_rate();
+		for clock in [&self.source_clock, &self.program_clock] {
+			let stale = {
+				let r = &clock.read(cx).rate;
+				r.num != seq_rate.num || r.den != seq_rate.den
+			};
+			if stale {
+				clock.update(cx, |c, _cx| c.rate = seq_rate);
+			}
+		}
 		// Each clock loops at its own monitor's length: the program at the
 		// sequence length, the source at the selected footage's duration
 		// (the sequence length is wrong for footage playback — an empty
@@ -3569,6 +3640,12 @@ impl EngineGateway for RealEngine {
 						if length.0 > 0 && target >= length.0 {
 							target %= length.0;
 						}
+						let cur = self.clock_frame(Monitor::Program, cx).0;
+						if (target - cur).abs() > 2 {
+							audio_dbg(&format!(
+								"playhead reanchor jump {cur} -> {target} (secs {secs:.3}, anchor f{start_frame}@{start_secs:.3})"
+							));
+						}
 						let clock = self.program_clock.clone();
 						clock.update(cx, |clock, cx| {
 							// Re-anchor (not transport.seek): the next

crates/oak-audio/src/manager.rs

@@ -193,6 +193,18 @@ impl ManagerInner {
 		Ok(())
 	}
 
+	/// Frames currently queued for the output callback (diagnostics).
+	pub fn output_queued_frames(&self) -> i64 {
+		self.output_buffer.queued_frames()
+	}
+
+	/// Drop up to `frames` stale frames from the front of the output queue
+	/// (underrun resync without a full clear; see
+	/// [`PreviewAudioDevice::drop_front_frames`]). Returns frames dropped.
+	pub fn drop_output_frames(&self, frames: i64) -> i64 {
+		self.output_buffer.drop_front_frames(frames)
+	}
+
 	/// Read and reset the output underrun counter (frames the callback had
 	/// to zero-fill because the buffer was empty). The playback engine
 	/// polls this per tick and resyncs after an underrun: the zero-fill

crates/oak-audio/src/previewdevice.rs

@@ -176,6 +176,36 @@ impl PreviewAudioDevice {
 		self.output_frames_consumed.store(0, Ordering::Relaxed);
 	}
 
+	/// Frames currently queued for the output callback (diagnostics).
+	pub fn queued_frames(&self) -> i64 {
+		let inner = self.lock.lock().unwrap();
+		if inner.bytes_per_frame <= 0 {
+			return 0;
+		}
+		inner.buffer.len() as i64 / inner.bytes_per_frame as i64
+	}
+
+	/// Drop up to `frames` frames from the FRONT of the queued buffer,
+	/// returning the frames actually dropped. Underrun resync: zero-fill
+	/// advanced the output clock past this much queued content, so it
+	/// would all play late — trimming just the stale lead resyncs playback
+	/// WITHOUT the full clear + re-render storm a `clear()` causes (the
+	/// rest of the queue stays audible and the master-clock anchor stays
+	/// valid, since the anchor maps the clock to sequence frames and the
+	/// clock already advanced past the zero-fill).
+	pub fn drop_front_frames(&self, frames: i64) -> i64 {
+		if frames <= 0 {
+			return 0;
+		}
+		let mut inner = self.lock.lock().unwrap();
+		if inner.bytes_per_frame <= 0 {
+			return 0;
+		}
+		let bytes = (frames * inner.bytes_per_frame as i64).min(inner.buffer.len() as i64) as usize;
+		inner.buffer.drain(..bytes);
+		bytes as i64 / inner.bytes_per_frame as i64
+	}
+
 	/// Account for frames consumed by the output callback (including
 	/// underrun zero-fill).
 	pub fn add_output_frames(&self, frame_count: i64) {