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..49fe0d8987dcfe45f682768e7855d0c9900589ef 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_(new rtc::TaskQueue(kTimerQueueName)),
+      timer_has_started_(false),
       _recSampleRate(0),
       _playSampleRate(0),
       _recChannels(0),
@@ -45,58 +51,68 @@ 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),
+      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);
+  RTC_DCHECK(task_queue_);
 }
 
 AudioDeviceBuffer::~AudioDeviceBuffer() {
   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() {
   LOG(INFO) << __FUNCTION__;
+  if (!timer_has_started_) {

[stefan-webrtc, 2016/07/07 15:22:13]

Is this accessed on a single thread? I don't know this code well, so I can't
determine if this is safe or not. Maybe it's a good idea to add a thread checker
now already just to be sure?

[henrika_webrtc, 2016/07/08 12:46:48]

It is only accessed on one thread but it is a good idea to do that anyhow.
Thanks.

+    StartTimer();
+    timer_has_started_ = true;
+  }
   return 0;
 }
 
 int32_t AudioDeviceBuffer::InitRecording() {
   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 +126,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 +134,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 +143,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 +209,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 +218,7 @@ int32_t AudioDeviceBuffer::StartInputFileRecording(
 }
 
 int32_t AudioDeviceBuffer::StopInputFileRecording() {
-  CriticalSectionScoped lock(&_critSect);
+  rtc::CritScope lock(&_critSect);
 
   _recFile.Flush();
   _recFile.CloseFile();
@@ -212,7 +228,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 +237,7 @@ int32_t AudioDeviceBuffer::StartOutputFileRecording(
 }
 
 int32_t AudioDeviceBuffer::StopOutputFileRecording() {
-  CriticalSectionScoped lock(&_critSect);
+  rtc::CritScope lock(&_critSect);
 
   _playFile.Flush();
   _playFile.CloseFile();
@@ -231,7 +247,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 +286,14 @@ int32_t AudioDeviceBuffer::SetRecordedBuffer(const void* audioBuffer,
     _recFile.Write(&_recBuffer[0], _recSize);
   }
 
+  ++rec_callbacks_;
+  rec_samples_ += nSamples;
+
   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 +328,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 +351,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 +370,14 @@ int32_t AudioDeviceBuffer::RequestPlayoutData(size_t nSamples) {
     LOG(LS_ERROR) << "NeedMorePlayData() failed";
   }
 
+  ++play_callbacks_;
+  play_samples_ += 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 +390,42 @@ 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());
+
+  int32_t next_callback_time = rtc::Time32() + kTimerIntervalInMilliseconds;

[stefan-webrtc, 2016/07/07 15:22:13]

I think it'd be better to use TimeMillis() and int64_t's instead.

[henrika_webrtc, 2016/07/08 12:46:48]

Done.

+
+  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;
+
+  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_;

[stefan-webrtc, 2016/07/07 15:22:13]

As mentioned offline, I think you have to protect these with a lock, otherwise
tsan this will most certainly complain.

[henrika_webrtc, 2016/07/08 12:46:48]

It actually does not complain. At least not in the tests we run. But let me add
a thread checker and upload a new version.

+  last_play_callbacks_ = play_callbacks_;
+  last_rec_samples_ = rec_samples_;
+  last_play_samples_ = play_samples_;
+
+  int32_t time_to_wait_ms = next_callback_time - rtc::Time32();

[stefan-webrtc, 2016/07/07 15:22:13]

same here.

[henrika_webrtc, 2016/07/08 12:46:48]

Done.

+  RTC_DCHECK_GT(time_to_wait_ms, 0) << "Invalid timer interval";
+
+  task_queue_->PostDelayedTask(rtc::Bind(&AudioDeviceBuffer::LogStats, this),
+                               time_to_wait_ms);
+}
+
 }  // namespace webrtc