Add AudioOutputController trace events and UMA backed wedge detection.

media/audio/audio_output_controller.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 "media/audio/audio_output_controller.h"
 
 #include "base/bind.h"
 #include "base/debug/trace_event.h"
 #include "base/message_loop/message_loop.h"
 #include "base/metrics/histogram.h"
@@ skipping 39 matching lines @@
       volume_(1.0),
       state_(kEmpty),
       num_allowed_io_(0),
       sync_reader_(sync_reader),
       message_loop_(audio_manager->GetMessageLoop()),
 #if defined(AUDIO_POWER_MONITORING)
       power_monitor_(
           params.sample_rate(),
           TimeDelta::FromMilliseconds(kPowerMeasurementTimeConstantMillis)),
 #endif
-      number_polling_attempts_left_(0) {
+      wedge_detected_(false) {
   DCHECK(audio_manager);
   DCHECK(handler_);
   DCHECK(sync_reader_);
   DCHECK(message_loop_.get());
 }
 
 AudioOutputController::~AudioOutputController() {
   DCHECK_EQ(kClosed, state_);
 }
 
@@ skipping 54 matching lines @@
   message_loop_->PostTaskAndReply(
       FROM_HERE,
       base::Bind(&AudioOutputController::DoSwitchOutputDevice, this,
                  output_device_id),
       callback);
 }
 
 void AudioOutputController::DoCreate(bool is_for_device_change) {
   DCHECK(message_loop_->BelongsToCurrentThread());
   SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioOutputController.CreateTime");
+  TRACE_EVENT0("audio", "AudioOutputController::DoCreate");
 
   // Close() can be called before DoCreate() is executed.
   if (state_ == kClosed)
     return;
 
   DoStopCloseAndClearStream();  // Calls RemoveOutputDeviceChangeListener().
   DCHECK_EQ(kEmpty, state_);
 
   stream_ = diverting_to_stream_ ?
       diverting_to_stream_ :
@@ skipping 24 matching lines @@
   state_ = kCreated;
 
   // And then report we have been created if we haven't done so already.
   if (!is_for_device_change)
     handler_->OnCreated();
 }
 
 void AudioOutputController::DoPlay() {
   DCHECK(message_loop_->BelongsToCurrentThread());
   SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioOutputController.PlayTime");
+  TRACE_EVENT0("audio", "AudioOutputController::DoPlay");
 
   // We can start from created or paused state.
   if (state_ != kCreated && state_ != kPaused)
     return;
 
   // Ask for first packet.
   sync_reader_->UpdatePendingBytes(0);
 
   state_ = kPlaying;
 
 #if defined(AUDIO_POWER_MONITORING)
   power_monitor_.Reset();
   power_poll_callback_.Reset(
       base::Bind(&AudioOutputController::ReportPowerMeasurementPeriodically,
                  this));
   // Run the callback to send an initial notification that we're starting in
   // silence, and to schedule periodic callbacks.
   power_poll_callback_.callback().Run();
 #endif
 
-  // We start the AudioOutputStream lazily.
+  // For UMA tracking purposes, start the wedge detection timer.  This allows us
+  // to record statistics about the number of wedged playbacks in the field.
+  //
+  // WedgeCheck() will look to see if |wedge_detected_| is still true after the
+  // timeout expires.  Care must be taken to ensure the wedge check delay is
+  // large enough that the value isn't queried while OnMoreDataIO() is setting
+  // it.  Currently, all buffers are less than 42ms, so anything larger is fine.

[scherkus (not reviewing), 2013/11/04 19:05:12]

isn't the important # here how long it takes between starting the device and
time until the first OnMoreDataIO() call, which I assume is independent of the
buffer size?

[DaleCurtis, 2013/11/04 21:11:37]

Ah, yeah, you're right. The PlayTime UMA values show this code completes in < 1
sec for 99% of users.  If I look at the OSX graph, that's not true until ~ 1.5
seconds.  That's still not the same as the time until OnMoreIOData, but that
gives a baseline at least.  So it looks like a better value might be ~3 to 5
seconds. 

+  //
+  // Timer self-manages its lifetime and WedgeCheck() will only fire if the

[scherkus (not reviewing), 2013/11/04 19:05:12]

nit on comment accuracy: WedgeCheck() always runs, it just doesn't do anything
if state != kPlaying

[DaleCurtis, 2013/11/04 21:11:37]

Done.

+  // state is still kPlaying.  Additional Start() calls will invalidate the
+  // previous timer.
+  wedge_timer_.Start(
+      FROM_HERE, TimeDelta::FromSeconds(1), this,
+      &AudioOutputController::WedgeCheck);
+  wedge_detected_ = true;

[scherkus (not reviewing), 2013/11/04 19:05:12]

how about on_more_data_io_called_, since that's what you're actually checking
for?

(when I first read this code it caught me off guard since it reads as if we've
immediately detected a wedge)

[DaleCurtis, 2013/11/04 21:11:37]

Done.

+
   AllowEntryToOnMoreIOData();
   stream_->Start(this);
 
   handler_->OnPlaying();
 }
 
 #if defined(AUDIO_POWER_MONITORING)
 void AudioOutputController::ReportPowerMeasurementPeriodically() {
   DCHECK(message_loop_->BelongsToCurrentThread());
   const std::pair<float, bool>& reading =
@@ skipping 16 matching lines @@
     power_poll_callback_.Cancel();
 #endif
 
     state_ = kPaused;
   }
 }
 
 void AudioOutputController::DoPause() {
   DCHECK(message_loop_->BelongsToCurrentThread());
   SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioOutputController.PauseTime");
+  TRACE_EVENT0("audio", "AudioOutputController::DoPause");
 
   StopStream();
 
   if (state_ != kPaused)
     return;
 
   // Let the renderer know we've stopped.  Necessary to let PPAPI clients know
   // audio has been shutdown.  TODO(dalecurtis): This stinks.  PPAPI should have
   // a better way to know when it should exit PPB_Audio_Shared::Run().
   sync_reader_->UpdatePendingBytes(-1);
 
 #if defined(AUDIO_POWER_MONITORING)
   // Paused means silence follows.
   handler_->OnPowerMeasured(AudioPowerMonitor::zero_power(), false);
 #endif
 
   handler_->OnPaused();
 }
 
 void AudioOutputController::DoClose() {
   DCHECK(message_loop_->BelongsToCurrentThread());
   SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioOutputController.CloseTime");
+  TRACE_EVENT0("audio", "AudioOutputController::DoClose");
 
   if (state_ != kClosed) {
     DoStopCloseAndClearStream();
     sync_reader_->Close();
     state_ = kClosed;
   }
 }
 
 void AudioOutputController::DoSetVolume(double volume) {
   DCHECK(message_loop_->BelongsToCurrentThread());
@@ skipping 45 matching lines @@
                                       AudioBuffersState buffers_state) {
   return OnMoreIOData(NULL, dest, buffers_state);
 }
 
 int AudioOutputController::OnMoreIOData(AudioBus* source,
                                         AudioBus* dest,
                                         AudioBuffersState buffers_state) {
   DisallowEntryToOnMoreIOData();
   TRACE_EVENT0("audio", "AudioOutputController::OnMoreIOData");
 
+  // Indicate that we haven't wedged (at least not indefinitely, WedgeCheck()
+  // may have already fired if OnMoreIOData() took an abnormal amount of time).
+  if (wedge_detected_)

[scherkus (not reviewing), 2013/11/04 19:05:12]

you don't need this if statement

[DaleCurtis, 2013/11/04 21:11:37]

I was trying to avoid setting it if it's already set since another thread might
be reading it.  That said, the compiler might just optimize it out, so removed.

+    wedge_detected_ = false;

[scherkus (not reviewing), 2013/11/04 19:05:12]

IIRC OnMoreIOData() runs on a different thread vs. the thread where you read
this value in WedgeCheck()

[DaleCurtis, 2013/11/04 21:11:37]

Correct, hence the comment above.  It seemed overkill to use an AtomicRefCount,
but after some experimenting its not that bad.  Fixed.

+
   sync_reader_->Read(source, dest);
 
   const int frames = dest->frames();
   sync_reader_->UpdatePendingBytes(
       buffers_state.total_bytes() + frames * params_.GetBytesPerFrame());
 
 #if defined(AUDIO_POWER_MONITORING)
   power_monitor_.Scan(*dest, frames);
 #endif
 
@@ skipping 23 matching lines @@
       diverting_to_stream_ = NULL;
     stream_ = NULL;
   }
 
   state_ = kEmpty;
 }
 
 void AudioOutputController::OnDeviceChange() {
   DCHECK(message_loop_->BelongsToCurrentThread());
   SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioOutputController.DeviceChangeTime");
+  TRACE_EVENT0("audio", "AudioOutputController::OnDeviceChange");
 
   // TODO(dalecurtis): Notify the renderer side that a device change has
   // occurred.  Currently querying the hardware information here will lead to
   // crashes on OSX.  See http://crbug.com/158170.
 
   // Recreate the stream (DoCreate() will first shut down an existing stream).
   // Exit if we ran into an error.
   const State original_state = state_;
   DoCreate(true);
   if (!stream_ || state_ == kError)
@@ skipping 58 matching lines @@
 void AudioOutputController::AllowEntryToOnMoreIOData() {
   DCHECK(base::AtomicRefCountIsZero(&num_allowed_io_));
   base::AtomicRefCountInc(&num_allowed_io_);
 }
 
 void AudioOutputController::DisallowEntryToOnMoreIOData() {
   const bool is_zero = !base::AtomicRefCountDec(&num_allowed_io_);
   DCHECK(is_zero);
 }
 
+void AudioOutputController::WedgeCheck() {
+  DCHECK(message_loop_->BelongsToCurrentThread());
+
+  // If we should be playing and we haven't, that's a wedge.
+  if (state_ == kPlaying) {
+    UMA_HISTOGRAM_BOOLEAN(
+        "Media.AudioOutputControllerWedgeDetected", wedge_detected_);

[jar (doing other things), 2013/11/04 07:03:43]

This seems to use a histogram as a counter.  With nothing to normalize this
count, what will it mean?

Have you considered an event instead of a histogram?

Have you considered gathering both == and != in the histogram?

...or is there a way to normalize this?  .... or is "any error" and hence "any
sample" in this histogram a hint that there is a problem (and that is what you
are after)?

[DaleCurtis, 2013/11/04 18:57:32]

I'm confused with what you mean by == and !=.  |wedge_detected_| may be true or
false depending on if OnMoreIOData() ran.  Ideally it'll be mostly false, but we
know it will be sometimes true on OSX.

Since we're logging both true and false, this should be normalized, no?

+  }
+}
+
 }  // namespace media