Bug 1062293 - Add specialized logging to track the lifetime state change of MediaStreamGraphs r=jesup a=lmandel
authorPaul Adenot <paul@paul.cx>
Sun, 31 Aug 2014 14:19:48 +0200
changeset 224770 731305558f1caad7b6241cb94810589c05408628
parent 224769 bc2efaa7ed163ebec8b244acba05d82cbc4b3432
child 224771 94140d5b60085f363115e6dbd730af2b8f4ec828
push id3979
push userraliiev@mozilla.com
push dateMon, 13 Oct 2014 16:35:44 +0000
treeherdermozilla-beta@30f2cc610691 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersjesup, lmandel
bugs1062293
milestone34.0a2
Bug 1062293 - Add specialized logging to track the lifetime state change of MediaStreamGraphs r=jesup a=lmandel As noted in the comment, it is very useful to have this interleaved with the ADB logcat on Android/b2g, because this way we can correlate gecko state with the state of the Android HAL.
content/media/GraphDriver.cpp
content/media/GraphDriver.h
content/media/MediaStreamGraph.cpp
content/media/MediaStreamGraphImpl.h
--- a/content/media/GraphDriver.cpp
+++ b/content/media/GraphDriver.cpp
@@ -12,16 +12,30 @@
 
 #ifdef PR_LOGGING
 extern PRLogModuleInfo* gMediaStreamGraphLog;
 #define STREAM_LOG(type, msg) PR_LOG(gMediaStreamGraphLog, type, msg)
 #else
 #define STREAM_LOG(type, msg)
 #endif
 
+// We don't use NSPR log here because we want this interleaved with adb logcat
+// on Android/B2G
+// #define ENABLE_LIFECYCLE_LOG
+#ifdef ENABLE_LIFECYCLE_LOG
+#ifdef ANDROID
+#include "android/log.h"
+#define LIFECYCLE_LOG(args...)  __android_log_print(ANDROID_LOG_INFO, "Gecko - MSG" , ## __VA_ARGS__); printf(__VA_ARGS__);printf("\n");
+#else
+#define LIFECYCLE_LOG(...) printf(__VA_ARGS__);printf("\n");
+#endif
+#else
+#define LIFECYCLE_LOG(...)
+#endif
+
 namespace mozilla {
 
 struct AutoProfilerUnregisterThread
 {
   // The empty ctor is used to silence a pre-4.8.0 GCC unused variable warning.
   AutoProfilerUnregisterThread()
   {
   }
@@ -63,17 +77,19 @@ void GraphDriver::SetGraphTime(GraphDriv
   STREAM_LOG(PR_LOG_DEBUG, ("Setting previous driver: %p (%s)", aPreviousDriver, aPreviousDriver->AsAudioCallbackDriver() ? "AudioCallbackDriver" : "SystemClockDriver"));
   MOZ_ASSERT(!mPreviousDriver);
   mPreviousDriver = aPreviousDriver;
 }
 
 void GraphDriver::SwitchAtNextIteration(GraphDriver* aNextDriver)
 {
 
-  STREAM_LOG(PR_LOG_DEBUG, ("Switching to new driver: %p (%s)", aNextDriver, aNextDriver->AsAudioCallbackDriver() ? "AudioCallbackDriver" : "SystemClockDriver"));
+  LIFECYCLE_LOG("Switching to new driver: %p (%s)",
+      aNextDriver, aNextDriver->AsAudioCallbackDriver() ?
+      "AudioCallbackDriver" : "SystemClockDriver");
   // Sometimes we switch twice to a new driver per iteration, this is probably a
   // bug.
   MOZ_ASSERT(!mNextDriver || !mNextDriver->AsAudioCallbackDriver());
   mNextDriver = aNextDriver;
 }
 
 void GraphDriver::EnsureImmediateWakeUpLocked()
 {
@@ -130,25 +146,30 @@ class MediaStreamGraphShutdownThreadRunn
 public:
   explicit MediaStreamGraphShutdownThreadRunnable(GraphDriver* aDriver)
     : mDriver(aDriver)
   {
   }
   NS_IMETHOD Run()
   {
     MOZ_ASSERT(NS_IsMainThread());
+
+    LIFECYCLE_LOG("MediaStreamGraphShutdownThreadRunnable for graph %p",
+        mDriver->GraphImpl());
     // We can't release an audio driver on the main thread, because it can be
     // blocking.
     if (mDriver->AsAudioCallbackDriver()) {
-      STREAM_LOG(PR_LOG_DEBUG, ("Releasing audio driver off main thread.\n"));
+      LIFECYCLE_LOG("Releasing audio driver off main thread.");
       nsRefPtr<AsyncCubebTask> releaseEvent =
-        new AsyncCubebTask(mDriver->AsAudioCallbackDriver(), AsyncCubebTask::SHUTDOWN);
+        new AsyncCubebTask(mDriver->AsAudioCallbackDriver(),
+                           AsyncCubebTask::SHUTDOWN);
       mDriver = nullptr;
       releaseEvent->Dispatch();
     } else {
+      LIFECYCLE_LOG("Dropping driver reference for SystemClockDriver.");
       mDriver = nullptr;
     }
     return NS_OK;
   }
 private:
   nsRefPtr<GraphDriver> mDriver;
 };
 
@@ -158,17 +179,23 @@ public:
     : mDriver(aDriver)
   {
   }
   NS_IMETHOD Run()
   {
     char aLocal;
     STREAM_LOG(PR_LOG_DEBUG, ("Starting system thread"));
     profiler_register_thread("MediaStreamGraph", &aLocal);
+    LIFECYCLE_LOG("Starting a new system driver for graph %p\n",
+                  mDriver->mGraphImpl);
     if (mDriver->mPreviousDriver) {
+      LIFECYCLE_LOG("%p releasing an AudioCallbackDriver(%p), for graph %p\n",
+                    mDriver,
+                    mDriver->mPreviousDriver.get(),
+                    mDriver->GraphImpl());
       MOZ_ASSERT(!mDriver->AsAudioCallbackDriver());
       // Stop and release the previous driver off-main-thread.
       nsRefPtr<AsyncCubebTask> releaseEvent =
         new AsyncCubebTask(mDriver->mPreviousDriver->AsAudioCallbackDriver(), AsyncCubebTask::SHUTDOWN);
       mDriver->mPreviousDriver = nullptr;
       releaseEvent->Dispatch();
     } else {
       MonitorAutoLock mon(mDriver->mGraphImpl->GetMonitor());
@@ -180,16 +207,17 @@ public:
   }
 private:
   ThreadedDriver* mDriver;
 };
 
 void
 ThreadedDriver::Start()
 {
+  LIFECYCLE_LOG("Starting thread for a SystemClockDriver  %p\n", mGraphImpl);
   nsCOMPtr<nsIRunnable> event = new MediaStreamGraphInitThreadRunnable(this);
   NS_NewNamedThread("MediaStreamGrph", getter_AddRefs(mThread), event);
 }
 
 void
 ThreadedDriver::Resume()
 {
   Start();
@@ -427,24 +455,27 @@ AsyncCubebTask::Run()
     // assumes the caller does.
     return NS_OK;
   }
 
   MOZ_ASSERT(mDriver);
 
   switch(mOperation) {
     case AsyncCubebOperation::INIT:
+      LIFECYCLE_LOG("AsyncCubebOperation::INIT\n");
       mDriver->Init();
       break;
     case AsyncCubebOperation::SHUTDOWN:
+      LIFECYCLE_LOG("AsyncCubebOperation::SHUTDOWN\n");
       mDriver->Stop();
       mDriver = nullptr;
       break;
     case AsyncCubebOperation::SLEEP: {
       {
+        LIFECYCLE_LOG("AsyncCubebOperation::SLEEP\n");
         MonitorAutoLock mon(mDriver->mGraphImpl->GetMonitor());
         // We might just have been awoken
         if (mDriver->mNeedAnotherIteration) {
           mDriver->mPauseRequested = false;
           mDriver->mWaitState = AudioCallbackDriver::WAITSTATE_RUNNING;
           break;
         }
         mDriver->Stop();
@@ -792,17 +823,17 @@ AudioCallbackDriver::DataCallback(AudioD
     mGraphImpl->SetCurrentDriver(mNextDriver);
     mNextDriver->Start();
     // Returning less than aFrames starts the draining and eventually stops the
     // audio thread. This function will never get called again.
     return aFrames - 1;
   }
 
   if (!stillProcessing) {
-    STREAM_LOG(PR_LOG_DEBUG, ("Stopping audio thread for MediaStreamGraph %p", this));
+    LIFECYCLE_LOG("Stopping audio thread for MediaStreamGraph %p", this);
     return aFrames - 1;
   }
   return aFrames;
 }
 
 void
 AudioCallbackDriver::StateCallback(cubeb_state aState)
 {
--- a/content/media/GraphDriver.h
+++ b/content/media/GraphDriver.h
@@ -182,16 +182,20 @@ public:
    */
   void EnsureNextIteration();
 
   /**
    * Same thing, but not locked.
    */
   void EnsureNextIterationLocked();
 
+  MediaStreamGraphImpl* GraphImpl() {
+    return mGraphImpl;
+  }
+
 protected:
   // Time of the start of this graph iteration.
   GraphTime mIterationStart;
   // Time of the end of this graph iteration.
   GraphTime mIterationEnd;
   // Time, in the future, for which blocking has been computed.
   GraphTime mStateComputedTime;
   GraphTime mNextStateComputedTime;
--- a/content/media/MediaStreamGraph.cpp
+++ b/content/media/MediaStreamGraph.cpp
@@ -40,26 +40,42 @@ namespace mozilla {
 
 #ifdef PR_LOGGING
 PRLogModuleInfo* gMediaStreamGraphLog;
 #define STREAM_LOG(type, msg) PR_LOG(gMediaStreamGraphLog, type, msg)
 #else
 #define STREAM_LOG(type, msg)
 #endif
 
+// #define ENABLE_LIFECYCLE_LOG
+
+// We don't use NSPR log here because we want this interleaved with adb logcat
+// on Android/B2G
+#ifdef ENABLE_LIFECYCLE_LOG
+#  ifdef ANDROID
+#    include "android/log.h"
+#    define LIFECYCLE_LOG(...)  __android_log_print(ANDROID_LOG_INFO, "Gecko - MSG", ## __VA_ARGS__); printf(__VA_ARGS__);printf("\n");
+#  else
+#    define LIFECYCLE_LOG(...) printf(__VA_ARGS__);printf("\n");
+#  endif
+#else
+#  define LIFECYCLE_LOG(...)
+#endif
+
 /**
  * The singleton graph instance.
  */
 static MediaStreamGraphImpl* gGraph;
 
 MediaStreamGraphImpl::~MediaStreamGraphImpl()
 {
   NS_ASSERTION(IsEmpty(),
                "All streams should have been destroyed by messages from the main thread");
   STREAM_LOG(PR_LOG_DEBUG, ("MediaStreamGraph %p destroyed", this));
+  LIFECYCLE_LOG("MediaStreamGraphImpl::~MediaStreamGraphImpl\n");
 }
 
 
 StreamTime
 MediaStreamGraphImpl::GetDesiredBufferEnd(MediaStream* aStream)
 {
   StreamTime current = IterationEnd() - aStream->mBufferStartTime;
   // When waking up media decoders, we need a longer safety margin, as it can
@@ -1451,17 +1467,17 @@ public:
   explicit MediaStreamGraphShutDownRunnable(MediaStreamGraphImpl* aGraph)
     : mGraph(aGraph)
   {}
   NS_IMETHOD Run()
   {
     NS_ASSERTION(mGraph->mDetectedNotRunning,
                  "We should know the graph thread control loop isn't running!");
 
-    STREAM_LOG(PR_LOG_DEBUG, ("Shutting down graph %p", mGraph.get()));
+    LIFECYCLE_LOG("Shutting down graph %p", mGraph.get());
 
     if (mGraph->CurrentDriver()->AsAudioCallbackDriver()) {
       MOZ_ASSERT(!mGraph->CurrentDriver()->AsAudioCallbackDriver()->InCallback());
     }
 
     mGraph->CurrentDriver()->Stop();
 
     // mGraph's thread is not running so it's OK to do whatever here
@@ -1554,38 +1570,56 @@ MediaStreamGraphImpl::RunInStableState(b
 
   {
     MonitorAutoLock lock(mMonitor);
     if (aSourceIsMSG) {
       MOZ_ASSERT(mPostedRunInStableStateEvent);
       mPostedRunInStableStateEvent = false;
     }
 
+#ifdef ENABLE_LIFECYCLE_LOG
+  // This should be kept in sync with the LifecycleState enum in
+  // MediaStreamGraphImpl.h
+  const char * LifecycleState_str[] = {
+    "LIFECYCLE_THREAD_NOT_STARTED",
+    "LIFECYCLE_RUNNING",
+    "LIFECYCLE_WAITING_FOR_MAIN_THREAD_CLEANUP",
+    "LIFECYCLE_WAITING_FOR_THREAD_SHUTDOWN",
+    "LIFECYCLE_WAITING_FOR_STREAM_DESTRUCTION"
+  };
+
+  if (mLifecycleState != LIFECYCLE_RUNNING) {
+    LIFECYCLE_LOG("Running %p in stable state. Current state: %s\n",
+        this, LifecycleState_str[mLifecycleState]);
+  }
+#endif
+
     runnables.SwapElements(mUpdateRunnables);
     for (uint32_t i = 0; i < mStreamUpdates.Length(); ++i) {
       StreamUpdate* update = &mStreamUpdates[i];
       if (update->mStream) {
         ApplyStreamUpdate(update);
       }
     }
     mStreamUpdates.Clear();
 
     if (mCurrentTaskMessageQueue.IsEmpty()) {
       if (mLifecycleState == LIFECYCLE_WAITING_FOR_MAIN_THREAD_CLEANUP && IsEmpty()) {
         // Complete shutdown. First, ensure that this graph is no longer used.
         // A new graph graph will be created if one is needed.
-        STREAM_LOG(PR_LOG_DEBUG, ("Disconnecting MediaStreamGraph %p", this));
+        LIFECYCLE_LOG("Disconnecting MediaStreamGraph %p", this);
         if (this == gGraph) {
           // null out gGraph if that's the graph being shut down
           gGraph = nullptr;
         }
         // Asynchronously clean up old graph. We don't want to do this
         // synchronously because it spins the event loop waiting for threads
         // to shut down, and we don't want to do that in a stable state handler.
         mLifecycleState = LIFECYCLE_WAITING_FOR_THREAD_SHUTDOWN;
+        LIFECYCLE_LOG("Sending MediaStreamGraphShutDownRunnable %p", this);
         nsCOMPtr<nsIRunnable> event = new MediaStreamGraphShutDownRunnable(this );
         NS_DispatchToMainThread(event);
       }
     } else {
       if (mLifecycleState <= LIFECYCLE_WAITING_FOR_MAIN_THREAD_CLEANUP) {
         MessageBlock* block = mBackMessageQueue.AppendElement();
         block->mMessages.SwapElements(mCurrentTaskMessageQueue);
         block->mGraphUpdateIndex = mNextGraphUpdateIndex;
@@ -1600,16 +1634,19 @@ MediaStreamGraphImpl::RunInStableState(b
       if (mLifecycleState == LIFECYCLE_WAITING_FOR_MAIN_THREAD_CLEANUP &&
           mRealtime && !mForceShutDown) {
         mLifecycleState = LIFECYCLE_RUNNING;
         // Revive the MediaStreamGraph since we have more messages going to it.
         // Note that we need to put messages into its queue before reviving it,
         // or it might exit immediately.
         {
           MonitorAutoUnlock unlock(mMonitor);
+          LIFECYCLE_LOG("Reviving a graph (%p) ! %s\n",
+              this, CurrentDriver()->AsAudioCallbackDriver() ? "AudioDriver" :
+                                                               "SystemDriver");
           CurrentDriver()->Revive();
         }
       }
     }
 
     // Don't start the thread for a non-realtime graph until it has been
     // explicitly started by StartNonRealtimeProcessing.
     if (mLifecycleState == LIFECYCLE_THREAD_NOT_STARTED &&
@@ -1617,17 +1654,20 @@ MediaStreamGraphImpl::RunInStableState(b
       mLifecycleState = LIFECYCLE_RUNNING;
       // Start the thread now. We couldn't start it earlier because
       // the graph might exit immediately on finding it has no streams. The
       // first message for a new graph must create a stream.
       {
         // We should exit the monitor for now, because starting a stream might
         // take locks, and we don't want to deadlock.
         MonitorAutoUnlock unlock(mMonitor);
-        STREAM_LOG(PR_LOG_DEBUG, ("Starting a graph ! %s\n", CurrentDriver()->AsAudioCallbackDriver() ? "AudioDriver" : "SystemDriver"));
+        LIFECYCLE_LOG("Starting a graph (%p) ! %s\n",
+                      this,
+                      CurrentDriver()->AsAudioCallbackDriver() ? "AudioDriver" :
+                                                                 "SystemDriver");
         CurrentDriver()->Start();
       }
     }
 
     if ((mForceShutDown || !mRealtime) &&
         mLifecycleState == LIFECYCLE_WAITING_FOR_MAIN_THREAD_CLEANUP) {
       // Defer calls to RunDuringShutdown() to happen while mMonitor is not held.
       for (uint32_t i = 0; i < mBackMessageQueue.Length(); ++i) {
--- a/content/media/MediaStreamGraphImpl.h
+++ b/content/media/MediaStreamGraphImpl.h
@@ -515,16 +515,19 @@ public:
    * object.
    * 2) Forced shutdown at application shutdown, or completion of a
    * non-realtime graph. A flag is set, RunThread() detects the flag and
    * exits, the next RunInStableState() detects the flag, and dispatches the
    * async event to Shutdown() the graph's threads. However the graph object
    * is not deleted. New messages for the graph are processed synchronously on
    * the main thread if necessary. When the last stream is destroyed, the
    * graph object is deleted.
+   *
+   * This should be kept in sync with the LifecycleState_str array in
+   * MediaStreamGraph.cpp
    */
   enum LifecycleState {
     // The graph thread hasn't started yet.
     LIFECYCLE_THREAD_NOT_STARTED,
     // RunThread() is running normally.
     LIFECYCLE_RUNNING,
     // In the following states, the graph thread is not running so
     // all "graph thread only" state in this class can be used safely