Report timing statistics for audio controller methods via UMA.

Logs the time taken to execute the main methods of AudioInputController
and AudioOutputController.  This timing information will be used to
determine if we can combine the audio thread and the UI thread on OSX
to (hopefully) fix http://crbug.com/158170.

BUG=158170
TEST=chrome://histograms/Media.Audio contains information.

Review URL: https://chromiumcodereview.appspot.com/14827002

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@200414 0039d316-1c4b-4281-b951-d872f2087c98

5 files changed, 60 insertions, 0 deletions

diff --git a/media/audio/audio_input_controller.cc b/media/audio/audio_input_controller.cc
index 2e408db..d70c706 100644
--- a/media/audio/audio_input_controller.cc
+++ b/media/audio/audio_input_controller.cc
@@ -7,6 +7,7 @@
 #include "base/bind.h"
 #include "base/threading/thread_restrictions.h"
 #include "media/base/limits.h"
+#include "media/base/scoped_histogram_timer.h"
 
 namespace {
 const int kMaxInputChannels = 2;
@@ -168,6 +169,7 @@ void AudioInputController::DoCreate(AudioManager* audio_manager,
                                     const AudioParameters& params,
                                     const std::string& device_id) {
   DCHECK(message_loop_->BelongsToCurrentThread());
+  SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioInputController.CreateTime");
   // TODO(miu): See TODO at top of file.  Until that's resolved, assume all
   // platform audio input requires the |no_data_timer_| be used to auto-detect
   // errors.  In reality, probably only Windows and IOS need to be treated as
@@ -214,6 +216,7 @@ void AudioInputController::DoCreateForStream(
 
 void AudioInputController::DoRecord() {
   DCHECK(message_loop_->BelongsToCurrentThread());
+  SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioInputController.RecordTime");
 
   if (state_ != kCreated)
     return;
@@ -235,6 +238,7 @@ void AudioInputController::DoRecord() {
 
 void AudioInputController::DoClose() {
   DCHECK(message_loop_->BelongsToCurrentThread());
+  SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioInputController.CloseTime");
 
   // Delete the timer on the same thread that created it.
   no_data_timer_.reset();
diff --git a/media/audio/audio_output_controller.cc b/media/audio/audio_output_controller.cc
index f41ed74..9e7893c 100644
--- a/media/audio/audio_output_controller.cc
+++ b/media/audio/audio_output_controller.cc
@@ -14,6 +14,7 @@
 #include "media/audio/audio_silence_detector.h"
 #include "media/audio/audio_util.h"
 #include "media/audio/shared_memory_util.h"
+#include "media/base/scoped_histogram_timer.h"
 
 using base::Time;
 using base::TimeDelta;
@@ -103,6 +104,7 @@ void AudioOutputController::SetVolume(double volume) {
 
 void AudioOutputController::DoCreate(bool is_for_device_change) {
   DCHECK(message_loop_->BelongsToCurrentThread());
+  SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioOutputController.CreateTime");
 
   // Close() can be called before DoCreate() is executed.
   if (state_ == kClosed)
@@ -169,6 +171,7 @@ void AudioOutputController::DoPlay() {
 
 void AudioOutputController::PollAndStartIfDataReady() {
   DCHECK(message_loop_->BelongsToCurrentThread());
+  SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioOutputController.PlayTime");
 
   DCHECK_EQ(kStarting, state_);
 
@@ -223,6 +226,7 @@ void AudioOutputController::StopStream() {
 
 void AudioOutputController::DoPause() {
   DCHECK(message_loop_->BelongsToCurrentThread());
+  SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioOutputController.PauseTime");
 
   StopStream();
 
@@ -237,6 +241,7 @@ void AudioOutputController::DoPause() {
 
 void AudioOutputController::DoClose() {
   DCHECK(message_loop_->BelongsToCurrentThread());
+  SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioOutputController.CloseTime");
 
   if (state_ != kClosed) {
     DoStopCloseAndClearStream();
@@ -363,6 +368,7 @@ void AudioOutputController::DoStopCloseAndClearStream() {
 
 void AudioOutputController::OnDeviceChange() {
   DCHECK(message_loop_->BelongsToCurrentThread());
+  SCOPED_UMA_HISTOGRAM_TIMER("Media.AudioOutputController.DeviceChangeTime");
 
   // TODO(dalecurtis): Notify the renderer side that a device change has
   // occurred.  Currently querying the hardware information here will lead to
diff --git a/media/base/scoped_histogram_timer.h b/media/base/scoped_histogram_timer.h
new file mode 100644
index 0000000..39daa56
--- /dev/null
+++ b/media/base/scoped_histogram_timer.h
@@ -0,0 +1,32 @@
+// Copyright 2013 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.
+
+#ifndef MEDIA_BASE_SCOPED_HISTOGRAM_TIMER_H_
+#define MEDIA_BASE_SCOPED_HISTOGRAM_TIMER_H_
+
+#include "base/metrics/histogram.h"
+#include "base/time.h"
+
+// Scoped class which logs its time on this earth as a UMA statistic.  Must be
+// a #define macro since UMA macros prevent variables as names.  The nested
+// macro is necessary to expand __COUNTER__ to an actual value.
+#define SCOPED_UMA_HISTOGRAM_TIMER(name) \
+  SCOPED_UMA_HISTOGRAM_TIMER_EXPANDER(name, __COUNTER__)
+
+#define SCOPED_UMA_HISTOGRAM_TIMER_EXPANDER(name, key) \
+  SCOPED_UMA_HISTOGRAM_TIMER_UNIQUE(name, key)
+
+#define SCOPED_UMA_HISTOGRAM_TIMER_UNIQUE(name, key) \
+  class ScopedHistogramTimer##key { \
+   public: \
+    ScopedHistogramTimer##key() : constructed_(base::TimeTicks::Now()) {} \
+    ~ScopedHistogramTimer##key() { \
+      base::TimeDelta elapsed = base::TimeTicks::Now() - constructed_; \
+      UMA_HISTOGRAM_TIMES(name, elapsed); \
+    } \
+   private: \
+    base::TimeTicks constructed_; \
+  } scoped_histogram_timer_##key
+
+#endif  // MEDIA_BASE_SCOPED_HISTOGRAM_TIMER_H_
diff --git a/media/base/scoped_histogram_timer_unittest.cc b/media/base/scoped_histogram_timer_unittest.cc
new file mode 100644
index 0000000..191a577
--- /dev/null
+++ b/media/base/scoped_histogram_timer_unittest.cc
@@ -0,0 +1,16 @@
+// Copyright 2013 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 "base/time.h"
+#include "media/base/scoped_histogram_timer.h"
+#include "testing/gtest/include/gtest/gtest.h"
+
+namespace media {
+
+TEST(ScopedHistogramTimer, TwoTimersOneScope) {
+  SCOPED_UMA_HISTOGRAM_TIMER("TestTimer0");
+  SCOPED_UMA_HISTOGRAM_TIMER("TestTimer1");
+}
+
+}  // namespace media
\ No newline at end of file
diff --git a/media/media.gyp b/media/media.gyp
index 089778c..d5335ec 100644
--- a/media/media.gyp
+++ b/media/media.gyp
@@ -276,6 +276,7 @@
         'base/pipeline_status.h',
         'base/ranges.cc',
         'base/ranges.h',
+        'base/scoped_histogram_timer.h',
         'base/seekable_buffer.cc',
         'base/seekable_buffer.h',
         'base/serial_runner.cc',
@@ -950,6 +951,7 @@
         'base/pipeline_unittest.cc',
         'base/ranges_unittest.cc',
         'base/run_all_unittests.cc',
+        'base/scoped_histogram_timer_unittest.cc',
         'base/seekable_buffer_unittest.cc',
         'base/sinc_resampler_unittest.cc',
         'base/test_data_util.cc',