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

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 <utility>
 
 #include "base/bind.h"
 #include "base/bind_helpers.h"
@@ skipping 16 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;
-
 // Audio parameters that don't change.
 const media::AudioParameters::Format kFormat =
     media::AudioParameters::AUDIO_PCM_LOW_LATENCY;
 const media::ChannelLayout kChannelLayout = media::CHANNEL_LAYOUT_STEREO;
 const int kChannels = 2;
 const int kBitsPerSample = 16;
 
+// Used for UMA histograms.
+const int kRenderTimeHistogramMinMicroseconds = 100;
+const int kRenderTimeHistogramMaxMicroseconds = 30 * 1000;  // 30 milliseconds

[Ilya Sherman, 2016/08/24 21:53:41]

I somewhat suspect that this is too low an upper bound, if you want visibility
into the long tail.  And, with 50 buckets, you should be able to allow for a
much larger range within the histogram, without sacrificing much precision in
the smaller buckets.  I'd suggest an upper bound of at least 1 second -- that
would match the range of the UMA_HISTOGRAM_TIMES macro, just with both the min
and the max reduced by a factor of 10.

[Henrik Grunell, 2016/08/25 08:34:07]

That makes sense, changed to max 1 s.

+
 // 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<void(const blink::WebMediaStream&,
@@ skipping 105 matching lines @@
       source_render_frame_id_(source_render_frame_id),
       session_id_(session_id),
       signaling_thread_(signaling_thread),
       media_stream_(media_stream),
       source_(NULL),
       play_ref_count_(0),
       start_ref_count_(0),
       audio_delay_milliseconds_(0),
       sink_params_(kFormat, kChannelLayout, 0, kBitsPerSample, 0),
       output_device_id_(device_id),
-      security_origin_(security_origin),
-      render_callback_count_(0) {
+      security_origin_(security_origin) {
   WebRtcLogMessage(base::StringPrintf(
       "WAR::WAR. source_render_frame_id=%d, session_id=%d, effects=%i",
       source_render_frame_id, session_id, sink_params_.effects()));
 }
 
 WebRtcAudioRenderer::~WebRtcAudioRenderer() {
   DCHECK(thread_checker_.CalledOnValidThread());
   DCHECK_EQ(state_, UNINITIALIZED);
 }
 
@@ skipping 58 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 33 matching lines @@
 
   DCHECK_EQ(state_, PLAYING);
   DCHECK_GT(play_ref_count_, 0);
   if (!--play_ref_count_)
     state_ = PAUSED;
 }
 
 void WebRtcAudioRenderer::Stop() {
   DVLOG(1) << "WebRtcAudioRenderer::Stop()";
   DCHECK(thread_checker_.CalledOnValidThread());
+  // If |max_render_time_| is zero, no render call has been made.
+  if (!max_render_time_.is_zero()) {
+    UMA_HISTOGRAM_CUSTOM_COUNTS(
+        "Media.Audio.Render.GetSourceDataTimeMax.WebRTC",
+        max_render_time_.InMicroseconds(), kRenderTimeHistogramMinMicroseconds,
+        kRenderTimeHistogramMaxMicroseconds, 50);
+    max_render_time_ = base::TimeDelta();
+  }
+
   {
     base::AutoLock auto_lock(lock_);
     if (state_ == UNINITIALIZED)
       return;
 
     if (--start_ref_count_)
       return;
 
     DVLOG(1) << "Calling RemoveAudioRenderer and Stop().";
 
@@ skipping 151 matching lines @@
   // otherwise the data will be buffered up inside |source_|.
   source_->RenderData(audio_bus, sink_params_.sample_rate(),
                       output_delay_milliseconds,
                       &current_time_);
 
   // Avoid filling up the audio bus if we are not playing; instead
   // return here and ensure that the returned value in Render() is 0.
   if (state_ != PLAYING)
     audio_bus->Zero();
 
-  if (++render_callback_count_ == kNumCallbacksBetweenRenderTimeHistograms) {
+  // Measure the elapsed time for this function and log it to UMA. Store the max
+  // value. Don't do this for low resolution clocks to not skew data.
+  if (base::TimeTicks::IsHighResolution()) {

[Henrik Grunell, 2016/08/24 12:38:37]

This is only applicable to Windows (as of now), with a ~15.5 ms precision in low
res. I don't know how the value is rounded or how common falling back is. I'm
hesitating to exclude the data depending on this. Maybe another histogram is a
good option? Wdyt?

[o1ka, 2016/08/24 12:43:14]

I think it's fine to log it for high res only.

[Henrik Grunell, 2016/08/25 08:34:07]

Let's go for that.

     base::TimeDelta elapsed = base::TimeTicks::Now() - start_time;
-    render_callback_count_ = 0;
-    UMA_HISTOGRAM_TIMES("WebRTC.AudioRenderTimes", elapsed);
+    UMA_HISTOGRAM_CUSTOM_COUNTS("Media.Audio.Render.GetSourceDataTime.WebRTC",
+                                elapsed.InMicroseconds(),
+                                kRenderTimeHistogramMinMicroseconds,
+                                kRenderTimeHistogramMaxMicroseconds, 50);
+
+    if (elapsed > max_render_time_)
+      max_render_time_ = elapsed;
   }
 }
 
 void WebRtcAudioRenderer::UpdateSourceVolume(
     webrtc::AudioSourceInterface* source) {
   DCHECK(thread_checker_.CalledOnValidThread());
 
   // Note: If there are no playing audio renderers, then the volume will be
   // set to 0.0.
   float volume = 0.0f;
@@ skipping 155 matching lines @@
           base::Bind(&WebRtcAudioRenderer::SourceCallback,
                      base::Unretained(this))));
     }
     sink_params_ = new_sink_params;
   }
 
   sink_->Initialize(new_sink_params, this);
 }
 
 }  // namespace content