Adds delta-time logging for audio playout

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 54 matching lines @@
       last_play_samples_(0),
       last_log_stat_time_(0) {
   LOG(INFO) << "AudioDeviceBuffer::ctor";
   memset(_recBuffer, 0, kMaxBufferSizeBytes);
   memset(_playBuffer, 0, kMaxBufferSizeBytes);
 }
 
 AudioDeviceBuffer::~AudioDeviceBuffer() {
   RTC_DCHECK(thread_checker_.CalledOnValidThread());
   LOG(INFO) << "AudioDeviceBuffer::~dtor";
+
+  int total_diff_time = 0;
+  int num_measurements = 0;
+  while (!playout_diff_time_map_.empty()) {

[magjed_webrtc, 2016/07/29 10:07:11]

Use a range-based loop instead:
for (const auto& keyAndValue : playout_diff_time_map_) {
  int time_diff = keyAndValue.first;
  int num_elements = keyAndValue.second;  
}

[henrika_webrtc, 2016/07/29 11:11:00]

Thanks. 

+    int time_diff = playout_diff_time_map_.begin()->first;
+    int num_elements =  playout_diff_time_map_.begin()->second;
+    total_diff_time += num_elements * time_diff;
+    num_measurements += num_elements;
+    LOG(INFO) << time_diff << " => " << num_elements;
+    playout_diff_time_map_.erase(playout_diff_time_map_.begin());
+  }
+  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;
+
+
   _recFile.Flush();
   _recFile.CloseFile();
   delete &_recFile;
 
   _playFile.Flush();
   _playFile.CloseFile();
   delete &_playFile;
 }
 
 int32_t AudioDeviceBuffer::RegisterAudioCallback(
     AudioTransport* audioCallback) {
   LOG(INFO) << __FUNCTION__;
   rtc::CritScope lock(&_critSectCb);
   _ptrCbAudioTransport = audioCallback;
   return 0;
 }
 
 int32_t AudioDeviceBuffer::InitPlayout() {
   RTC_DCHECK(thread_checker_.CalledOnValidThread());
   LOG(INFO) << __FUNCTION__;
+  last_playout_time_ = rtc::TimeMillis();
   if (!timer_has_started_) {
     StartTimer();
     timer_has_started_ = true;
   }
   return 0;
 }
 
 int32_t AudioDeviceBuffer::InitRecording() {
   RTC_DCHECK(thread_checker_.CalledOnValidThread());
   LOG(INFO) << __FUNCTION__;
@@ skipping 221 matching lines @@
   }
 
   return 0;
 }
 
 int32_t AudioDeviceBuffer::RequestPlayoutData(size_t nSamples) {
   uint32_t playSampleRate = 0;
   size_t playBytesPerSample = 0;
   size_t playChannels = 0;
 
+  // Measure time since last function call and update a map where the key value
+  // corresponds to time differences (in milliseconds), and the mapped element
+  // represents the number of times a given time difference was found.
+  // Writing to map can be done without a lock since it is only read once at
+  // destruction when no audio is running.
+  int64_t now_time = rtc::TimeMillis();
+  int64_t diff_time = rtc::TimeDiff(now_time, last_playout_time_);

[magjed_webrtc, 2016/07/29 10:07:11]

Consider using
diff_time = std::min(1000, diff_time);
to limit the number of elements in the map.
Also, you could use a plain array instead of a map if you cap the numbers that
way, but I'm not sure how sparse the array will be and if it's an improvement
over using a map.

[henrika_webrtc, 2016/07/29 11:11:00]

Will add the cap, thanks!

Would like to keep the map since the array would be sparse and we would have to
allocate memory for zeros. Hope that is OK.

[magjed_webrtc, 2016/07/29 12:16:07]

The map has a big overhead per element and will need to store at least two
pointers (left/right child), the key, the value, probably a color (it's a
red–black tree), and will contain as many internal nodes as leaf nodes, so
probably something like 80 bytes per element in average, compared to an array
with just 8 bytes (64 bit int) per element. So if you have more than 50
elements, an array will use less memory. An array will probably be something
like 10x faster as well. 100 lookups per second is not completely negligible.

[henrika_webrtc, 2016/07/29 12:50:24]

Will change

+  last_playout_time_ = now_time;
+  playout_diff_time_map_[diff_time]++;
+
   // TOOD(henrika): improve bad locking model and make it more clear that only
   // 10ms buffer sizes is supported in WebRTC.
   {
     rtc::CritScope lock(&_critSect);
 
     // Store copies under lock and use copies hereafter to avoid race with
     // setter methods.
     playSampleRate = _playSampleRate;
     playBytesPerSample = _playBytesPerSample;
     playChannels = _playChannels;
@@ skipping 111 matching lines @@
   rec_samples_ += num_samples;
 }
 
 void AudioDeviceBuffer::UpdatePlayStats(size_t num_samples) {
   RTC_DCHECK(task_queue_.IsCurrent());
   ++play_callbacks_;
   play_samples_ += num_samples;
 }
 
 }  // namespace webrtc