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

webrtc/modules/audio_device/audio_device_buffer.cc

 /*
  *  Copyright (c) 2012 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 <algorithm>
 
 #include "webrtc/modules/audio_device/audio_device_buffer.h"
 
 #include "webrtc/base/arraysize.h"
 #include "webrtc/base/bind.h"
 #include "webrtc/base/checks.h"
 #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 {
 
 static const char kTimerQueueName[] = "AudioDeviceBufferTimer";
 
 // Time between two sucessive calls to LogStats().
 static const size_t kTimerIntervalInSeconds = 10;
 static const size_t kTimerIntervalInMilliseconds =
     kTimerIntervalInSeconds * rtc::kNumMillisecsPerSec;
 
@@ skipping 20 matching lines @@
       clock_drift_(0),
       num_stat_reports_(0),
       rec_callbacks_(0),
       last_rec_callbacks_(0),
       play_callbacks_(0),
       last_play_callbacks_(0),
       rec_samples_(0),
       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";
 }
 
 AudioDeviceBuffer::~AudioDeviceBuffer() {
   RTC_DCHECK(thread_checker_.CalledOnValidThread());
   LOG(INFO) << "AudioDeviceBuffer::~dtor";
 
   size_t total_diff_time = 0;
   int num_measurements = 0;
   LOG(INFO) << "[playout diff time => #measurements]";
   for (size_t diff = 0; diff < arraysize(playout_diff_times_); ++diff) {
     uint32_t num_elements = playout_diff_times_[diff];
     if (num_elements > 0) {
       total_diff_time += num_elements * diff;
       num_measurements += num_elements;
       LOG(INFO) << "[" << diff << " => " << num_elements << "]";
     }
   }
   if (num_measurements > 0) {
     LOG(INFO) << "total_diff_time: " << total_diff_time;
     LOG(INFO) << "num_measurements: " << num_measurements;
     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(
     AudioTransport* audio_callback) {
   LOG(INFO) << __FUNCTION__;
   rtc::CritScope lock(&_critSectCb);
   audio_transport_cb_ = audio_callback;
   return 0;
 }
 
 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;
   }
   return 0;
 }
 
 int32_t AudioDeviceBuffer::InitRecording() {
   LOG(INFO) << __FUNCTION__;
   RTC_DCHECK(thread_checker_.CalledOnValidThread());
+  ResetRecStats();
   if (!timer_has_started_) {
     StartTimer();
     timer_has_started_ = true;
   }
   return 0;
 }
 
 int32_t AudioDeviceBuffer::SetRecordingSampleRate(uint32_t fsHz) {
   LOG(INFO) << "SetRecordingSampleRate(" << fsHz << ")";
   rtc::CritScope lock(&_critSect);
@@ skipping 135 matching lines @@
     for (size_t i = 0; i < rec_samples_per_10ms_; i++) {
       *ptr16Out = *ptr16In;
       ptr16Out++;
       ptr16In++;
       ptr16In++;
     }
   }
 
   // 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;
 }
 
 int32_t AudioDeviceBuffer::DeliverRecordedData() {
   RTC_CHECK(rec_buffer_);
   RTC_DCHECK(audio_transport_cb_);
   rtc::CritScope lock(&_critSectCb);
 
   if (!audio_transport_cb_) {
     LOG(LS_WARNING) << "Invalid audio transport";
@@ skipping 50 matching lines @@
   res = audio_transport_cb_->NeedMorePlayData(
       play_samples_per_10ms_, play_bytes_per_sample_, play_channels_,
       play_sample_rate_, &play_buffer_[0], num_samples_out, &elapsed_time_ms,
       &ntp_time_ms);
   if (res != 0) {
     LOG(LS_ERROR) << "NeedMorePlayData() failed";
   }
 
   // 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);
 }
 
 int32_t AudioDeviceBuffer::GetPlayoutData(void* audio_buffer) {
   rtc::CritScope lock(&_critSect);
   memcpy(audio_buffer, &play_buffer_[0], play_bytes_per_10ms_);
   return static_cast<int32_t>(play_samples_per_10ms_);
 }
 
 void AudioDeviceBuffer::AllocatePlayoutBufferIfNeeded() {
@@ skipping 22 matching lines @@
   rec_samples_per_10ms_ = static_cast<size_t>(rec_sample_rate_ * 10 / 1000);
   rec_bytes_per_10ms_ = rec_bytes_per_sample_ * rec_samples_per_10ms_;
   LOG(INFO) << "recorded samples per 10ms: " << rec_samples_per_10ms_;
   LOG(INFO) << "recorded bytes per 10ms: " << rec_bytes_per_10ms_;
   // Allocate memory for the recording audio buffer. It will always contain
   // audio samples corresponding to 10ms of audio.
   rec_buffer_.reset(new int8_t[rec_bytes_per_10ms_]);
 }
 
 void AudioDeviceBuffer::StartTimer() {
+  num_stat_reports_ = 0;
   last_log_stat_time_ = rtc::TimeMillis();
   task_queue_.PostDelayedTask(rtc::Bind(&AudioDeviceBuffer::LogStats, this),
                               kTimerIntervalInMilliseconds);
 }
 
 void AudioDeviceBuffer::LogStats() {
   RTC_DCHECK(task_queue_.IsCurrent());
 
   int64_t now_time = rtc::TimeMillis();
   int64_t next_callback_time = now_time + kTimerIntervalInMilliseconds;
   int64_t time_since_last = rtc::TimeDiff(now_time, last_log_stat_time_);
   last_log_stat_time_ = now_time;
 
   // Log the latest statistics but skip the first 10 seconds since we are not
   // sure of the exact starting point. I.e., the first log printout will be
   // after ~20 seconds.
   if (++num_stat_reports_ > 1) {
     uint32_t diff_samples = rec_samples_ - last_rec_samples_;
     uint32_t rate = diff_samples / kTimerIntervalInSeconds;
     LOG(INFO) << "[REC : " << time_since_last << "msec, "
               << rec_sample_rate_ / 1000
               << "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;
     LOG(INFO) << "[PLAY: " << time_since_last << "msec, "
               << play_sample_rate_ / 1000
               << "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";
 
   // 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_.PostDelayedTask(rtc::Bind(&AudioDeviceBuffer::LogStats, this),
                               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