Improvements in how WebRTC.Audio.RecordedOnlyZeros is added as histogram

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 f74d3d58e1852ff846bf121ceaeb027dde2e27e3..1be3beb10abfda8ea8ae478bb397d0dceef3852c 100644
--- a/webrtc/modules/audio_device/audio_device_buffer.cc
+++ b/webrtc/modules/audio_device/audio_device_buffer.cc
@@ -30,11 +30,17 @@ static const char kTimerQueueName[] = "AudioDeviceBufferTimer";
 static const size_t kTimerIntervalInSeconds = 10;
 static const size_t kTimerIntervalInMilliseconds =
     kTimerIntervalInSeconds * rtc::kNumMillisecsPerSec;
+// Min time required to qualify an audio session as a "call". If playout or
+// recording has been active for less than this time we will not store any
+// logs or UMA stats but instead consider the call as too short.
+static const size_t kMinValidCallTimeTimeInSeconds = 10;
+static const size_t kMinValidCallTimeTimeInMilliseconds =
+    kMinValidCallTimeTimeInSeconds * rtc::kNumMillisecsPerSec;
 
 AudioDeviceBuffer::AudioDeviceBuffer()
     : audio_transport_cb_(nullptr),
-      task_queue_(kTimerQueueName),
-      timer_has_started_(false),
+      playing_(false),
+      recording_(false),
       rec_sample_rate_(0),
       play_sample_rate_(0),
       rec_channels_(0),
@@ -59,43 +65,17 @@ AudioDeviceBuffer::AudioDeviceBuffer()
       last_log_stat_time_(0),
       max_rec_level_(0),
       max_play_level_(0),
-      num_rec_level_is_zero_(0),
       rec_stat_count_(0),
-      play_stat_count_(0) {
+      play_stat_count_(0),
+      play_start_time_(0),
+      rec_start_time_(0),
+      only_silence_recorded_(true) {
   LOG(INFO) << "AudioDeviceBuffer::ctor";
 }
 
 AudioDeviceBuffer::~AudioDeviceBuffer() {

[tommi, 2016/10/25 16:43:22]

add checks for !playing_ and !recording_?

[henrika_webrtc, 2016/10/26 12:42:41]

Done.

   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_HISTOGRAM_BOOLEAN("WebRTC.Audio.RecordedOnlyZeros",
-    static_cast<int>(num_stat_reports_ == num_rec_level_is_zero_));
-  }
 }
 
 int32_t AudioDeviceBuffer::RegisterAudioCallback(
@@ -108,24 +88,109 @@ int32_t AudioDeviceBuffer::RegisterAudioCallback(
 
 int32_t AudioDeviceBuffer::InitPlayout() {

[tommi, 2016/10/25 16:43:22]

can we remove this function?

[henrika_webrtc, 2016/10/26 12:42:41]

Done.

   LOG(INFO) << __FUNCTION__;
+  return 0;
+}
+
+void AudioDeviceBuffer::StartPlayout() {
   RTC_DCHECK(thread_checker_.CalledOnValidThread());
+  if (playing_) {

[tommi, 2016/10/25 16:43:23]

what about RTC_DCHECK(!playing_) ?

[henrika_webrtc, 2016/10/26 12:42:41]

Done.

+    return;
+  }
+  LOG(INFO) << __FUNCTION__;
   ResetPlayStats();
-  if (!timer_has_started_) {
+  // Start a periodic timer based on task queue if not already done by the
+  // recording side.
+  if (!task_queue_) {
     StartTimer();

[tommi, 2016/10/25 16:43:23]

it looks like every time StartTimer is called, you first check if task_queue_ is
not null.  What about moving this check into StartTimer and don't do anything if
task_queue_ is already valid?

[henrika_webrtc, 2016/10/26 12:42:40]

Excellent idea ;-)

-    timer_has_started_ = true;
   }
-  return 0;
+  playing_ = true;
 }
 
 int32_t AudioDeviceBuffer::InitRecording() {
   LOG(INFO) << __FUNCTION__;
+  return 0;
+}
+
+void AudioDeviceBuffer::StartRecording() {
   RTC_DCHECK(thread_checker_.CalledOnValidThread());
+  if (recording_) {

[tommi, 2016/10/25 16:43:22]

RTC_DCHECK(!recording_)?

[henrika_webrtc, 2016/10/26 12:42:41]

Done.

+    return;
+  }
+  LOG(INFO) << __FUNCTION__;
   ResetRecStats();
-  if (!timer_has_started_) {
+  // Start a periodic timer based on task queue if not already done by the
+  // playout side.
+  if (!task_queue_) {
     StartTimer();
-    timer_has_started_ = true;
   }
-  return 0;
+  recording_ = true;
+}
+
+void AudioDeviceBuffer::StopPlayout() {
+  RTC_DCHECK(thread_checker_.CalledOnValidThread());
+  if (!playing_) {

[tommi, 2016/10/25 16:43:22]

RTC_DCHECK(playing_) ?

[henrika_webrtc, 2016/10/26 12:42:41]

Done.

+    return;
+  }
+  LOG(INFO) << __FUNCTION__;
+  playing_ = false;
+  // Stop the timer if no more media is active.
+  if (!recording_) {
+    StopTimer();
+  }
+  // Add diagnostic logging of delta times for playout callbacks. We are doing
+  // this wihout a lock since playout should be stopped by now and it a minor
+  // conflict during stop will not have a great impact on the total statistics.
+  const size_t time_since_start = rtc::TimeSince(play_start_time_);
+  if (time_since_start > kMinValidCallTimeTimeInMilliseconds) {
+    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;

[tommi, 2016/10/25 16:43:22]

can all of these be merged to one LOG statement?

I wonder what the difference would be for this .obj file in terms of size if
LOG(INFO) was made to be a no-op in release builds.  Seems like a lot of debug
logging that's not useful unless someone's actually debugging.

[henrika_webrtc, 2016/10/26 12:42:41]

Done.

+      LOG(INFO) << "num_measurements: " << num_measurements;
+      LOG(INFO) << "average: "
+               << static_cast<float>(total_diff_time) / num_measurements;
+    }
+  }
+  LOG(INFO) << "total playout time: " << time_since_start;
+}
+
+void AudioDeviceBuffer::StopRecording() {
+  RTC_DCHECK(thread_checker_.CalledOnValidThread());
+  if (!recording_) {

[tommi, 2016/10/25 16:43:22]

RTC_DCHECK(recording_) ?

[henrika_webrtc, 2016/10/26 12:42:41]

Done.

+    return;
+  }
+  LOG(INFO) << __FUNCTION__;
+  recording_ = false;
+  // Stop the timer if no more media is active.
+  if (!playing_) {
+    StopTimer();
+  }
+  // Add UMA histogram to keep track of the case when only zeros have been
+  // recorded. Measurements (max of absolute level) are taken twice per second,
+  // which means that if e.g 10 seconds of audio has been recorded, a total of
+  // 20 level estimates must all be identical to zero to trigger the histogram.
+  // |only_silence_recorded_| can only be cleared on the native audio thread
+  // that drives audio capture but we know by design that the audio has stopped
+  // when this method is called, hence there should not be aby conflicts. Also,
+  // the fact that |only_silence_recorded_| can be affected during the complete
+  // call makes chances of conflicts with potentially one last callback very
+  // small.
+  const size_t time_since_start = rtc::TimeSince(rec_start_time_);
+  if (time_since_start > kMinValidCallTimeTimeInMilliseconds) {
+    const int only_zeros = static_cast<int>(only_silence_recorded_);
+    RTC_HISTOGRAM_BOOLEAN("WebRTC.Audio.RecordedOnlyZeros", only_zeros);
+    LOG(INFO)  << "HISTOGRAM(WebRTC.Audio.RecordedOnlyZeros): " <<  only_zeros;

[tommi, 2016/10/25 16:43:22]

fix spaces

[henrika_webrtc, 2016/10/26 12:42:41]

Done.

+  }
+  LOG(INFO) << "total recording time: " << time_since_start;
 }
 
 int32_t AudioDeviceBuffer::SetRecordingSampleRate(uint32_t fsHz) {
@@ -249,7 +314,7 @@ int32_t AudioDeviceBuffer::SetRecordedBuffer(const void* audio_buffer,
   if (old_size != rec_buffer_.size()) {
     LOG(LS_INFO) << "Size of recording buffer: " << rec_buffer_.size();

[tommi, 2016/10/25 16:43:23]

fyi - logging from within performance sensitive callbacks can be expensive. 
Amongst other things, it will grab a global lock for stdio, which means that
this can contend with any other thread that is logging or writing to stdout. 
Additionally it grabs the global g_log_crit lock, which is held while any
potential log sink's OnLogMessage method is called.

[henrika_webrtc, 2016/10/26 12:42:41]

Wow, didn't know that. It is a very, very rare event and only happens the first
time we set the size or if e.g. the sample rate of a device changes. 

May I keep it?

   }
-  // Derive a new level value twice per second.
+  // Derive a new level value twice per second and check if it is non-zero.
   int16_t max_abs = 0;
   RTC_DCHECK_LT(rec_stat_count_, 50);
   if (++rec_stat_count_ >= 50) {
@@ -258,12 +323,18 @@ int32_t AudioDeviceBuffer::SetRecordedBuffer(const void* audio_buffer,
     max_abs = WebRtcSpl_MaxAbsValueW16(
         reinterpret_cast<const int16_t*>(rec_buffer_.data()), size);
     rec_stat_count_ = 0;
+    // Set |only_silence_recorded_| to false as soon as at least one detection
+    // of a non-zero audio packet is found. It can only be restored to true
+    // again by restarting the call.
+    if (max_abs > 0) {
+      only_silence_recorded_ = false;
+    }
   }
   // Update some stats but do it on the task queue to ensure that the members
   // are modified and read on the same thread. Note that |max_abs| will be
   // zero in most calls and then have no effect of the stats. It is only updated
   // approximately two times per second and can then change the stats.
-  task_queue_.PostTask(rtc::Bind(&AudioDeviceBuffer::UpdateRecStats, this,
+  task_queue_->PostTask(rtc::Bind(&AudioDeviceBuffer::UpdateRecStats, this,
                                  max_abs, num_samples));
   return 0;
 }
@@ -354,7 +425,7 @@ int32_t AudioDeviceBuffer::RequestPlayoutData(size_t num_samples) {
   // are modified and read on the same thread. Note that |max_abs| will be
   // zero in most calls and then have no effect of the stats. It is only updated
   // approximately two times per second and can then change the stats.
-  task_queue_.PostTask(rtc::Bind(&AudioDeviceBuffer::UpdatePlayStats, this,
+  task_queue_->PostTask(rtc::Bind(&AudioDeviceBuffer::UpdatePlayStats, this,
                                  max_abs, num_samples_out));

[tommi, 2016/10/25 16:43:22]

fix indent (maybe run git cl format?)

[henrika_webrtc, 2016/10/26 12:42:41]

For some reason git cl format does not work on this CL. Don't know the exact
reason. I always use it. Will change.

I created a new CL and patched it with this one and did git cl format again. Did
not find any other misses than those you pointed out already.

   return static_cast<int32_t>(num_samples_out);
 }
@@ -370,14 +441,23 @@ int32_t AudioDeviceBuffer::GetPlayoutData(void* audio_buffer) {
 }
 
 void AudioDeviceBuffer::StartTimer() {
+  LOG(INFO) << "StartTimer";

[tommi, 2016/10/25 16:43:22]

do we need all of this logging in release builds?

[henrika_webrtc, 2016/10/26 12:42:40]

Removed

   num_stat_reports_ = 0;
   last_log_stat_time_ = rtc::TimeMillis();
-  task_queue_.PostDelayedTask(rtc::Bind(&AudioDeviceBuffer::LogStats, this),
-                              kTimerIntervalInMilliseconds);
+  task_queue_.reset(new rtc::TaskQueue(kTimerQueueName));
+  task_queue_->PostDelayedTask(rtc::Bind(&AudioDeviceBuffer::LogStats, this),
+                               kTimerIntervalInMilliseconds);
+}
+
+void AudioDeviceBuffer::StopTimer() {
+  LOG(INFO) << "StopTimer";
+  if (task_queue_) {

[tommi, 2016/10/25 16:43:23]

check isn't necessary (reset() handles it)

[henrika_webrtc, 2016/10/26 12:42:41]

Thanks!

+    task_queue_.reset(nullptr);
+  }
 }
 
 void AudioDeviceBuffer::LogStats() {
-  RTC_DCHECK(task_queue_.IsCurrent());
+  RTC_DCHECK(task_queue_->IsCurrent());
 
   int64_t now_time = rtc::TimeMillis();
   int64_t next_callback_time = now_time + kTimerIntervalInMilliseconds;
@@ -409,12 +489,6 @@ void AudioDeviceBuffer::LogStats() {
               << "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_;
@@ -427,21 +501,24 @@ void AudioDeviceBuffer::LogStats() {
 
   // 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);
+  task_queue_->PostDelayedTask(rtc::Bind(&AudioDeviceBuffer::LogStats, this),
+                               time_to_wait_ms);
 }
 
 void AudioDeviceBuffer::ResetRecStats() {
+  rec_start_time_ = rtc::TimeMillis();
   rec_callbacks_ = 0;
   last_rec_callbacks_ = 0;
   rec_samples_ = 0;
   last_rec_samples_ = 0;
   max_rec_level_ = 0;
-  num_rec_level_is_zero_ = 0;
+  only_silence_recorded_ = true;
 }
 
 void AudioDeviceBuffer::ResetPlayStats() {
-  last_playout_time_ = rtc::TimeMillis();
+  const uint64_t now_time = rtc::TimeMillis();
+  play_start_time_ = now_time;
+  last_playout_time_ = now_time;
   play_callbacks_ = 0;
   last_play_callbacks_ = 0;
   play_samples_ = 0;
@@ -450,7 +527,7 @@ void AudioDeviceBuffer::ResetPlayStats() {
 }
 
 void AudioDeviceBuffer::UpdateRecStats(int16_t max_abs, size_t num_samples) {
-  RTC_DCHECK(task_queue_.IsCurrent());
+  RTC_DCHECK(task_queue_->IsCurrent());
   ++rec_callbacks_;
   rec_samples_ += num_samples;
   if (max_abs > max_rec_level_) {
@@ -459,7 +536,7 @@ void AudioDeviceBuffer::UpdateRecStats(int16_t max_abs, size_t num_samples) {
 }
 
 void AudioDeviceBuffer::UpdatePlayStats(int16_t max_abs, size_t num_samples) {
-  RTC_DCHECK(task_queue_.IsCurrent());
+  RTC_DCHECK(task_queue_->IsCurrent());
   ++play_callbacks_;
   play_samples_ += num_samples;
   if (max_abs > max_play_level_) {