diff --git a/crates/wzp-native/cpp/oboe_bridge.cpp b/crates/wzp-native/cpp/oboe_bridge.cpp index cf8b79f..c8c4ece 100644 --- a/crates/wzp-native/cpp/oboe_bridge.cpp +++ b/crates/wzp-native/cpp/oboe_bridge.cpp @@ -83,6 +83,11 @@ static std::atomic g_playout_latency_ms{0.0f}; class CaptureCallback : public oboe::AudioStreamDataCallback { public: + uint64_t calls = 0; + uint64_t total_frames = 0; + uint64_t total_written = 0; + uint64_t ring_full_drops = 0; + oboe::DataCallbackResult onAudioReady( oboe::AudioStream* stream, void* audioData, @@ -102,6 +107,32 @@ public: g_rings.capture_write_idx, g_rings.capture_read_idx, src, to_write); } + total_frames += numFrames; + total_written += to_write; + if (to_write < numFrames) { + ring_full_drops += (numFrames - to_write); + } + + // Sample-range probe on the FIRST callback to prove we get real audio + if (calls == 0 && numFrames > 0) { + int16_t lo = src[0], hi = src[0]; + int32_t sumsq = 0; + for (int32_t i = 0; i < numFrames; i++) { + if (src[i] < lo) lo = src[i]; + if (src[i] > hi) hi = src[i]; + sumsq += (int32_t)src[i] * (int32_t)src[i]; + } + int32_t rms = (int32_t) (numFrames > 0 ? (int32_t)__builtin_sqrt((double)sumsq / (double)numFrames) : 0); + LOGI("capture cb#0: numFrames=%d sample_range=[%d..%d] rms=%d to_write=%d", + numFrames, lo, hi, rms, to_write); + } + // Heartbeat every 50 callbacks (~1s at 20ms/burst) + calls++; + if ((calls % 50) == 0) { + LOGI("capture heartbeat: calls=%llu numFrames=%d ring_avail_write=%d to_write=%d full_drops=%llu total_written=%llu", + (unsigned long long)calls, numFrames, avail, to_write, + (unsigned long long)ring_full_drops, (unsigned long long)total_written); + } // Update latency estimate auto result = stream->calculateLatencyMillis(); @@ -120,6 +151,12 @@ public: class PlayoutCallback : public oboe::AudioStreamDataCallback { public: + uint64_t calls = 0; + uint64_t total_frames = 0; + uint64_t total_played_real = 0; + uint64_t underrun_frames = 0; + uint64_t nonempty_calls = 0; + oboe::DataCallbackResult onAudioReady( oboe::AudioStream* stream, void* audioData, @@ -140,10 +177,43 @@ public: ring_read(g_rings.playout_buf, g_rings.playout_capacity, g_rings.playout_write_idx, g_rings.playout_read_idx, dst, to_read); + nonempty_calls++; } // Fill remainder with silence on underrun if (to_read < numFrames) { memset(dst + to_read, 0, (numFrames - to_read) * sizeof(int16_t)); + underrun_frames += (numFrames - to_read); + } + total_frames += numFrames; + total_played_real += to_read; + + // First callback: log requested config + prove we're being called + if (calls == 0) { + LOGI("playout cb#0: numFrames=%d ring_avail_read=%d to_read=%d", + numFrames, avail, to_read); + } + // On the first callback that actually has data, log the sample range + // so we can tell if the samples coming out of the ring look like real + // audio vs constant-zeroes vs garbage. + if (to_read > 0 && nonempty_calls == 1) { + int16_t lo = dst[0], hi = dst[0]; + int32_t sumsq = 0; + for (int32_t i = 0; i < to_read; i++) { + if (dst[i] < lo) lo = dst[i]; + if (dst[i] > hi) hi = dst[i]; + sumsq += (int32_t)dst[i] * (int32_t)dst[i]; + } + int32_t rms = (to_read > 0) ? (int32_t)__builtin_sqrt((double)sumsq / (double)to_read) : 0; + LOGI("playout FIRST nonempty read: to_read=%d sample_range=[%d..%d] rms=%d", + to_read, lo, hi, rms); + } + // Heartbeat every 50 callbacks (~1s at 20ms/burst) + calls++; + if ((calls % 50) == 0) { + LOGI("playout heartbeat: calls=%llu nonempty=%llu numFrames=%d ring_avail_read=%d to_read=%d underrun_frames=%llu total_played_real=%llu", + (unsigned long long)calls, (unsigned long long)nonempty_calls, + numFrames, avail, to_read, + (unsigned long long)underrun_frames, (unsigned long long)total_played_real); } // Update latency estimate @@ -193,6 +263,15 @@ int wzp_oboe_start(const WzpOboeConfig* config, const WzpOboeRings* rings) { LOGE("Failed to open capture stream: %s", oboe::convertToText(result)); return -2; } + LOGI("capture stream opened: actualSR=%d actualCh=%d actualFormat=%d actualFramesPerBurst=%d actualFramesPerDataCallback=%d bufferCapacityInFrames=%d sharing=%d perfMode=%d", + g_capture_stream->getSampleRate(), + g_capture_stream->getChannelCount(), + (int)g_capture_stream->getFormat(), + g_capture_stream->getFramesPerBurst(), + g_capture_stream->getFramesPerDataCallback(), + g_capture_stream->getBufferCapacityInFrames(), + (int)g_capture_stream->getSharingMode(), + (int)g_capture_stream->getPerformanceMode()); // Build playout stream // @@ -224,6 +303,15 @@ int wzp_oboe_start(const WzpOboeConfig* config, const WzpOboeRings* rings) { g_capture_stream.reset(); return -3; } + LOGI("playout stream opened: actualSR=%d actualCh=%d actualFormat=%d actualFramesPerBurst=%d actualFramesPerDataCallback=%d bufferCapacityInFrames=%d sharing=%d perfMode=%d", + g_playout_stream->getSampleRate(), + g_playout_stream->getChannelCount(), + (int)g_playout_stream->getFormat(), + g_playout_stream->getFramesPerBurst(), + g_playout_stream->getFramesPerDataCallback(), + g_playout_stream->getBufferCapacityInFrames(), + (int)g_playout_stream->getSharingMode(), + (int)g_playout_stream->getPerformanceMode()); g_running.store(true, std::memory_order_release); diff --git a/crates/wzp-native/src/lib.rs b/crates/wzp-native/src/lib.rs index 0d85cc9..46682dc 100644 --- a/crates/wzp-native/src/lib.rs +++ b/crates/wzp-native/src/lib.rs @@ -172,6 +172,8 @@ struct AudioBackend { capture: RingBuffer, playout: RingBuffer, started: std::sync::Mutex, + /// Per-write logging throttle counter for wzp_native_audio_write_playout. + playout_write_log_count: std::sync::atomic::AtomicU64, } static BACKEND: OnceLock<&'static AudioBackend> = OnceLock::new(); @@ -182,6 +184,7 @@ fn backend() -> &'static AudioBackend { capture: RingBuffer::new(RING_CAPACITY), playout: RingBuffer::new(RING_CAPACITY), started: std::sync::Mutex::new(false), + playout_write_log_count: std::sync::atomic::AtomicU64::new(0), })) }) } @@ -258,9 +261,56 @@ pub unsafe extern "C" fn wzp_native_audio_write_playout(input: *const i16, in_le return 0; } let slice = unsafe { std::slice::from_raw_parts(input, in_len) }; - backend().playout.write(slice) + let b = backend(); + let before_w = b.playout.write_idx.load(std::sync::atomic::Ordering::Relaxed); + let before_r = b.playout.read_idx.load(std::sync::atomic::Ordering::Relaxed); + let written = b.playout.write(slice); + // First few writes: log ring state + sample range so we can compare what + // engine.rs hands us to what the C++ playout callback reads. + let first_writes = b.playout_write_log_count.fetch_add(1, std::sync::atomic::Ordering::Relaxed); + if first_writes < 3 || first_writes % 50 == 0 { + let (mut lo, mut hi, mut sumsq) = (i16::MAX, i16::MIN, 0i64); + for &s in slice.iter() { + if s < lo { lo = s; } + if s > hi { hi = s; } + sumsq += (s as i64) * (s as i64); + } + let rms = (sumsq as f64 / slice.len() as f64).sqrt() as i32; + let avail_w_after = b.playout.available_write(); + let avail_r_after = b.playout.available_read(); + let msg = format!( + "playout WRITE #{first_writes}: in_len={} written={} range=[{lo}..{hi}] rms={rms} before_w={before_w} before_r={before_r} avail_read_after={avail_r_after} avail_write_after={avail_w_after}", + slice.len(), written + ); + unsafe { + android_log(msg.as_str()); + } + } + written } +// Minimal android logcat shim so we can print from the cdylib without pulling +// in android_logger crate (which would add another dep that has to build with +// cargo-ndk). Uses libc's __android_log_print via extern linkage. +#[cfg(target_os = "android")] +unsafe extern "C" { + fn __android_log_write(prio: i32, tag: *const u8, text: *const u8) -> i32; +} + +#[cfg(target_os = "android")] +unsafe fn android_log(msg: &str) { + // ANDROID_LOG_INFO = 4. Tag and text must be NUL-terminated. + let tag = b"wzp-native\0"; + let mut buf = Vec::with_capacity(msg.len() + 1); + buf.extend_from_slice(msg.as_bytes()); + buf.push(0); + unsafe { __android_log_write(4, tag.as_ptr(), buf.as_ptr()); } +} + +#[cfg(not(target_os = "android"))] +#[allow(dead_code)] +unsafe fn android_log(_msg: &str) {} + /// Current capture latency reported by Oboe, in milliseconds. Returns /// NaN / 0.0 if the stream isn't running. #[unsafe(no_mangle)] diff --git a/desktop/src-tauri/src/engine.rs b/desktop/src-tauri/src/engine.rs index 64e91bb..8d82d8a 100644 --- a/desktop/src-tauri/src/engine.rs +++ b/desktop/src-tauri/src/engine.rs @@ -351,11 +351,34 @@ impl CallEngine { Ok(n) => { last_decode_n = n; decoded_frames += 1; + // Log sample range for the first few decoded frames and periodically + if decoded_frames <= 3 || decoded_frames % 100 == 0 { + let slice = &pcm[..n]; + let (mut lo, mut hi, mut sumsq) = (i16::MAX, i16::MIN, 0i64); + for &s in slice.iter() { + if s < lo { lo = s; } + if s > hi { hi = s; } + sumsq += (s as i64) * (s as i64); + } + let rms = (sumsq as f64 / n as f64).sqrt() as i32; + info!( + decoded_frames, + n, + sample_lo = lo, + sample_hi = hi, + rms, + codec = ?current_codec, + "recv: decoded PCM sample range" + ); + } agc.process_frame(&mut pcm[..n]); if !recv_spk.load(Ordering::Relaxed) { let w = crate::wzp_native::audio_write_playout(&pcm[..n]); last_written = w; written_samples = written_samples.saturating_add(w as u64); + if w < n && decoded_frames <= 10 { + tracing::warn!(n, w, "recv: partial playout write (ring nearly full)"); + } } } Err(e) => { @@ -378,6 +401,22 @@ impl CallEngine { } Err(_) => {} } + + // Heartbeat every 2s with decode+playout state + if heartbeat.elapsed() >= std::time::Duration::from_secs(2) { + let fr = recv_fr.load(Ordering::Relaxed); + info!( + recv_fr = fr, + decoded_frames, + last_decode_n, + last_written, + written_samples, + decode_errs, + codec = ?current_codec, + "recv heartbeat (android)" + ); + heartbeat = std::time::Instant::now(); + } } });