Add AudioOutputController trace events and UMA backed wedge detection.

media/audio/audio_output_controller.cc

Index: media/audio/audio_output_controller.cc
diff --git a/media/audio/audio_output_controller.cc b/media/audio/audio_output_controller.cc
index 4f008c993db98b3527199fb0d6f0fa5b925c0407..435e68695ac156bd2fd5adeed9047d9919f7c68e 100644
--- a/media/audio/audio_output_controller.cc
+++ b/media/audio/audio_output_controller.cc
@@ -57,7 +57,7 @@ AudioOutputController::AudioOutputController(
           params.sample_rate(),
           TimeDelta::FromMilliseconds(kPowerMeasurementTimeConstantMillis)),
 #endif
-      number_polling_attempts_left_(0) {
+      wedge_detected_(false) {
   DCHECK(audio_manager);
   DCHECK(handler_);
   DCHECK(sync_reader_);
@@ -132,6 +132,7 @@ void AudioOutputController::SwitchOutputDevice(
 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)
@@ -176,6 +177,7 @@ void AudioOutputController::DoCreate(bool is_for_device_change) {
 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)
@@ -196,7 +198,22 @@ void AudioOutputController::DoPlay() {
   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);
 
@@ -233,6 +250,7 @@ void AudioOutputController::StopStream() {
 void AudioOutputController::DoPause() {
   DCHECK(message_loop_->BelongsToCurrentThread());
   SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioOutputController.PauseTime");
+  TRACE_EVENT0("audio", "AudioOutputController::DoPause");
 
   StopStream();
 
@@ -255,6 +273,7 @@ void AudioOutputController::DoPause() {
 void AudioOutputController::DoClose() {
   DCHECK(message_loop_->BelongsToCurrentThread());
   SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioOutputController.CloseTime");
+  TRACE_EVENT0("audio", "AudioOutputController::DoClose");
 
   if (state_ != kClosed) {
     DoStopCloseAndClearStream();
@@ -320,6 +339,11 @@ int AudioOutputController::OnMoreIOData(AudioBus* source,
   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();
@@ -363,6 +387,7 @@ void AudioOutputController::DoStopCloseAndClearStream() {
 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
@@ -441,4 +466,14 @@ void AudioOutputController::DisallowEntryToOnMoreIOData() {
   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