From ffc84527309d73c2779ffad9b3910a83d03b5f06 Mon Sep 17 00:00:00 2001 From: Sam Zackrisson Date: Tue, 15 Oct 2019 13:43:02 +0200 Subject: [PATCH] AEC3: Add support for logging warnings on delay buffer changes MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 Reviewed-by: Per Åhgren Cr-Commit-Position: refs/heads/master@{#29489} --- api/audio/echo_canceller3_config.h | 1 + api/audio/echo_canceller3_config_json.cc | 7 ++++- .../echo_canceller3_config_json_unittest.cc | 3 ++ .../audio_processing/aec3/block_processor.cc | 7 +++-- modules/audio_processing/aec3/echo_remover.cc | 6 +++- .../aec3/render_delay_buffer.cc | 28 +++++++++++-------- 6 files changed, 37 insertions(+), 15 deletions(-) diff --git a/api/audio/echo_canceller3_config.h b/api/audio/echo_canceller3_config.h index 7c8ca1b4f7..efd6bb5654 100644 --- a/api/audio/echo_canceller3_config.h +++ b/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 { diff --git a/api/audio/echo_canceller3_config_json.cc b/api/audio/echo_canceller3_config_json.cc index c17497a335..28aec9eea7 100644 --- a/api/audio/echo_canceller3_config_json.cc +++ b/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", §ion)) { @@ -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\": {"; diff --git a/api/audio/test/echo_canceller3_config_json_unittest.cc b/api/audio/test/echo_canceller3_config_json_unittest.cc index 5e98426602..5274a0b75e 100644 --- a/api/audio/test/echo_canceller3_config_json_unittest.cc +++ b/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, diff --git a/modules/audio_processing/aec3/block_processor.cc b/modules/audio_processing/aec3/block_processor.cc index c02994b966..fa9c7b3fb3 100644 --- a/modules/audio_processing/aec3/block_processor.cc +++ b/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 - << " at block " << capture_call_counter_; + rtc::LoggingSeverity log_level = + 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; } diff --git a/modules/audio_processing/aec3/echo_remover.cc b/modules/audio_processing/aec3/echo_remover.cc index 7cec47cca0..a05a38987c 100644 --- a/modules/audio_processing/aec3/echo_remover.cc +++ b/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; } diff --git a/modules/audio_processing/aec3/render_delay_buffer.cc b/modules/audio_processing/aec3/render_delay_buffer.cc index bcaa566c0f..6eb32e4fb3 100644 --- a/modules/audio_processing/aec3/render_delay_buffer.cc +++ b/modules/audio_processing/aec3/render_delay_buffer.cc @@ -70,6 +70,7 @@ class RenderDelayBufferImpl final : public RenderDelayBuffer { std::unique_ptr 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(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 " - << capture_call_counter_; + RTC_LOG_V(delay_log_level_) + << "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 " - << capture_call_counter_; + RTC_LOG_V(delay_log_level_) + << "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(delay) - static_cast(*delay_); - RTC_LOG(LS_INFO) << "Mismatch between first estimated delay after reset " - "and externally reported audio buffer delay: " - << difference << " blocks"; + RTC_LOG_V(delay_log_level_) + << "Mismatch between first estimated delay after reset " + "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);