Avoid calling PostTask in audio callbacks

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.
  */
 
@@ skipping 35 matching lines @@
       play_channels_(0),
       playing_(false),
       recording_(false),
       current_mic_level_(0),
       new_mic_level_(0),
       typing_status_(false),
       play_delay_ms_(0),
       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";
   playout_thread_checker_.DetachFromThread();
   recording_thread_checker_.DetachFromThread();
 }
 
 AudioDeviceBuffer::~AudioDeviceBuffer() {
   RTC_DCHECK_RUN_ON(&main_thread_checker_);
   RTC_DCHECK(!playing_);
@@ skipping 238 matching lines @@
     // Returns the largest absolute value in a signed 16-bit vector.
     max_abs = WebRtcSpl_MaxAbsValueW16(rec_buffer_.data(), rec_buffer_.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([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;
 }
 
 int32_t AudioDeviceBuffer::DeliverRecordedData() {
   RTC_DCHECK_RUN_ON(&recording_thread_checker_);
   if (!audio_transport_cb_) {
     LOG(LS_WARNING) << "Invalid audio transport";
     return 0;
   }
   const size_t frames = rec_buffer_.size() / rec_channels_;
@@ skipping 44 matching lines @@
 
   // Derive a new level value twice per second.
   int16_t max_abs = 0;
   RTC_DCHECK_LT(play_stat_count_, 50);
   if (++play_stat_count_ >= 50) {
     // Returns the largest absolute value in a signed 16-bit vector.
     max_abs =
         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);
 }
 
 int32_t AudioDeviceBuffer::GetPlayoutData(void* audio_buffer) {
   RTC_DCHECK_RUN_ON(&playout_thread_checker_);
   RTC_DCHECK_GT(play_buffer_.size(), 0);
   const size_t bytes_per_sample = sizeof(int16_t);
   memcpy(audio_buffer, play_buffer_.data(),
          play_buffer_.size() * bytes_per_sample);
   // Return samples per channel or number of frames.
@@ skipping 29 matching lines @@
 
   // Avoid adding more logs since we are in STOP mode.
   if (!log_stats_) {
     return;
   }
 
   int64_t next_callback_time = now_time + kTimerIntervalInMilliseconds;
   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_;
+  {
+    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.

 
-    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_;
+    // 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";
 
   // Keep posting new (delayed) tasks until state is changed to kLogStop.
   task_queue_.PostDelayedTask(rtc::Bind(&AudioDeviceBuffer::LogStats, this,
                                         AudioDeviceBuffer::LOG_ACTIVE),
                               time_to_wait_ms);
 }
 
 void AudioDeviceBuffer::ResetRecStats() {
   RTC_DCHECK_RUN_ON(&task_queue_);
+  rtc::CritScope cs(&lock_);
   rec_callbacks_ = 0;
   last_rec_callbacks_ = 0;
   rec_samples_ = 0;
   last_rec_samples_ = 0;
   max_rec_level_ = 0;
 }
 
 void AudioDeviceBuffer::ResetPlayStats() {
   RTC_DCHECK_RUN_ON(&task_queue_);
+  rtc::CritScope cs(&lock_);
   play_callbacks_ = 0;
   last_play_callbacks_ = 0;
   play_samples_ = 0;
   last_play_samples_ = 0;
   max_play_level_ = 0;
 }
 
 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_) {
     max_rec_level_ = 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_) {
     max_play_level_ = max_abs;
   }
 }
 
 }  // namespace webrtc