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";
   // TODO(henrika): improve buffer handling and ensure that we don't allocate
   // more than what is required.
   play_buffer_.reset(new int8_t[kMaxBufferSizeBytes]);
   rec_buffer_.reset(new int8_t[kMaxBufferSizeBytes]);
 }
 
 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",

[tommi, 2016/10/24 12:19:15]

since this is only logged in certain cases, there's no comparison to see when
rec_callbacks_ or num_stats_reports_ is 0, which could be useful to know the
ratio between the two (or if this dtor actually ever runs before stats gathering
is turned off).

+    static_cast<int>(num_stat_reports_ == num_rec_level_is_zero_));

[tommi, 2016/10/24 12:19:15]

fix indent

+  }
 }
 
 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 134 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));

[tommi, 2016/10/24 12:19:14]

isn't this a bug?  audio_buffer will for sure not be correct when the task
actually runs, it might not even be valid.

[henrika_webrtc, 2016/10/24 13:05:14]

Correct. It has been fixed since this CL landed. I no longer pass the audio
buffer but do the level calculation on the audio thread and post the result. 

   return 0;
 }
 
 int32_t AudioDeviceBuffer::DeliverRecordedData() {
   RTC_DCHECK(audio_transport_cb_);
   rtc::CritScope lock(&_critSectCb);
 
   if (!audio_transport_cb_) {
     LOG(LS_WARNING) << "Invalid audio transport";
     return 0;
@@ skipping 48 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,
+                                 &play_buffer_[0], num_samples_out));

[tommi, 2016/10/24 12:19:15]

this looks like a race.  We're holding a lock here, not running on the task
queue, write to play_buffer_[0] and then post that pointer... UpdatePlayStats
doesn't hold the same lock but even if it did, it looks to me like what would be
in that buffer isn't guaranteed to be what it was when the call to PostTask was
made.

[henrika_webrtc, 2016/10/24 13:05:14]

Agree. Has been changed since this CL landed.

   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::UpdatePlayoutParameters() {
   RTC_CHECK(play_bytes_per_sample_);
   rtc::CritScope lock(&_critSect);
   // Update the required buffer size given sample rate and number of channels.
   play_samples_per_10ms_ = static_cast<size_t>(play_sample_rate_ * 10 / 1000);
   play_bytes_per_10ms_ = play_bytes_per_sample_ * play_samples_per_10ms_;
   RTC_DCHECK_LE(play_bytes_per_10ms_, kMaxBufferSizeBytes);
 }
 
 void AudioDeviceBuffer::UpdateRecordingParameters() {
   RTC_CHECK(rec_bytes_per_sample_);
   rtc::CritScope lock(&_critSect);
   // Update the required buffer size given sample rate and number of channels.
   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_;
   RTC_DCHECK_LE(rec_bytes_per_10ms_, kMaxBufferSizeBytes);
 }
 
 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;

[tommi, 2016/10/24 12:19:15]

what if any of these are not 0 already?  Are we missing out on reporting (see
dtor)?

+  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());

[tommi, 2016/10/24 12:19:14]

see above. if this runs on the task queue, it looks to me like it will contend
with the audio callback thread(s)

[henrika_webrtc, 2016/10/24 13:05:14]

Acknowledged.

   ++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)),
+        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());

[tommi, 2016/10/24 12:19:14]

same here

[henrika_webrtc, 2016/10/24 13:05:14]

Acknowledged.

   ++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)),
+        num_samples * play_channels_);
+    if (max_abs > max_play_level_) {
+      max_play_level_ = max_abs;
+    }
+  }
 }
 
 }  // namespace webrtc