From 9b5f3428397c0812d07a6af112db43582016a4bf Mon Sep 17 00:00:00 2001 From: fufesou Date: Mon, 14 Sep 2026 12:26:23 +0800 Subject: [PATCH] fix(audio): throttled debug logs (#16172) * fix(audio): throttled debug logs Signed-off-by: fufesou * fix(audio): preserve contention counts across throttled reports Signed-off-by: fufesou --------- Signed-off-by: fufesou --- src/client.rs | 6 ++- src/client/audio_playback.rs | 23 ++++++++-- src/client/audio_playback_tests.rs | 46 ++++++++++++++++++- .../audio_service/audio_capture_encoder.rs | 2 +- 4 files changed, 69 insertions(+), 8 deletions(-) diff --git a/src/client.rs b/src/client.rs index cc10aa858..8138fed8b 100644 --- a/src/client.rs +++ b/src/client.rs @@ -2250,7 +2250,9 @@ impl AudioBuffer { let occupied = lock.occupied_len(); drop(lock); if let Some((discarded, generation)) = discard { - log::debug!( + hbb_common::throttled_log!( + audio_playback::AUDIO_PLAYBACK_LOG_INTERVAL, + debug, "Audio buffer capacity discard: samples={discarded}, generation={generation}" ); } @@ -2441,7 +2443,7 @@ impl AudioHandler { } #[cfg(target_os = "linux")] if self.simple.is_none() { - log::debug!("PulseAudio simple binding does not exists"); + log::trace!("PulseAudio simple binding does not exists"); return; } self.audio_decoder.as_mut().map(|(d, buffer)| { diff --git a/src/client/audio_playback.rs b/src/client/audio_playback.rs index 8e2cb0894..656533c5e 100644 --- a/src/client/audio_playback.rs +++ b/src/client/audio_playback.rs @@ -1,4 +1,4 @@ -use hbb_common::{log, thiserror}; +use hbb_common::{log, log_throttle::LogThrottle, thiserror}; use ringbuf::{ring_buffer::RbBase, Rb}; use std::sync::{ atomic::{AtomicBool, AtomicUsize, Ordering}, @@ -6,6 +6,8 @@ use std::sync::{ }; pub(super) const UNDERRUN_DECLICK_MS: usize = 5; +pub(super) const AUDIO_PLAYBACK_LOG_INTERVAL: std::time::Duration = + std::time::Duration::from_secs(5); const MILLISECONDS_PER_SECOND: usize = 1_000; #[derive(Clone, Copy, Debug, PartialEq, Eq)] @@ -36,17 +38,30 @@ pub(super) struct AudioPlaybackRecovery { output_frame: Vec, } -#[derive(Default)] pub(super) struct AudioPlaybackStatus { pub(super) ready: AtomicBool, contentions: AtomicUsize, + contention_log_throttle: LogThrottle, buffer_poisoned: AtomicBool, } +impl Default for AudioPlaybackStatus { + fn default() -> Self { + Self { + ready: AtomicBool::new(false), + contentions: AtomicUsize::new(0), + contention_log_throttle: LogThrottle::new(AUDIO_PLAYBACK_LOG_INTERVAL), + buffer_poisoned: AtomicBool::new(false), + } + } +} + impl AudioPlaybackStatus { pub(super) fn report_errors(&self) { - let contentions = self.contentions.swap(0, Ordering::Relaxed); - if contentions != 0 { + if self.contentions.load(Ordering::Relaxed) != 0 + && self.contention_log_throttle.due().is_some() + { + let contentions = self.contentions.swap(0, Ordering::Relaxed); log::debug!("Audio playback PCM buffer contention: callbacks={contentions}"); } if self.buffer_poisoned.swap(false, Ordering::Relaxed) { diff --git a/src/client/audio_playback_tests.rs b/src/client/audio_playback_tests.rs index ce528a732..bbe3e1646 100644 --- a/src/client/audio_playback_tests.rs +++ b/src/client/audio_playback_tests.rs @@ -1,4 +1,7 @@ -use super::{AudioPlaybackConfig, AudioPlaybackError, AudioPlaybackRecovery, AudioPlaybackWriter}; +use super::{ + AudioPlaybackConfig, AudioPlaybackError, AudioPlaybackRecovery, AudioPlaybackStatus, + AudioPlaybackWriter, +}; use ringbuf::{ring_buffer::RbBase, Rb}; use std::{ sync::{atomic::Ordering, mpsc, Arc, Mutex}, @@ -216,3 +219,44 @@ fn poisoned_playback_buffer_reports_once_without_panicking_in_the_callback() { assert_eq!(writer.status.contentions.load(Ordering::Relaxed), 0); assert!(!writer.status.ready.load(Ordering::Acquire)); } + +#[test] +fn contention_counts_accumulate_until_the_next_report() { + let status = AudioPlaybackStatus::default(); + status.report_errors(); + status.contentions.fetch_add(1, Ordering::Relaxed); + status.report_errors(); + assert_eq!(status.contentions.load(Ordering::Relaxed), 0); + + let mut total = 0; + for callbacks in [3, 7, 2] { + total += callbacks; + status.contentions.fetch_add(callbacks, Ordering::Relaxed); + status.report_errors(); + assert_eq!(status.contentions.load(Ordering::Relaxed), total); + } + status.buffer_poisoned.store(true, Ordering::Relaxed); + status.report_errors(); + assert!(!status.buffer_poisoned.load(Ordering::Relaxed)); + assert_eq!(status.contentions.load(Ordering::Relaxed), total); + + std::thread::sleep(super::AUDIO_PLAYBACK_LOG_INTERVAL); + status.report_errors(); + assert_eq!(status.contentions.load(Ordering::Relaxed), 0); +} + +#[test] +fn contention_reporting_is_independent_between_playbacks() { + let first = AudioPlaybackStatus::default(); + let second = AudioPlaybackStatus::default(); + for status in [&first, &second] { + status.contentions.fetch_add(1, Ordering::Relaxed); + status.report_errors(); + assert_eq!(status.contentions.load(Ordering::Relaxed), 0); + } + for status in [&first, &second] { + status.contentions.fetch_add(1, Ordering::Relaxed); + status.report_errors(); + assert_eq!(status.contentions.load(Ordering::Relaxed), 1); + } +} diff --git a/src/server/audio_service/audio_capture_encoder.rs b/src/server/audio_service/audio_capture_encoder.rs index f5f8b3722..e090c9f2c 100644 --- a/src/server/audio_service/audio_capture_encoder.rs +++ b/src/server/audio_service/audio_capture_encoder.rs @@ -87,7 +87,7 @@ impl CaptureStatsReporter { return; } let stats = std::mem::take(&mut self.pending); - log::debug!( + log::trace!( "Audio capture PCM handoff stats: observed_max_queued_packets={}, approx_queued_audio_ms={}, capacity_packets={}", stats.max_queued_packets, stats.max_queued_packets.saturating_mul(CAPTURE_PACKET_MS),