Adds data logging in native AudioDeviceBuffer class

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 fb82b91ea105a4daa235ed8420e162aa431a7000..82b1933c408f7b7f906ee39674395fc56eda8f65 100644
--- a/webrtc/modules/audio_device/audio_device_buffer.cc
+++ b/webrtc/modules/audio_device/audio_device_buffer.cc
@@ -10,21 +10,27 @@
 
 #include "webrtc/modules/audio_device/audio_device_buffer.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/modules/audio_device/audio_device_config.h"
-#include "webrtc/system_wrappers/include/critical_section_wrapper.h"
 
 namespace webrtc {
 
 static const int kHighDelayThresholdMs = 300;
 static const int kLogHighDelayIntervalFrames = 500;  // 5 seconds.
 
+static const char kTimerQueueName[] = "AudioDeviceBufferTimer";
+static const size_t kTimerIntervalInSeconds = 10;
+static const size_t kTimerIntervalInMilliseconds =
+    kTimerIntervalInSeconds * 1000;
+
 AudioDeviceBuffer::AudioDeviceBuffer()
-    : _critSect(*CriticalSectionWrapper::CreateCriticalSection()),
-      _critSectCb(*CriticalSectionWrapper::CreateCriticalSection()),
-      _ptrCbAudioTransport(nullptr),
+    : _ptrCbAudioTransport(nullptr),
+      task_queue_(kTimerQueueName),
+      timer_has_started_(false),
       _recSampleRate(0),
       _playSampleRate(0),
       _recChannels(0),
@@ -45,58 +51,71 @@ AudioDeviceBuffer::AudioDeviceBuffer()
       _recDelayMS(0),
       _clockDrift(0),
       // Set to the interval in order to log on the first occurrence.
-      high_delay_counter_(kLogHighDelayIntervalFrames) {
+      high_delay_counter_(kLogHighDelayIntervalFrames),
+      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) {
   LOG(INFO) << "AudioDeviceBuffer::ctor";
   memset(_recBuffer, 0, kMaxBufferSizeBytes);
   memset(_playBuffer, 0, kMaxBufferSizeBytes);
 }
 
 AudioDeviceBuffer::~AudioDeviceBuffer() {
+  RTC_DCHECK(thread_checker_.CalledOnValidThread());
   LOG(INFO) << "AudioDeviceBuffer::~dtor";
-  {
-    CriticalSectionScoped lock(&_critSect);
-
-    _recFile.Flush();
-    _recFile.CloseFile();
-    delete &_recFile;
-
-    _playFile.Flush();
-    _playFile.CloseFile();
-    delete &_playFile;
-  }
+  _recFile.Flush();
+  _recFile.CloseFile();
+  delete &_recFile;
 
-  delete &_critSect;
-  delete &_critSectCb;
+  _playFile.Flush();
+  _playFile.CloseFile();
+  delete &_playFile;
 }
 
 int32_t AudioDeviceBuffer::RegisterAudioCallback(
     AudioTransport* audioCallback) {
   LOG(INFO) << __FUNCTION__;
-  CriticalSectionScoped lock(&_critSectCb);
+  rtc::CritScope lock(&_critSectCb);
   _ptrCbAudioTransport = audioCallback;
   return 0;
 }
 
 int32_t AudioDeviceBuffer::InitPlayout() {
+  RTC_DCHECK(thread_checker_.CalledOnValidThread());
   LOG(INFO) << __FUNCTION__;
+  if (!timer_has_started_) {
+    StartTimer();
+    timer_has_started_ = true;
+  }
   return 0;
 }
 
 int32_t AudioDeviceBuffer::InitRecording() {
+  RTC_DCHECK(thread_checker_.CalledOnValidThread());
   LOG(INFO) << __FUNCTION__;
+  if (!timer_has_started_) {
+    StartTimer();
+    timer_has_started_ = true;
+  }
   return 0;
 }
 
 int32_t AudioDeviceBuffer::SetRecordingSampleRate(uint32_t fsHz) {
   LOG(INFO) << "SetRecordingSampleRate(" << fsHz << ")";
-  CriticalSectionScoped lock(&_critSect);
+  rtc::CritScope lock(&_critSect);
   _recSampleRate = fsHz;
   return 0;
 }
 
 int32_t AudioDeviceBuffer::SetPlayoutSampleRate(uint32_t fsHz) {
   LOG(INFO) << "SetPlayoutSampleRate(" << fsHz << ")";
-  CriticalSectionScoped lock(&_critSect);
+  rtc::CritScope lock(&_critSect);
   _playSampleRate = fsHz;
   return 0;
 }
@@ -110,7 +129,7 @@ int32_t AudioDeviceBuffer::PlayoutSampleRate() const {
 }
 
 int32_t AudioDeviceBuffer::SetRecordingChannels(size_t channels) {
-  CriticalSectionScoped lock(&_critSect);
+  rtc::CritScope lock(&_critSect);
   _recChannels = channels;
   _recBytesPerSample =
       2 * channels;  // 16 bits per sample in mono, 32 bits in stereo
@@ -118,7 +137,7 @@ int32_t AudioDeviceBuffer::SetRecordingChannels(size_t channels) {
 }
 
 int32_t AudioDeviceBuffer::SetPlayoutChannels(size_t channels) {
-  CriticalSectionScoped lock(&_critSect);
+  rtc::CritScope lock(&_critSect);
   _playChannels = channels;
   // 16 bits per sample in mono, 32 bits in stereo
   _playBytesPerSample = 2 * channels;
@@ -127,7 +146,7 @@ int32_t AudioDeviceBuffer::SetPlayoutChannels(size_t channels) {
 
 int32_t AudioDeviceBuffer::SetRecordingChannel(
     const AudioDeviceModule::ChannelType channel) {
-  CriticalSectionScoped lock(&_critSect);
+  rtc::CritScope lock(&_critSect);
 
   if (_recChannels == 1) {
     return -1;
@@ -193,7 +212,7 @@ void AudioDeviceBuffer::SetVQEData(int playDelayMs,
 
 int32_t AudioDeviceBuffer::StartInputFileRecording(
     const char fileName[kAdmMaxFileNameSize]) {
-  CriticalSectionScoped lock(&_critSect);
+  rtc::CritScope lock(&_critSect);
 
   _recFile.Flush();
   _recFile.CloseFile();
@@ -202,7 +221,7 @@ int32_t AudioDeviceBuffer::StartInputFileRecording(
 }
 
 int32_t AudioDeviceBuffer::StopInputFileRecording() {
-  CriticalSectionScoped lock(&_critSect);
+  rtc::CritScope lock(&_critSect);
 
   _recFile.Flush();
   _recFile.CloseFile();
@@ -212,7 +231,7 @@ int32_t AudioDeviceBuffer::StopInputFileRecording() {
 
 int32_t AudioDeviceBuffer::StartOutputFileRecording(
     const char fileName[kAdmMaxFileNameSize]) {
-  CriticalSectionScoped lock(&_critSect);
+  rtc::CritScope lock(&_critSect);
 
   _playFile.Flush();
   _playFile.CloseFile();
@@ -221,7 +240,7 @@ int32_t AudioDeviceBuffer::StartOutputFileRecording(
 }
 
 int32_t AudioDeviceBuffer::StopOutputFileRecording() {
-  CriticalSectionScoped lock(&_critSect);
+  rtc::CritScope lock(&_critSect);
 
   _playFile.Flush();
   _playFile.CloseFile();
@@ -231,7 +250,7 @@ int32_t AudioDeviceBuffer::StopOutputFileRecording() {
 
 int32_t AudioDeviceBuffer::SetRecordedBuffer(const void* audioBuffer,
                                              size_t nSamples) {
-  CriticalSectionScoped lock(&_critSect);
+  rtc::CritScope lock(&_critSect);
 
   if (_recBytesPerSample == 0) {
     assert(false);
@@ -270,11 +289,16 @@ int32_t AudioDeviceBuffer::SetRecordedBuffer(const void* audioBuffer,
     _recFile.Write(&_recBuffer[0], _recSize);
   }
 
+  // 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, nSamples));

[stefan-webrtc, 2016/07/11 08:38:46]

Nice

[henrika_webrtc, 2016/07/11 10:50:15]

Thanks!

+
   return 0;
 }
 
 int32_t AudioDeviceBuffer::DeliverRecordedData() {
-  CriticalSectionScoped lock(&_critSectCb);
+  rtc::CritScope lock(&_critSectCb);
   // Ensure that user has initialized all essential members
   if ((_recSampleRate == 0) || (_recSamples == 0) ||
       (_recBytesPerSample == 0) || (_recChannels == 0)) {
@@ -309,7 +333,7 @@ int32_t AudioDeviceBuffer::RequestPlayoutData(size_t nSamples) {
   // TOOD(henrika): improve bad locking model and make it more clear that only
   // 10ms buffer sizes is supported in WebRTC.
   {
-    CriticalSectionScoped lock(&_critSect);
+    rtc::CritScope lock(&_critSect);
 
     // Store copies under lock and use copies hereafter to avoid race with
     // setter methods.
@@ -332,7 +356,7 @@ int32_t AudioDeviceBuffer::RequestPlayoutData(size_t nSamples) {
 
   size_t nSamplesOut(0);
 
-  CriticalSectionScoped lock(&_critSectCb);
+  rtc::CritScope lock(&_critSectCb);
 
   // It is currently supported to start playout without a valid audio
   // transport object. Leads to warning and silence.
@@ -351,11 +375,16 @@ int32_t AudioDeviceBuffer::RequestPlayoutData(size_t nSamples) {
     LOG(LS_ERROR) << "NeedMorePlayData() failed";
   }
 
+  // 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::UpdatePlayStats, this, nSamplesOut));
+
   return static_cast<int32_t>(nSamplesOut);
 }
 
 int32_t AudioDeviceBuffer::GetPlayoutData(void* audioBuffer) {
-  CriticalSectionScoped lock(&_critSect);
+  rtc::CritScope lock(&_critSect);
   RTC_CHECK_LE(_playSize, kMaxBufferSizeBytes);
 
   memcpy(audioBuffer, &_playBuffer[0], _playSize);
@@ -368,4 +397,59 @@ int32_t AudioDeviceBuffer::GetPlayoutData(void* audioBuffer) {
   return static_cast<int32_t>(_playSamples);
 }
 
+void AudioDeviceBuffer::StartTimer() {
+  task_queue_.PostDelayedTask(rtc::Bind(&AudioDeviceBuffer::LogStats, this),
+                              kTimerIntervalInMilliseconds);
+}
+
+void AudioDeviceBuffer::LogStats() {
+  RTC_DCHECK(task_queue_.IsCurrent());
+
+  int64_t next_callback_time = rtc::TimeMillis() + kTimerIntervalInMilliseconds;
+
+  // 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:10 sec@" << _recSampleRate / 1000
+              << "kHz] callbacks: " << rec_callbacks_ - last_rec_callbacks_
+              << ", "
+              << "samples: " << diff_samples << ", "
+              << "rate: " << rate;

[stefan-webrtc, 2016/07/11 08:38:46]

Should you also log how much system time actually passed since the last call to
LogStats()? The time may not be accurate, so you may want to know if 5, 10 or 15
ms has passed. 

[henrika_webrtc, 2016/07/11 10:50:15]

Good idea. Let me fix that. Assuming you mean seconds and not milliseconds ;-)
Note that I try to derive the exact waiting time below to compensate for any
deviations. Will add anyhow.

+
+    diff_samples = play_samples_ - last_play_samples_;
+    rate = diff_samples / kTimerIntervalInSeconds;
+    LOG(INFO) << "[PLAY:10 sec@" << _playSampleRate / 1000
+              << "kHz] callbacks: " << play_callbacks_ - last_play_callbacks_
+              << ", "
+              << "samples: " << diff_samples << ", "
+              << "rate: " << rate;
+  }
+
+  last_rec_callbacks_ = rec_callbacks_;
+  last_play_callbacks_ = play_callbacks_;
+  last_rec_samples_ = rec_samples_;
+  last_play_samples_ = play_samples_;
+
+  int64_t time_to_wait_ms = next_callback_time - rtc::TimeMillis();
+  RTC_DCHECK_GT(time_to_wait_ms, 0) << "Invalid timer interval";
+
+  task_queue_.PostDelayedTask(rtc::Bind(&AudioDeviceBuffer::LogStats, this),
+                              time_to_wait_ms);
+}
+
+void AudioDeviceBuffer::UpdateRecStats(int num_samples) {
+  RTC_DCHECK(task_queue_.IsCurrent());
+  ++rec_callbacks_;
+  rec_samples_ += num_samples;
+}
+
+void AudioDeviceBuffer::UpdatePlayStats(int num_samples) {
+  RTC_DCHECK(task_queue_.IsCurrent());
+  ++play_callbacks_;
+  play_samples_ += num_samples;
+}
+
 }  // namespace webrtc