fix(audio): throttled debug logs (#16172)

* fix(audio): throttled debug logs

Signed-off-by: fufesou <linlong1266@gmail.com>

* fix(audio): preserve contention counts across throttled reports

Signed-off-by: fufesou <linlong1266@gmail.com>

---------

Signed-off-by: fufesou <linlong1266@gmail.com>

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)| {

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<f32>,
 }
 
-#[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 self.contentions.load(Ordering::Relaxed) != 0
-        if contentions != 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) {

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);
+    }
+}

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),