Log PipelineImpl events to MediaLog.

BUG=
TEST=


Review URL: http://codereview.chromium.org/7584013

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

6 files changed, 127 insertions, 32 deletions

diff --git a/media/base/media_log.cc b/media/base/media_log.cc
index 38be126..15bca41 100644
--- a/media/base/media_log.cc
+++ b/media/base/media_log.cc
@@ -7,6 +7,7 @@
 #include "base/atomic_sequence_num.h"
 #include "base/logging.h"
 #include "base/scoped_ptr.h"
+#include "base/values.h"
 
 namespace media {
 
@@ -16,16 +17,24 @@ static base::AtomicSequenceNumber media_log_count(base::LINKER_INITIALIZED);
 
 const char* MediaLog::EventTypeToString(MediaLogEvent::Type type) {
   switch (type) {
-    case MediaLogEvent::CREATING:
-      return "CREATING";
-    case MediaLogEvent::DESTROYING:
-      return "DESTROYING";
+    case MediaLogEvent::WEBMEDIAPLAYER_CREATED:
+      return "WEBMEDIAPLAYER_CREATED";
+    case MediaLogEvent::WEBMEDIAPLAYER_DESTROYED:
+      return "WEBMEDIAPLAYER_DESTROYED";
+    case MediaLogEvent::PIPELINE_CREATED:
+      return "PIPELINE_CREATED";
+    case MediaLogEvent::PIPELINE_DESTROYED:
+      return "PIPELINE_DESTROYED";
     case MediaLogEvent::LOAD:
       return "LOAD";
+    case MediaLogEvent::SEEK:
+      return "SEEK";
     case MediaLogEvent::PLAY:
       return "PLAY";
     case MediaLogEvent::PAUSE:
       return "PAUSE";
+    case MediaLogEvent::PIPELINE_STATE_CHANGED:
+      return "PIPELINE_STATE_CHANGED";
     case MediaLogEvent::BUFFERED_EXTENTS_CHANGED:
       return "BUFFERED_EXTENTS_CHANGED";
   }
@@ -33,6 +42,43 @@ const char* MediaLog::EventTypeToString(MediaLogEvent::Type type) {
   return NULL;
 }
 
+const char* MediaLog::PipelineStateToString(PipelineImpl::State state) {
+  switch (state) {
+    case PipelineImpl::kCreated:
+      return "created";
+    case PipelineImpl::kInitDemuxer:
+      return "initDemuxer";
+    case PipelineImpl::kInitAudioDecoder:
+      return "initAudioDecoder";
+    case PipelineImpl::kInitAudioRenderer:
+      return "initAudioRenderer";
+    case PipelineImpl::kInitVideoDecoder:
+      return "initVideoDecoder";
+    case PipelineImpl::kInitVideoRenderer:
+      return "initVideoRenderer";
+    case PipelineImpl::kPausing:
+      return "pausing";
+    case PipelineImpl::kSeeking:
+      return "seeking";
+    case PipelineImpl::kFlushing:
+      return "flushing";
+    case PipelineImpl::kStarting:
+      return "starting";
+    case PipelineImpl::kStarted:
+      return "started";
+    case PipelineImpl::kEnded:
+      return "ended";
+    case PipelineImpl::kStopping:
+      return "stopping";
+    case PipelineImpl::kStopped:
+      return "stopped";
+    case PipelineImpl::kError:
+      return "error";
+  }
+  NOTREACHED();
+  return NULL;
+}
+
 MediaLog::MediaLog() {
   id_ = media_log_count.GetNext();
 }
@@ -57,6 +103,20 @@ MediaLogEvent* MediaLog::CreateLoadEvent(const std::string& url) {
   return event.release();
 }
 
+MediaLogEvent* MediaLog::CreateSeekEvent(float seconds) {
+  scoped_ptr<MediaLogEvent> event(CreateEvent(MediaLogEvent::SEEK));
+  event->params.SetDouble("seek_target", seconds);
+  return event.release();
+}
+
+MediaLogEvent* MediaLog::CreatePipelineStateChangedEvent(
+    PipelineImpl::State state) {
+  scoped_ptr<MediaLogEvent> event(
+      CreateEvent(MediaLogEvent::PIPELINE_STATE_CHANGED));
+  event->params.SetString("pipeline_state", PipelineStateToString(state));
+  return event.release();
+}
+
 MediaLogEvent* MediaLog::CreateBufferedExtentsChangedEvent(
     size_t start, size_t current, size_t end) {
   scoped_ptr<MediaLogEvent> event(
diff --git a/media/base/media_log.h b/media/base/media_log.h
index 88417ac..c9905e5 100644
--- a/media/base/media_log.h
+++ b/media/base/media_log.h
@@ -8,13 +8,15 @@
 
 #include "base/memory/ref_counted.h"
 #include "media/base/media_log_event.h"
+#include "media/base/pipeline_impl.h"
 
 namespace media {
 
 class MediaLog : public base::RefCountedThreadSafe<MediaLog> {
  public:
-  // Return a string to represent an EventType.
+  // Convert various enums to strings.
   static const char* EventTypeToString(MediaLogEvent::Type type);
+  static const char* PipelineStateToString(PipelineImpl::State);
 
   MediaLog();
 
@@ -26,6 +28,8 @@ class MediaLog : public base::RefCountedThreadSafe<MediaLog> {
   // Helper methods to create events and their parameters.
   MediaLogEvent* CreateEvent(MediaLogEvent::Type type);
   MediaLogEvent* CreateLoadEvent(const std::string& url);
+  MediaLogEvent* CreateSeekEvent(float seconds);
+  MediaLogEvent* CreatePipelineStateChangedEvent(PipelineImpl::State state);
   MediaLogEvent* CreateBufferedExtentsChangedEvent(size_t start, size_t current,
                                                    size_t end);
 
diff --git a/media/base/media_log_event.h b/media/base/media_log_event.h
index 0c8e3da..9d4e15e 100644
--- a/media/base/media_log_event.h
+++ b/media/base/media_log_event.h
@@ -13,20 +13,33 @@ namespace media {
 
 struct MediaLogEvent {
   enum Type {
-    // A media player is being created or destroyed.
+    // A WebMediaPlayer is being created or destroyed.
     // params: none.
-    CREATING,
-    DESTROYING,
+    WEBMEDIAPLAYER_CREATED,
+    WEBMEDIAPLAYER_DESTROYED,
+
+    // A PipelineImpl is being created or destroyed.
+    // params: none.
+    PIPELINE_CREATED,
+    PIPELINE_DESTROYED,
 
     // A media player is loading a resource.
     // params: "url": <URL of the resource>.
     LOAD,
 
+    // A media player has started seeking.
+    // params: "seek_target": <number of seconds to which to seek>.
+    SEEK,
+
     // A media player has been told to play or pause.
     // params: none.
     PLAY,
     PAUSE,
 
+    // The state of PipelineImpl has changed.
+    // params: "pipeline_state": <string name of the state>.
+    PIPELINE_STATE_CHANGED,
+
     // The extents of the sliding buffer have changed.
     // params: "buffer_start": <first buffered byte>.
     //         "buffer_current": <current offset>.
diff --git a/media/base/pipeline_impl.cc b/media/base/pipeline_impl.cc
index c75b740..0a88b2d 100644
--- a/media/base/pipeline_impl.cc
+++ b/media/base/pipeline_impl.cc
@@ -17,6 +17,7 @@
 #include "base/synchronization/condition_variable.h"
 #include "media/base/clock.h"
 #include "media/base/filter_collection.h"
+#include "media/base/media_log.h"
 
 namespace media {
 
@@ -62,13 +63,17 @@ class PipelineImpl::PipelineInitState {
   scoped_refptr<CompositeFilter> composite_;
 };
 
-PipelineImpl::PipelineImpl(MessageLoop* message_loop)
+PipelineImpl::PipelineImpl(MessageLoop* message_loop, MediaLog* media_log)
     : message_loop_(message_loop),
+      media_log_(media_log),
       clock_(new Clock(&base::Time::Now)),
       waiting_for_clock_update_(false),
       state_(kCreated),
       current_bytes_(0) {
+  media_log_->AddEvent(media_log_->CreatePipelineStateChangedEvent(kCreated));
   ResetState();
+  media_log_->AddEvent(
+      media_log_->CreateEvent(MediaLogEvent::PIPELINE_CREATED));
 }
 
 PipelineImpl::~PipelineImpl() {
@@ -76,6 +81,9 @@ PipelineImpl::~PipelineImpl() {
   DCHECK(!running_) << "Stop() must complete before destroying object";
   DCHECK(!stop_pending_);
   DCHECK(!seek_pending_);
+
+  media_log_->AddEvent(
+      media_log_->CreateEvent(MediaLogEvent::PIPELINE_DESTROYED));
 }
 
 void PipelineImpl::Init(PipelineStatusCallback* ended_callback,
@@ -381,8 +389,9 @@ void PipelineImpl::ResetState() {
   clock_->SetTime(kZero);
 }
 
-void PipelineImpl::set_state(State next_state) {
+void PipelineImpl::SetState(State next_state) {
   state_ = next_state;
+  media_log_->AddEvent(media_log_->CreatePipelineStateChangedEvent(next_state));
 }
 
 bool PipelineImpl::IsPipelineOk() {
@@ -621,10 +630,10 @@ void PipelineImpl::StartTask(FilterCollection* filter_collection,
   bool raw_media = (base::strncasecmp(url.c_str(), kRawMediaScheme,
                                       strlen(kRawMediaScheme)) == 0);
   if (raw_media) {
-    set_state(kInitVideoDecoder);
+    SetState(kInitVideoDecoder);
     InitializeVideoDecoder(NULL);
   } else {
-    set_state(kInitDemuxer);
+    SetState(kInitDemuxer);
     InitializeDemuxer();
   }
 }
@@ -662,7 +671,7 @@ void PipelineImpl::InitializeTask() {
 
   // Demuxer created, create audio decoder.
   if (state_ == kInitDemuxer) {
-    set_state(kInitAudioDecoder);
+    SetState(kInitAudioDecoder);
     // If this method returns false, then there's no audio stream.
     if (InitializeAudioDecoder(demuxer_))
       return;
@@ -670,7 +679,8 @@ void PipelineImpl::InitializeTask() {
 
   // Assuming audio decoder was created, create audio renderer.
   if (state_ == kInitAudioDecoder) {
-    set_state(kInitAudioRenderer);
+    SetState(kInitAudioRenderer);
+
     // Returns false if there's no audio stream.
     if (InitializeAudioRenderer(pipeline_init_state_->audio_decoder_)) {
       base::AutoLock auto_lock(lock_);
@@ -682,14 +692,14 @@ void PipelineImpl::InitializeTask() {
   // Assuming audio renderer was created, create video decoder.
   if (state_ == kInitAudioRenderer) {
     // Then perform the stage of initialization, i.e. initialize video decoder.
-    set_state(kInitVideoDecoder);
+    SetState(kInitVideoDecoder);
     if (InitializeVideoDecoder(demuxer_))
       return;
   }
 
   // Assuming video decoder was created, create video renderer.
   if (state_ == kInitVideoDecoder) {
-    set_state(kInitVideoRenderer);
+    SetState(kInitVideoRenderer);
     if (InitializeVideoRenderer(pipeline_init_state_->video_decoder_)) {
       base::AutoLock auto_lock(lock_);
       has_video_ = true;
@@ -725,7 +735,7 @@ void PipelineImpl::InitializeTask() {
 
     // Fire the seek request to get the filters to preroll.
     seek_pending_ = true;
-    set_state(kSeeking);
+    SetState(kSeeking);
     if (demuxer_)
       seek_timestamp_ = demuxer_->GetStartTime();
     else
@@ -864,7 +874,7 @@ void PipelineImpl::SeekTask(base::TimeDelta time,
   //   kSeeking (for each filter)
   //   kStarting (for each filter)
   //   kStarted
-  set_state(kPausing);
+  SetState(kPausing);
   seek_timestamp_ = time;
   seek_callback_.reset(seek_callback);
 
@@ -908,7 +918,7 @@ void PipelineImpl::NotifyEndedTask() {
   }
 
   // Transition to ended, executing the callback if present.
-  set_state(kEnded);
+  SetState(kEnded);
   if (ended_callback_.get()) {
     ended_callback_->Run(status_);
   }
@@ -958,7 +968,7 @@ void PipelineImpl::FilterStateTransitionTask() {
 
   // Decrement the number of remaining transitions, making sure to transition
   // to the next state if needed.
-  set_state(FindNextState(state_));
+  SetState(FindNextState(state_));
   if (state_ == kSeeking) {
     base::AutoLock auto_lock(lock_);
     clock_->SetTime(seek_timestamp_);
@@ -1018,16 +1028,16 @@ void PipelineImpl::TeardownStateTransitionTask() {
   DCHECK(IsPipelineTearingDown());
   switch (state_) {
     case kStopping:
-      set_state(error_caused_teardown_ ? kError : kStopped);
+      SetState(error_caused_teardown_ ? kError : kStopped);
       FinishDestroyingFiltersTask();
       break;
     case kPausing:
-      set_state(kFlushing);
+      SetState(kFlushing);
       pipeline_filter_->Flush(
           NewCallback(this, &PipelineImpl::OnTeardownStateTransition));
       break;
     case kFlushing:
-      set_state(kStopping);
+      SetState(kStopping);
       pipeline_filter_->Stop(
           NewCallback(this, &PipelineImpl::OnTeardownStateTransition));
       break;
@@ -1254,7 +1264,7 @@ void PipelineImpl::TearDownPipeline() {
   switch (state_) {
     case kCreated:
     case kError:
-      set_state(kStopped);
+      SetState(kStopped);
       // Need to put this in the message loop to make sure that it comes
       // after any pending callback tasks that are already queued.
       message_loop_->PostTask(FROM_HERE,
@@ -1271,7 +1281,7 @@ void PipelineImpl::TearDownPipeline() {
       pipeline_init_state_.reset();
       filter_collection_.reset();
 
-      set_state(kStopping);
+      SetState(kStopping);
       pipeline_filter_->Stop(
           NewCallback(this, &PipelineImpl::OnTeardownStateTransition));
 
@@ -1282,7 +1292,7 @@ void PipelineImpl::TearDownPipeline() {
     case kSeeking:
     case kFlushing:
     case kStarting:
-      set_state(kStopping);
+      SetState(kStopping);
       pipeline_filter_->Stop(
           NewCallback(this, &PipelineImpl::OnTeardownStateTransition));
 
@@ -1295,7 +1305,7 @@ void PipelineImpl::TearDownPipeline() {
 
     case kStarted:
     case kEnded:
-      set_state(kPausing);
+      SetState(kPausing);
       pipeline_filter_->Pause(
           NewCallback(this, &PipelineImpl::OnTeardownStateTransition));
       break;
diff --git a/media/base/pipeline_impl.h b/media/base/pipeline_impl.h
index caf4e19f..6fce5dc 100644
--- a/media/base/pipeline_impl.h
+++ b/media/base/pipeline_impl.h
@@ -27,6 +27,8 @@
 
 namespace media {
 
+class MediaLog;
+
 // Adapter for using asynchronous Pipeline methods in code that wants to run
 // synchronously.  To use, construct an instance of this class and pass the
 // |Callback()| to the Pipeline method requiring a callback.  Then Wait() for
@@ -93,7 +95,7 @@ class PipelineStatusNotification {
 // "Stopped" state.
 class PipelineImpl : public Pipeline, public FilterHost {
  public:
-  explicit PipelineImpl(MessageLoop* message_loop);
+  explicit PipelineImpl(MessageLoop* message_loop, MediaLog* media_log);
 
   // Pipeline implementation.
   virtual void Init(PipelineStatusCallback* ended_callback,
@@ -128,6 +130,8 @@ class PipelineImpl : public Pipeline, public FilterHost {
   void SetClockForTesting(Clock* clock);
 
  private:
+  friend class MediaLog;
+
   // Pipeline states, as described above.
   enum State {
     kCreated,
@@ -154,7 +158,7 @@ class PipelineImpl : public Pipeline, public FilterHost {
   void ResetState();
 
   // Updates |state_|. All state transitions should use this call.
-  void set_state(State next_state);
+  void SetState(State next_state);
 
   // Simple method used to make sure the pipeline is running normally.
   bool IsPipelineOk();
@@ -314,6 +318,9 @@ class PipelineImpl : public Pipeline, public FilterHost {
   // Message loop used to execute pipeline tasks.
   MessageLoop* message_loop_;
 
+  // MediaLog to which to log events.
+  scoped_refptr<MediaLog> media_log_;
+
   // Lock used to serialize access for the following data members.
   mutable base::Lock lock_;
 
diff --git a/media/base/pipeline_impl_unittest.cc b/media/base/pipeline_impl_unittest.cc
index 42496a3..18b9576 100644
--- a/media/base/pipeline_impl_unittest.cc
+++ b/media/base/pipeline_impl_unittest.cc
@@ -7,9 +7,10 @@
 #include "base/callback.h"
 #include "base/stl_util.h"
 #include "base/threading/simple_thread.h"
-#include "media/base/pipeline_impl.h"
-#include "media/base/filters.h"
 #include "media/base/filter_host.h"
+#include "media/base/filters.h"
+#include "media/base/media_log.h"
+#include "media/base/pipeline_impl.h"
 #include "media/base/mock_callback.h"
 #include "media/base/mock_filters.h"
 #include "testing/gtest/include/gtest/gtest.h"
@@ -61,7 +62,7 @@ class CallbackHelper {
 class PipelineImplTest : public ::testing::Test {
  public:
   PipelineImplTest()
-      : pipeline_(new PipelineImpl(&message_loop_)) {
+      : pipeline_(new PipelineImpl(&message_loop_, new MediaLog())) {
     pipeline_->Init(
         NewCallback(reinterpret_cast<CallbackHelper*>(&callbacks_),
                     &CallbackHelper::OnEnded),