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) {
+      on_more_io_data_called_(0) {
   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 |on_more_io_data_called_| is 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.
+  //
+  // Timer self-manages its lifetime and WedgeCheck() will only record the UMA
+  // statistic if state is still kPlaying.  Additional Start() calls will
+  // invalidate the previous timer.
+  wedge_timer_.reset(new base::OneShotTimer<AudioOutputController>());
+  wedge_timer_->Start(
+      FROM_HERE, TimeDelta::FromSeconds(3), this,
+      &AudioOutputController::WedgeCheck);
+  on_more_io_data_called_ = 0;
+
   AllowEntryToOnMoreIOData();
   stream_->Start(this);
 
   handler_->OnPlaying();
 }
 
 #if defined(AUDIO_POWER_MONITORING)
 void AudioOutputController::ReportPowerMeasurementPeriodically() {
   DCHECK(message_loop_->BelongsToCurrentThread());
   const std::pair<float, bool>& reading =
       power_monitor_.ReadCurrentPowerAndClip();
   handler_->OnPowerMeasured(reading.first, reading.second);
   message_loop_->PostDelayedTask(
       FROM_HERE, power_poll_callback_.callback(),
       TimeDelta::FromSeconds(1) / kPowerMeasurementsPerSecond);
 }
 #endif
 
 void AudioOutputController::StopStream() {
   DCHECK(message_loop_->BelongsToCurrentThread());
 
   if (state_ == kPlaying) {
+    wedge_timer_.reset();
     stream_->Stop();
     DisallowEntryToOnMoreIOData();
 
 #if defined(AUDIO_POWER_MONITORING)
     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).
+  // Since this thread is the only writer of |on_more_io_data_called_| once the
+  // thread starts, its safe to compare and then increment.
+  if (base::AtomicRefCountIsZero(&on_more_io_data_called_))
+    base::AtomicRefCountInc(&on_more_io_data_called_);
+
   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.AudioOutputControllerPlaybackStartupSuccess",
+                          base::AtomicRefCountIsOne(&on_more_io_data_called_));
+  }
+}
+
 }  // namespace media