Adds time measurement of WebRtcAudioRenderer::Render

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 24eee9a746613b95d858b47f355433ecd70b5ce6..c50f998cef5e46bf15acd4bdd56081c2f959e336 100644
--- a/content/renderer/media/webrtc_audio_renderer.cc
+++ b/content/renderer/media/webrtc_audio_renderer.cc
@@ -29,6 +29,11 @@ namespace content {
 
 namespace {
 
+// We add a UMA histogram measuring the execution time of the Render() method
+// every |kNumCallbacksBetweenRenderTimeHistograms| callback. Assuming 10ms
+// between each callback leads to one UMA update each 100ms.
+const int kNumCallbacksBetweenRenderTimeHistograms = 10;
+
 // This is a simple wrapper class that's handed out to users of a shared
 // WebRtcAudioRenderer instance.  This class maintains the per-user 'playing'
 // and 'started' states to avoid problems related to incorrect usage which
@@ -190,7 +195,8 @@ WebRtcAudioRenderer::WebRtcAudioRenderer(
       sink_params_(media::AudioParameters::AUDIO_PCM_LOW_LATENCY,
                    media::CHANNEL_LAYOUT_STEREO, sample_rate, 16,
                    frames_per_buffer,
-                   GetCurrentDuckingFlag(source_render_frame_id)) {
+                   GetCurrentDuckingFlag(source_render_frame_id)),
+      render_callback_count_(0) {
   WebRtcLogMessage(base::StringPrintf(
       "WAR::WAR. source_render_view_id=%d"
       ", session_id=%d, sample_rate=%d, frames_per_buffer=%d, effects=%i",
@@ -321,6 +327,7 @@ void WebRtcAudioRenderer::Play() {
     return;
 
   playing_state_.set_playing(true);
+  render_callback_count_ = 0;
 
   OnPlayStateChanged(media_stream_, &playing_state_);
 }
@@ -419,6 +426,8 @@ int WebRtcAudioRenderer::Render(media::AudioBus* audio_bus,
   if (!source_)
     return 0;
 
+  base::TimeTicks start_time = base::TimeTicks::Now() ;

[no longer working on chromium, 2014/09/18 17:35:42]

Render() is triggered by callbacks from the device, on Linux and Mac, the
callback is every 10ms, while on windows it is not strictly 10ms, and on
Android, it is at least 20ms. It means that the time we are measuring might be
more than 1 callback into webrtc on Windows and Android.

I am not sure how UMA_HISTOGRAM_TIMES is implemented, but in case the above
information matters, you probably should move the code into SourceCallback.

[henrika (OOO until Aug 14), 2014/09/19 13:13:53]

Will move it to SourceCallback. Thanks.

+
   DVLOG(2) << "WebRtcAudioRenderer::Render()";
   DVLOG(2) << "audio_delay_milliseconds: " << audio_delay_milliseconds;
 
@@ -429,6 +438,12 @@ int WebRtcAudioRenderer::Render(media::AudioBus* audio_bus,
   else
     SourceCallback(0, audio_bus);
 
+  if (++render_callback_count_ == kNumCallbacksBetweenRenderTimeHistograms) {
+    base::TimeDelta elapsed = base::TimeTicks::Now() - start_time;
+    render_callback_count_ = 0;
+    UMA_HISTOGRAM_TIMES("WebRTC.AudioRenderTimes", elapsed);
+  }
+
   return (state_ == PLAYING) ? audio_bus->frames() : 0;
 }