AEC3: Add support for logging warnings on delay buffer changes

This reintroduces the WARNING log level of a previous CL [1],
via a default-off config flag.

[1] https://webrtc-review.googlesource.com/c/src/+/148528

Bug: None
Change-Id: Ica8583cbb24a1611cfc684ae02d5a0f582004024
Reviewed-on: https://webrtc-review.googlesource.com/c/src/+/156566
Commit-Queue: Sam Zackrisson <saza@webrtc.org>
Reviewed-by: Per Åhgren <peah@webrtc.org>
Cr-Commit-Position: refs/heads/master@{#29489}

api/audio/echo_canceller3_config.h

@@ -48,6 +48,7 @@ struct RTC_EXPORT EchoCanceller3Config {
     } delay_selection_thresholds = {5, 20};
     bool use_external_delay_estimator = false;
     bool downmix_before_delay_estimation = true;
+    bool log_warning_on_delay_changes = false;
   } delay;
 
   struct Filter {

api/audio/echo_canceller3_config_json.cc

@@ -173,6 +173,8 @@ void Aec3ConfigFromJsonString(absl::string_view json_string,
               &cfg.delay.use_external_delay_estimator);
     ReadParam(section, "downmix_before_delay_estimation",
               &cfg.delay.downmix_before_delay_estimation);
+    ReadParam(section, "log_warning_on_delay_changes",
+              &cfg.delay.log_warning_on_delay_changes);
   }
 
   if (rtc::GetValueFromJsonObject(aec3_root, "filter", &section)) {
@@ -361,7 +363,10 @@ std::string Aec3ConfigToJsonString(const EchoCanceller3Config& config) {
   ost << "\"use_external_delay_estimator\": "
       << (config.delay.use_external_delay_estimator ? "true" : "false") << ",";
   ost << "\"downmix_before_delay_estimation\": "
-      << (config.delay.downmix_before_delay_estimation ? "true" : "false");
+      << (config.delay.downmix_before_delay_estimation ? "true" : "false")
+      << ",";
+  ost << "\"log_warning_on_delay_changes\": "
+      << (config.delay.log_warning_on_delay_changes ? "true" : "false");
   ost << "},";
 
   ost << "\"filter\": {";

api/audio/test/echo_canceller3_config_json_unittest.cc

@@ -18,6 +18,7 @@ namespace webrtc {
 TEST(EchoCanceller3JsonHelpers, ToStringAndParseJson) {
   EchoCanceller3Config cfg;
   cfg.delay.down_sampling_factor = 1u;
+  cfg.delay.log_warning_on_delay_changes = true;
   cfg.filter.shadow_initial.length_blocks = 7u;
   cfg.suppressor.normal_tuning.mask_hf.enr_suppress = .5f;
   std::string json_string = Aec3ConfigToJsonString(cfg);
@@ -34,6 +35,8 @@ TEST(EchoCanceller3JsonHelpers, ToStringAndParseJson) {
   // Expect changed values to carry through the transformation.
   EXPECT_EQ(cfg.delay.down_sampling_factor,
             cfg_transformed.delay.down_sampling_factor);
+  EXPECT_EQ(cfg.delay.log_warning_on_delay_changes,
+            cfg_transformed.delay.log_warning_on_delay_changes);
   EXPECT_EQ(cfg.filter.shadow_initial.length_blocks,
             cfg_transformed.filter.shadow_initial.length_blocks);
   EXPECT_EQ(cfg.suppressor.normal_tuning.mask_hf.enr_suppress,

modules/audio_processing/aec3/block_processor.cc

@@ -171,8 +171,11 @@ void BlockProcessorImpl::ProcessCapture(
       bool delay_change =
           render_buffer_->AlignFromDelay(estimated_delay_->delay);
       if (delay_change) {
-        RTC_LOG(LS_INFO) << "Delay changed to " << estimated_delay_->delay
+        rtc::LoggingSeverity log_level =
-                         << " at block " << capture_call_counter_;
+            config_.delay.log_warning_on_delay_changes ? rtc::LS_WARNING
+                                                       : rtc::LS_INFO;
+        RTC_LOG_V(log_level) << "Delay changed to " << estimated_delay_->delay
+                             << " at block " << capture_call_counter_;
         echo_path_variability.delay_change =
             EchoPathVariability::DelayAdjustment::kNewDetectedDelay;
       }

modules/audio_processing/aec3/echo_remover.cc

@@ -334,7 +334,11 @@ void EchoRemoverImpl::ProcessCapture(
       if (gain_change_hangover_ == 0) {
         constexpr int kMaxBlocksPerFrame = 3;
         gain_change_hangover_ = kMaxBlocksPerFrame;
-        RTC_LOG(LS_INFO) << "Gain change detected at block " << block_counter_;
+        rtc::LoggingSeverity log_level =
+            config_.delay.log_warning_on_delay_changes ? rtc::LS_WARNING
+                                                       : rtc::LS_INFO;
+        RTC_LOG_V(log_level)
+            << "Gain change detected at block " << block_counter_;
       } else {
         echo_path_variability.gain_change = false;
       }

modules/audio_processing/aec3/render_delay_buffer.cc

@@ -70,6 +70,7 @@ class RenderDelayBufferImpl final : public RenderDelayBuffer {
   std::unique_ptr<ApmDataDumper> data_dumper_;
   const Aec3Optimization optimization_;
   const EchoCanceller3Config config_;
+  const rtc::LoggingSeverity delay_log_level_;
   size_t down_sampling_factor_;
   const int sub_block_size_;
   BlockBuffer blocks_;
@@ -117,6 +118,9 @@ RenderDelayBufferImpl::RenderDelayBufferImpl(const EchoCanceller3Config& config,
           new ApmDataDumper(rtc::AtomicOps::Increment(&instance_count_))),
       optimization_(DetectOptimization()),
       config_(config),
+      delay_log_level_(config_.delay.log_warning_on_delay_changes
+                           ? rtc::LS_WARNING
+                           : rtc::LS_INFO),
       down_sampling_factor_(config.delay.down_sampling_factor),
       sub_block_size_(static_cast<int>(down_sampling_factor_ > 0
                                            ? kBlockSize / down_sampling_factor_
@@ -199,7 +203,7 @@ RenderDelayBuffer::BufferingEvent RenderDelayBufferImpl::Insert(
     } else {
       if (++num_api_calls_in_a_row_ > max_observed_jitter_) {
         max_observed_jitter_ = num_api_calls_in_a_row_;
-        RTC_LOG(LS_INFO)
+        RTC_LOG_V(delay_log_level_)
             << "New max number api jitter observed at render block "
             << render_call_counter_ << ":  " << num_api_calls_in_a_row_
             << " blocks";
@@ -245,7 +249,7 @@ RenderDelayBufferImpl::PrepareCaptureProcessing() {
     } else {
       if (++num_api_calls_in_a_row_ > max_observed_jitter_) {
         max_observed_jitter_ = num_api_calls_in_a_row_;
-        RTC_LOG(LS_INFO)
+        RTC_LOG_V(delay_log_level_)
             << "New max number api jitter observed at capture block "
             << capture_call_counter_ << ":  " << num_api_calls_in_a_row_
             << " blocks";
@@ -256,15 +260,15 @@ RenderDelayBufferImpl::PrepareCaptureProcessing() {
   if (DetectExcessRenderBlocks()) {
     // Too many render blocks compared to capture blocks. Risk of delay ending
     // up before the filter used by the delay estimator.
-    RTC_LOG(LS_INFO) << "Excess render blocks detected at block "
+    RTC_LOG_V(delay_log_level_)
-                     << capture_call_counter_;
+        << "Excess render blocks detected at block " << capture_call_counter_;
     Reset();
     event = BufferingEvent::kRenderOverrun;
   } else if (RenderUnderrun()) {
     // Don't increment the read indices of the low rate buffer if there is a
     // render underrun.
-    RTC_LOG(LS_INFO) << "Render buffer underrun detected at block "
+    RTC_LOG_V(delay_log_level_)
-                     << capture_call_counter_;
+        << "Render buffer underrun detected at block " << capture_call_counter_;
     IncrementReadIndices();
     // Incrementing the buffer index without increasing the low rate buffer
     // index means that the delay is reduced by one.
@@ -293,9 +297,10 @@ bool RenderDelayBufferImpl::AlignFromDelay(size_t delay) {
   if (!external_audio_buffer_delay_verified_after_reset_ &&
       external_audio_buffer_delay_ && delay_) {
     int difference = static_cast<int>(delay) - static_cast<int>(*delay_);
-    RTC_LOG(LS_INFO) << "Mismatch between first estimated delay after reset "
+    RTC_LOG_V(delay_log_level_)
-                        "and externally reported audio buffer delay: "
+        << "Mismatch between first estimated delay after reset "
-                     << difference << " blocks";
+           "and externally reported audio buffer delay: "
+        << difference << " blocks";
     external_audio_buffer_delay_verified_after_reset_ = true;
   }
   if (delay_ && *delay_ == delay) {
@@ -315,7 +320,7 @@ bool RenderDelayBufferImpl::AlignFromDelay(size_t delay) {
 
 void RenderDelayBufferImpl::SetAudioBufferDelay(size_t delay_ms) {
   if (!external_audio_buffer_delay_) {
-    RTC_LOG(LS_INFO)
+    RTC_LOG_V(delay_log_level_)
         << "Receiving a first externally reported audio buffer delay of "
         << delay_ms << " ms.";
   }
@@ -347,7 +352,8 @@ int RenderDelayBufferImpl::ComputeDelay() const {
 
 // Set the read indices according to the delay.
 void RenderDelayBufferImpl::ApplyTotalDelay(int delay) {
-  RTC_LOG(LS_INFO) << "Applying total delay of " << delay << " blocks.";
+  RTC_LOG_V(delay_log_level_)
+      << "Applying total delay of " << delay << " blocks.";
   blocks_.read = blocks_.OffsetIndex(blocks_.write, -delay);
   spectra_.read = spectra_.OffsetIndex(spectra_.write, delay);
   ffts_.read = ffts_.OffsetIndex(ffts_.write, delay);