Add log message to help analyze why echo likelihood > 1.1

webrtc/modules/audio_processing/residual_echo_detector.cc

 /*
  *  Copyright (c) 2016 The WebRTC project authors. All Rights Reserved.
  *
  *  Use of this source code is governed by a BSD-style license
  *  that can be found in the LICENSE file in the root of the source
  *  tree. An additional intellectual property rights grant can be found
  *  in the file PATENTS.  All contributing project authors may
  *  be found in the AUTHORS file in the root of the source tree.
  */
 
 #include "webrtc/modules/audio_processing/residual_echo_detector.h"
 
 #include <algorithm>
 #include <numeric>
 
 #include "webrtc/base/atomicops.h"
+#include "webrtc/base/logging.h"
 #include "webrtc/modules/audio_processing/audio_buffer.h"
 #include "webrtc/modules/audio_processing/logging/apm_data_dumper.h"
 #include "webrtc/system_wrappers/include/metrics.h"
 
 namespace {
 
 float Power(rtc::ArrayView<const float> input) {
   if (input.size() == 0) {
     return 0.f;
   }
@@ skipping 79 matching lines @@
 
   // Get the next capture value, update capture statistics and add the relevant
   // values to the buffers.
   const float capture_power = Power(capture_audio);
   capture_statistics_.Update(capture_power);
   const float capture_mean = capture_statistics_.mean();
   const float capture_std_deviation = capture_statistics_.std_deviation();
 
   // Update the covariance values and determine the new echo likelihood.
   echo_likelihood_ = 0.f;
+
+  int best_delay = -1;
   for (size_t delay = 0; delay < covariances_.size(); ++delay) {
     const size_t read_index =
         (kLookbackFrames + next_insertion_index_ - delay) % kLookbackFrames;
     RTC_DCHECK_LT(read_index, render_power_.size());
     covariances_[delay].Update(capture_power, capture_mean,
                                capture_std_deviation, render_power_[read_index],
                                render_power_mean_[read_index],
                                render_power_std_dev_[read_index]);
-    echo_likelihood_ = std::max(
-        echo_likelihood_, covariances_[delay].normalized_cross_correlation());
+    if (covariances_[delay].normalized_cross_correlation() > echo_likelihood_) {
+      echo_likelihood_ = covariances_[delay].normalized_cross_correlation();
+      best_delay = delay;

[peah-webrtc, 2017/05/17 04:26:15]

I guess that the assignment in line 129 may fail on some platforms, as the
result may overflow (right?) You probably should do a static cast, or use an
optional<size_t> instead (but that is probably more expensive).

[ivoc, 2017/05/17 09:28:07]

I don't think it's possible for this assignment to fail on any platform. The
"delay" variable runs from 0 to kLookbackFrames, which is 650 (covariances_ has
a fixed size), which can easily be represented as an int. Since this is only a
temporary change and this is a simple solution, I would prefer to leave it like
this if that's okay with you.

[peah-webrtc, 2017/05/17 09:38:07]

Sorry, I meant that the compiler will complain. As you mention, the assignment
will not actually overflow. That is why I suggested the static_cast.

[ivoc, 2017/05/17 11:28:08]

Ah, that's a good point. Added static_cast.

+    }
   }
+  // This is a temporary log message to help find the underlying cause for echo
+  // likelihoods > 1.0.
+  // TODO(ivoc): Remove once the issue is resolved.
+  if (echo_likelihood_ > 1.1f) {

[peah-webrtc, 2017/05/17 04:26:15]

Not fully sure about the static variable. I'd rather have chosen to have a
member variable instead, but I cannot see anything in the style guide that
forbids that.

[ivoc, 2017/05/17 09:28:07]

The reason I chose a static variable is so that all of the code for this log
message is localized here. But you're right that a member variable is a nicer
solution, so I changed this to be a member variable instead.

+    static int log_counter = 0;
+    // Make sure we don't spam the log.
+    if (log_counter < 5 && best_delay != -1) {
+      const size_t read_index =
+          (kLookbackFrames + next_insertion_index_ - best_delay) %

[peah-webrtc, 2017/05/17 04:26:15]

I just want to point out that the % operator involves a division. Please
consider using a conditional instead.

[ivoc, 2017/05/17 09:28:07]

You're right that divisions are slow, but this piece of code can be executed at
most 5 times, so it is not very performance critical. I also think that actually
logging the message will be much slower than a single division.

I did change this to an if statement instead of the division.

+          kLookbackFrames;
+      RTC_DCHECK_LT(read_index, render_power_.size());
+      LOG_F(LS_ERROR) << "Unexpected high echo likelihood value: "

[peah-webrtc, 2017/05/17 04:26:15]

Please consider using j-son type formatting, as in level_controller.cc. That
will simplify machine parsing of the log. That is a feedback that I've gotten
which I think makes sense, but in this case is probably not super necessary as
the logging is temporary. However, as you are listing a lot of variable values,
json-style may make sense in particular for that.

[ivoc, 2017/05/17 09:28:07]

That seems like a good idea, done.

+                      << echo_likelihood_ << ", delay: " << best_delay
+                      << ", covariance: "
+                      << covariances_[best_delay].covariance()
+                      << ", last capture power: " << capture_power
+                      << ", capture mean: " << capture_mean
+                      << ", capture_std_deviation: " << capture_std_deviation
+                      << ", last render power: " << render_power_[read_index]
+                      << ", render mean: " << render_power_mean_[read_index]
+                      << ", render std_deviation: "
+                      << render_power_std_dev_[read_index]
+                      << ", reliability: " << reliability_;
+      log_counter++;
+    }
+  }
+
   reliability_ = (1.0f - kAlpha) * reliability_ + kAlpha * 1.0f;
   echo_likelihood_ *= reliability_;
   // This is a temporary fix to prevent echo likelihood values > 1.0.
   // TODO(ivoc): Find the root cause of this issue and fix it.
   echo_likelihood_ = std::min(echo_likelihood_, 1.0f);
   int echo_percentage = static_cast<int>(echo_likelihood_ * 100);
   RTC_HISTOGRAM_COUNTS("WebRTC.Audio.ResidualEchoDetector.EchoLikelihood",
                        echo_percentage, 0, 100, 100 /* number of bins */);
 
   // Update the buffer of recent likelihood values.
@@ skipping 22 matching lines @@
 
 void ResidualEchoDetector::PackRenderAudioBuffer(
     AudioBuffer* audio,
     std::vector<float>* packed_buffer) {
   packed_buffer->clear();
   packed_buffer->insert(packed_buffer->end(), audio->channels_f()[0],
                         audio->channels_f()[0] + audio->num_frames());
 }
 
 }  // namespace webrtc