Adds time measurement of WebRtcAudioRenderer::Render

content/renderer/media/webrtc_audio_renderer.cc

 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "content/renderer/media/webrtc_audio_renderer.h"
 
 #include "base/logging.h"
 #include "base/metrics/histogram.h"
 #include "base/strings/string_util.h"
 #include "base/strings/stringprintf.h"
@@ skipping 11 matching lines @@
 
 #if defined(OS_WIN)
 #include "base/win/windows_version.h"
 #include "media/audio/win/core_audio_util_win.h"
 #endif
 
 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
 // might violate the implementation assumptions inside WebRtcAudioRenderer
 // (see the play reference count).
 class SharedAudioRenderer : public MediaStreamAudioRenderer {
  public:
   // Callback definition for a callback that is called when when Play(), Pause()
   // or SetVolume are called (whenever the internal |playing_state_| changes).
   typedef base::Callback<
@@ skipping 141 matching lines @@
       session_id_(session_id),
       media_stream_(media_stream),
       source_(NULL),
       play_ref_count_(0),
       start_ref_count_(0),
       audio_delay_milliseconds_(0),
       fifo_delay_milliseconds_(0),
       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",
       source_render_view_id,
       session_id,
       sample_rate,
       frames_per_buffer,
       sink_params_.effects()));
 }
 
@@ skipping 110 matching lines @@
 }
 
 void WebRtcAudioRenderer::Play() {
   DVLOG(1) << "WebRtcAudioRenderer::Play()";
   DCHECK(thread_checker_.CalledOnValidThread());
 
   if (playing_state_.playing())
     return;
 
   playing_state_.set_playing(true);
+  render_callback_count_ = 0;
 
   OnPlayStateChanged(media_stream_, &playing_state_);
 }
 
 void WebRtcAudioRenderer::EnterPlayState() {
   DVLOG(1) << "WebRtcAudioRenderer::EnterPlayState()";
   DCHECK(thread_checker_.CalledOnValidThread());
   DCHECK_GT(start_ref_count_, 0) << "Did you forget to call Start()?";
   base::AutoLock auto_lock(lock_);
   if (state_ == UNINITIALIZED)
@@ skipping 78 matching lines @@
 bool WebRtcAudioRenderer::IsLocalRenderer() const {
   return false;
 }
 
 int WebRtcAudioRenderer::Render(media::AudioBus* audio_bus,
                                 int audio_delay_milliseconds) {
   base::AutoLock auto_lock(lock_);
   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;
 
   audio_delay_milliseconds_ = audio_delay_milliseconds;
 
   if (audio_fifo_)
     audio_fifo_->Consume(audio_bus, audio_bus->frames());
   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;
 }
 
 void WebRtcAudioRenderer::OnRenderError() {
   NOTIMPLEMENTED();
   LOG(ERROR) << "OnRenderError()";
 }
 
 // Called by AudioPullFifo when more data is necessary.
 void WebRtcAudioRenderer::SourceCallback(
@@ skipping 96 matching lines @@
       if (RemovePlayingState(source, state))
         EnterPauseState();
     } else if (AddPlayingState(source, state)) {
       EnterPlayState();
     }
     UpdateSourceVolume(source);
   }
 }
 
 }  // namespace content