Add UMA histograms for time spent getting WebRTC audio render data.

content/renderer/media/webrtc_audio_renderer.cc

Index: content/renderer/media/webrtc_audio_renderer.cc
diff --git a/content/renderer/media/webrtc_audio_renderer.cc b/content/renderer/media/webrtc_audio_renderer.cc
index e3ce2b0f6775112015b1586bed60f1a90d0f97d2..3d8108bcb83f8861d0ca8bfd7e80278d13c66fb9 100644
--- a/content/renderer/media/webrtc_audio_renderer.cc
+++ b/content/renderer/media/webrtc_audio_renderer.cc
@@ -39,6 +39,11 @@ namespace {
 // between each callback leads to one UMA update each 100ms.
 const int kNumCallbacksBetweenRenderTimeHistograms = 10;
 
+// We log UMA data for the average execution time of the SourceCallback() method
+// every |kNumCallbacksBetweenRenderAverageTimeHistograms| callback. Assuming
+// 10 ms between each callback leads to one UMA update per second.
+const int kNumCallbacksBetweenRenderAverageTimeHistograms = 100;
+
 // Audio parameters that don't change.
 const media::AudioParameters::Format kFormat =
     media::AudioParameters::AUDIO_PCM_LOW_LATENCY;
@@ -252,6 +257,7 @@ void WebRtcAudioRenderer::Play() {
 
   playing_state_.set_playing(true);
   render_callback_count_ = 0;
+  accumulated_render_time_ = base::TimeDelta();
 
   OnPlayStateChanged(media_stream_, &playing_state_);
 }
@@ -305,6 +311,11 @@ void WebRtcAudioRenderer::EnterPauseState() {
 void WebRtcAudioRenderer::Stop() {
   DVLOG(1) << "WebRtcAudioRenderer::Stop()";
   DCHECK(thread_checker_.CalledOnValidThread());
+  if (render_callback_count_ > 0) {
+    UMA_HISTOGRAM_TIMES("WebRTC.AudioRenderTimeMax", max_render_time_);
+    max_render_time_ = base::TimeDelta();
+  }
+
   {
     base::AutoLock auto_lock(lock_);
     if (state_ == UNINITIALIZED)
@@ -476,10 +487,24 @@ void WebRtcAudioRenderer::SourceCallback(
   if (state_ != PLAYING)
     audio_bus->Zero();
 
-  if (++render_callback_count_ == kNumCallbacksBetweenRenderTimeHistograms) {
-    base::TimeDelta elapsed = base::TimeTicks::Now() - start_time;
-    render_callback_count_ = 0;
+  // Measure the elapsed time for this function and log periodically.
+  base::TimeDelta elapsed = base::TimeTicks::Now() - start_time;

[DaleCurtis, 2016/08/22 17:32:19]

This will skew if you catch it between a suspend/resume cycle. Is that okay? If
not you'll need to invalidate this measure when OnSuspend() || OnResume() are
called (but not on Android; where suspend/resume mean something different :| ).

[Henrik Grunell, 2016/08/23 10:42:04]

Hmm, isn't it so that the ticks are updated as long as the system isn't yet
suspended, and not when suspended? I'm not sure how we can get a skew. Is there
something ambiguous going on when about to suspend?

[DaleCurtis, 2016/08/24 17:45:16]

If you record start_time prior to suspend and then compare against now during
resume you're going to get a massive value. It may not matter here, but it's
something to consider.

+  if (elapsed > max_render_time_)
+    max_render_time_ = elapsed;
+  accumulated_render_time_ += elapsed;
+  ++render_callback_count_;
+  if (render_callback_count_ % kNumCallbacksBetweenRenderTimeHistograms == 0)
     UMA_HISTOGRAM_TIMES("WebRTC.AudioRenderTimes", elapsed);
+  if (render_callback_count_ %
+          kNumCallbacksBetweenRenderAverageTimeHistograms ==
+      0) {
+    UMA_HISTOGRAM_CUSTOM_TIMES(
+        "WebRTC.AudioRenderTimesAverage",
+        accumulated_render_time_ /
+            kNumCallbacksBetweenRenderAverageTimeHistograms,
+        base::TimeDelta::FromMicroseconds(100),

[Henrik Grunell, 2016/08/22 15:21:59]

I'm not sure if microseconds precision is possible with this macro?

[DaleCurtis, 2016/08/22 17:32:19]

Yeah, the best you can do is milliseconds. The macro code explicitly calls
InMilliseconds().

[Ilya Sherman, 2016/08/22 21:17:47]

Alternately, you could use a CUSTOM_COUNTS macro and record the time in
microseconds directly.

[Henrik Grunell, 2016/08/23 10:42:04]

OK, I've switched to CUSTOM_COUNTS.

+        base::TimeDelta::FromMilliseconds(30), 50);
+    accumulated_render_time_ = base::TimeDelta();
   }
 }