Adds logging of native audio levels and UMA stats to track issues

webrtc/modules/audio_device/audio_device_buffer.cc

Index: webrtc/modules/audio_device/audio_device_buffer.cc
diff --git a/webrtc/modules/audio_device/audio_device_buffer.cc b/webrtc/modules/audio_device/audio_device_buffer.cc
index d157c1cb1ae661483675e18411c0bd57d6a6d449..e3250d83f35a82b735f669e982be2b4997af4d34 100644
--- a/webrtc/modules/audio_device/audio_device_buffer.cc
+++ b/webrtc/modules/audio_device/audio_device_buffer.cc
@@ -18,7 +18,9 @@
 #include "webrtc/base/logging.h"
 #include "webrtc/base/format_macros.h"
 #include "webrtc/base/timeutils.h"
+#include "webrtc/common_audio/signal_processing/include/signal_processing_library.h"
 #include "webrtc/modules/audio_device/audio_device_config.h"
+#include "webrtc/system_wrappers/include/metrics.h"
 
 namespace webrtc {
 
@@ -59,7 +61,10 @@ AudioDeviceBuffer::AudioDeviceBuffer()
       last_rec_samples_(0),
       play_samples_(0),
       last_play_samples_(0),
-      last_log_stat_time_(0) {
+      last_log_stat_time_(0),
+      max_rec_level_(0),
+      max_play_level_(0),
+      num_rec_level_is_zero_(0) {
   LOG(INFO) << "AudioDeviceBuffer::ctor";
 }
 
@@ -84,6 +89,16 @@ AudioDeviceBuffer::~AudioDeviceBuffer() {
     LOG(INFO) << "average: "
              << static_cast<float>(total_diff_time) / num_measurements;
   }
+
+  // Add UMA histogram to keep track of the case when only zeros have been
+  // recorded. Ensure that recording callbacks have started and that at least
+  // one timer event has been able to update |num_rec_level_is_zero_|.
+  // I am avoiding use of the task queue here since we are under destruction
+  // and reading these members on the creating thread feels safe.
+  if (rec_callbacks_ > 0 && num_stat_reports_ > 0) {
+    RTC_LOGGED_HISTOGRAM_BOOLEAN("WebRTC.Audio.RecordedOnlyZeros",
+    static_cast<int>(num_stat_reports_ == num_rec_level_is_zero_));
+  }
 }
 
 int32_t AudioDeviceBuffer::RegisterAudioCallback(
@@ -97,7 +112,7 @@ int32_t AudioDeviceBuffer::RegisterAudioCallback(
 int32_t AudioDeviceBuffer::InitPlayout() {
   LOG(INFO) << __FUNCTION__;
   RTC_DCHECK(thread_checker_.CalledOnValidThread());
-  last_playout_time_ = rtc::TimeMillis();
+  ResetPlayStats();
   if (!timer_has_started_) {
     StartTimer();
     timer_has_started_ = true;
@@ -108,6 +123,7 @@ int32_t AudioDeviceBuffer::InitPlayout() {
 int32_t AudioDeviceBuffer::InitRecording() {
   LOG(INFO) << __FUNCTION__;
   RTC_DCHECK(thread_checker_.CalledOnValidThread());
+  ResetRecStats();
   if (!timer_has_started_) {
     StartTimer();
     timer_has_started_ = true;
@@ -263,8 +279,8 @@ int32_t AudioDeviceBuffer::SetRecordedBuffer(const void* audio_buffer,
 
   // Update some stats but do it on the task queue to ensure that the members
   // are modified and read on the same thread.
-  task_queue_.PostTask(
-      rtc::Bind(&AudioDeviceBuffer::UpdateRecStats, this, num_samples));
+  task_queue_.PostTask(rtc::Bind(&AudioDeviceBuffer::UpdateRecStats, this,
+                                 audio_buffer, num_samples));
   return 0;
 }
 
@@ -335,8 +351,8 @@ int32_t AudioDeviceBuffer::RequestPlayoutData(size_t num_samples) {
 
   // Update some stats but do it on the task queue to ensure that access of
   // members is serialized hence avoiding usage of locks.
-  task_queue_.PostTask(
-      rtc::Bind(&AudioDeviceBuffer::UpdatePlayStats, this, num_samples_out));
+  task_queue_.PostTask(rtc::Bind(&AudioDeviceBuffer::UpdatePlayStats, this,

[peah-webrtc, 2016/09/09 09:06:27]

Would it not be better to post the task once every 50 frames and for the posted
UpdatePlayStats task then always do all the computations, instead of as now do
post the task each frame and only do the actual computations for one frame out
of all those 50.

I don't know the overhead of the PostTask and Bind calls as well as the actial
UpdatePlayStats call but if seems better to update and check the frame counter
before posting the task, rather than to do it inside the task.

[peah-webrtc, 2016/09/09 09:06:27]

How critical is the complexity here? Would it be ok to compute the level
estimation for all frames?

[henrika_webrtc, 2016/09/09 11:55:01]

Referring to off-line discussion.

[henrika_webrtc, 2016/09/09 11:55:01]

Referring to off-line discussion.

+                                 &play_buffer_[0], num_samples_out));
   return static_cast<int32_t>(num_samples_out);
 }
 
@@ -379,6 +395,7 @@ void AudioDeviceBuffer::AllocateRecordingBufferIfNeeded() {
 }
 
 void AudioDeviceBuffer::StartTimer() {
+  num_stat_reports_ = 0;
   last_log_stat_time_ = rtc::TimeMillis();
   task_queue_.PostDelayedTask(rtc::Bind(&AudioDeviceBuffer::LogStats, this),
                               kTimerIntervalInMilliseconds);
@@ -403,7 +420,8 @@ void AudioDeviceBuffer::LogStats() {
               << "kHz] callbacks: " << rec_callbacks_ - last_rec_callbacks_
               << ", "
               << "samples: " << diff_samples << ", "
-              << "rate: " << rate;
+              << "rate: " << rate << ", "
+              << "level: " << max_rec_level_;
 
     diff_samples = play_samples_ - last_play_samples_;
     rate = diff_samples / kTimerIntervalInSeconds;
@@ -412,13 +430,22 @@ void AudioDeviceBuffer::LogStats() {
               << "kHz] callbacks: " << play_callbacks_ - last_play_callbacks_
               << ", "
               << "samples: " << diff_samples << ", "
-              << "rate: " << rate;
+              << "rate: " << rate << ", "
+              << "level: " << max_play_level_;
+  }
+
+  // Count number of times we detect "no audio" corresponding to a case where
+  // all level measurements have been zero.
+  if (max_rec_level_ == 0) {
+    ++num_rec_level_is_zero_;
   }
 
   last_rec_callbacks_ = rec_callbacks_;
   last_play_callbacks_ = play_callbacks_;
   last_rec_samples_ = rec_samples_;
   last_play_samples_ = play_samples_;
+  max_rec_level_ = 0;
+  max_play_level_ = 0;
 
   int64_t time_to_wait_ms = next_callback_time - rtc::TimeMillis();
   RTC_DCHECK_GT(time_to_wait_ms, 0) << "Invalid timer interval";
@@ -429,16 +456,58 @@ void AudioDeviceBuffer::LogStats() {
                               time_to_wait_ms);
 }
 
-void AudioDeviceBuffer::UpdateRecStats(size_t num_samples) {
+void AudioDeviceBuffer::ResetRecStats() {
+  rec_callbacks_ = 0;
+  last_rec_callbacks_ = 0;
+  rec_samples_ = 0;
+  last_rec_samples_ = 0;
+  max_rec_level_ = 0;
+  num_rec_level_is_zero_ = 0;
+}
+
+void AudioDeviceBuffer::ResetPlayStats() {
+  last_playout_time_ = rtc::TimeMillis();
+  play_callbacks_ = 0;
+  last_play_callbacks_ = 0;
+  play_samples_ = 0;
+  last_play_samples_ = 0;
+  max_play_level_ = 0;
+}
+
+void AudioDeviceBuffer::UpdateRecStats(const void* audio_buffer,
+                                       size_t num_samples) {
   RTC_DCHECK(task_queue_.IsCurrent());
   ++rec_callbacks_;
   rec_samples_ += num_samples;
+
+  // Find the max absolute value in an audio packet twice per second and update
+  // |max_rec_level_| to track the largest value.
+  if (rec_callbacks_ % 50 == 0) {
+    int16_t max_abs = WebRtcSpl_MaxAbsValueW16(
+        static_cast<int16_t*>(const_cast<void*>(audio_buffer)),

[peah-webrtc, 2016/09/09 09:06:27]

Do we know that these samples are always int16_t samples?

[henrika_webrtc, 2016/09/09 11:55:01]

Yes. But I can add some more stuff around it.

+        num_samples * rec_channels_);
+    if (max_abs > max_rec_level_) {
+      max_rec_level_ = max_abs;
+    }
+  }
 }
 
-void AudioDeviceBuffer::UpdatePlayStats(size_t num_samples) {
+void AudioDeviceBuffer::UpdatePlayStats(const void* audio_buffer,
+                                        size_t num_samples) {
   RTC_DCHECK(task_queue_.IsCurrent());
   ++play_callbacks_;
   play_samples_ += num_samples;
+
+  // Find the max absolute value in an audio packet twice per second and update
+  // |max_play_level_| to track the largest value.
+  if (play_callbacks_ % 50 == 0) {
+    int16_t max_abs = WebRtcSpl_MaxAbsValueW16(
+        static_cast<int16_t*>(const_cast<void*>(audio_buffer)),

[peah-webrtc, 2016/09/09 09:06:27]

Do we know that these samples are always int16_t samples?

[henrika_webrtc, 2016/09/09 11:55:01]

Yes.

+        num_samples * play_channels_);
+    if (max_abs > max_play_level_) {
+      max_play_level_ = max_abs;
+    }
+  }
 }
 
 }  // namespace webrtc