Avoid calling PostTask in audio callbacks

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 e7a5da731a5abaa9a95b64149103da2aacebe0ff..aa93774a39e73674caead7db85f2b60f1fc9af91 100644
--- a/webrtc/modules/audio_device/audio_device_buffer.cc
+++ b/webrtc/modules/audio_device/audio_device_buffer.cc
@@ -53,21 +53,21 @@ AudioDeviceBuffer::AudioDeviceBuffer()
       rec_delay_ms_(0),
       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),
-      max_rec_level_(0),
-      max_play_level_(0),
       last_timer_task_time_(0),
       rec_stat_count_(0),
       play_stat_count_(0),
       play_start_time_(0),
       rec_start_time_(0),
+      rec_callbacks_(0),
+      play_callbacks_(0),
+      rec_samples_(0),
+      play_samples_(0),
+      max_rec_level_(0),
+      max_play_level_(0),
       only_silence_recorded_(true),
       log_stats_(false) {
   LOG(INFO) << "AudioDeviceBuffer::ctor";
@@ -326,13 +326,9 @@ int32_t AudioDeviceBuffer::SetRecordedBuffer(const void* audio_buffer,
       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([this, max_abs, samples_per_channel] {
-    UpdateRecStats(max_abs, samples_per_channel);
-  });
+  // Update recording stats which is used as base for periodic logging of the
+  // audio input state.
+  UpdateRecStats(max_abs, samples_per_channel);
   return 0;
 }
 
@@ -397,13 +393,9 @@ int32_t AudioDeviceBuffer::RequestPlayoutData(size_t samples_per_channel) {
         WebRtcSpl_MaxAbsValueW16(play_buffer_.data(), play_buffer_.size());
     play_stat_count_ = 0;
   }
-  // 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([this, max_abs, num_samples_out] {
-    UpdatePlayStats(max_abs, num_samples_out);
-  });
+  // Update playout stats which is used as base for periodic logging of the
+  // audio output state.
+  UpdatePlayStats(max_abs, num_samples_out);
   return static_cast<int32_t>(num_samples_out);
 }
 
@@ -453,36 +445,41 @@ void AudioDeviceBuffer::LogStats(LogState state) {
   int64_t time_since_last = rtc::TimeDiff(now_time, last_timer_task_time_);
   last_timer_task_time_ = now_time;
 
-  // Log the latest statistics but skip the first round just after state was
-  // set to LOG_START. Hence, first printed log will be after ~10 seconds.
-  if (++num_stat_reports_ > 1 && time_since_last > 0) {
-    uint32_t diff_samples = rec_samples_ - last_rec_samples_;
-    float rate = diff_samples / (static_cast<float>(time_since_last) / 1000.0);
-    LOG(INFO) << "[REC : " << time_since_last << "msec, "
-              << rec_sample_rate_ / 1000
-              << "kHz] callbacks: " << rec_callbacks_ - last_rec_callbacks_
-              << ", "
-              << "samples: " << diff_samples << ", "
-              << "rate: " << static_cast<int>(rate + 0.5) << ", "
-              << "level: " << max_rec_level_;
-
-    diff_samples = play_samples_ - last_play_samples_;
-    rate = diff_samples / (static_cast<float>(time_since_last) / 1000.0);
-    LOG(INFO) << "[PLAY: " << time_since_last << "msec, "
-              << play_sample_rate_ / 1000
-              << "kHz] callbacks: " << play_callbacks_ - last_play_callbacks_
-              << ", "
-              << "samples: " << diff_samples << ", "
-              << "rate: " << static_cast<int>(rate + 0.5) << ", "
-              << "level: " << max_play_level_;
-  }
+  {
+    rtc::CritScope cs(&lock_);

[the sun, 2017/02/01 22:37:42]

It bothers me that you're holding the lock while logging. If you put the 4 stats
that have a "last_" counterpart in a struct, it would be easy to:

const Stats stats = [&] {
  rtc::CritScope cs(&lock_);
  return stats_;
}();

do the logging, with diffs between "stats." and "last_."

last_ = stats;

[henrika_webrtc, 2017/02/02 13:51:48]

Will do. Thanks.

+
+    // Log the latest statistics but skip the first round just after state was
+    // set to LOG_START. Hence, first printed log will be after ~10 seconds.
+    if (++num_stat_reports_ > 1 && time_since_last > 0) {
+      uint32_t diff_samples = rec_samples_ - last_rec_samples_;
+      float rate =
+          diff_samples / (static_cast<float>(time_since_last) / 1000.0);
+      LOG(INFO) << "[REC : " << time_since_last << "msec, "
+                << rec_sample_rate_ / 1000
+                << "kHz] callbacks: " << rec_callbacks_ - last_rec_callbacks_
+                << ", "
+                << "samples: " << diff_samples << ", "
+                << "rate: " << static_cast<int>(rate + 0.5) << ", "
+                << "level: " << max_rec_level_;
+
+      diff_samples = play_samples_ - last_play_samples_;
+      rate = diff_samples / (static_cast<float>(time_since_last) / 1000.0);
+      LOG(INFO) << "[PLAY: " << time_since_last << "msec, "
+                << play_sample_rate_ / 1000
+                << "kHz] callbacks: " << play_callbacks_ - last_play_callbacks_
+                << ", "
+                << "samples: " << diff_samples << ", "
+                << "rate: " << static_cast<int>(rate + 0.5) << ", "
+                << "level: " << max_play_level_;
+    }
 
-  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;
+    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";
@@ -495,6 +492,7 @@ void AudioDeviceBuffer::LogStats(LogState state) {
 
 void AudioDeviceBuffer::ResetRecStats() {
   RTC_DCHECK_RUN_ON(&task_queue_);
+  rtc::CritScope cs(&lock_);
   rec_callbacks_ = 0;
   last_rec_callbacks_ = 0;
   rec_samples_ = 0;
@@ -504,6 +502,7 @@ void AudioDeviceBuffer::ResetRecStats() {
 
 void AudioDeviceBuffer::ResetPlayStats() {
   RTC_DCHECK_RUN_ON(&task_queue_);
+  rtc::CritScope cs(&lock_);
   play_callbacks_ = 0;
   last_play_callbacks_ = 0;
   play_samples_ = 0;
@@ -513,7 +512,8 @@ void AudioDeviceBuffer::ResetPlayStats() {
 
 void AudioDeviceBuffer::UpdateRecStats(int16_t max_abs,
                                        size_t samples_per_channel) {
-  RTC_DCHECK_RUN_ON(&task_queue_);
+  RTC_DCHECK_RUN_ON(&recording_thread_checker_);
+  rtc::CritScope cs(&lock_);
   ++rec_callbacks_;
   rec_samples_ += samples_per_channel;
   if (max_abs > max_rec_level_) {
@@ -523,7 +523,8 @@ void AudioDeviceBuffer::UpdateRecStats(int16_t max_abs,
 
 void AudioDeviceBuffer::UpdatePlayStats(int16_t max_abs,
                                         size_t samples_per_channel) {
-  RTC_DCHECK_RUN_ON(&task_queue_);
+  RTC_DCHECK_RUN_ON(&playout_thread_checker_);
+  rtc::CritScope cs(&lock_);
   ++play_callbacks_;
   play_samples_ += samples_per_channel;
   if (max_abs > max_play_level_) {