Bug 1062293 - Add specialized logging to track the lifetime state change of MediaStreamGraphs r=jesup

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.

--HG--
extra : rebase_source : 80df45d0851a06daac3abeab2ea4b5bc7e58a21d

content/media/GraphDriver.cpp

@@ -17,6 +17,20 @@ extern PRLogModuleInfo* gMediaStreamGraphLog;
 #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
@@ -68,7 +82,9 @@ void GraphDriver::SetGraphTime(GraphDriver* 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());
@@ -135,15 +151,20 @@ public:
   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;
@@ -163,7 +184,13 @@ public:
     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 =
@@ -185,6 +212,7 @@ private:
 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);
 }
@@ -432,14 +460,17 @@ AsyncCubebTask::Run()
 
   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) {
@@ -797,7 +828,7 @@ AudioCallbackDriver::DataCallback(AudioDataValue* aBuffer, long aFrames)
   }
 
   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;

content/media/GraphDriver.h

@@ -187,6 +187,10 @@ public:
    */
   void EnsureNextIterationLocked();
 
+  MediaStreamGraphImpl* GraphImpl() {
+    return mGraphImpl;
+  }
+
 protected:
   // Time of the start of this graph iteration.
   GraphTime mIterationStart;

content/media/MediaStreamGraph.cpp

@@ -45,6 +45,21 @@ PRLogModuleInfo* gMediaStreamGraphLog;
 #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.
  */
@@ -55,6 +70,7 @@ 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");
 }
 
 
@@ -1456,7 +1472,7 @@ public:
     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());
@@ -1559,6 +1575,23 @@ MediaStreamGraphImpl::RunInStableState(bool aSourceIsMSG)
       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];
@@ -1572,7 +1605,7 @@ MediaStreamGraphImpl::RunInStableState(bool aSourceIsMSG)
       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;
@@ -1581,6 +1614,7 @@ MediaStreamGraphImpl::RunInStableState(bool aSourceIsMSG)
         // 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);
       }
@@ -1605,6 +1639,9 @@ MediaStreamGraphImpl::RunInStableState(bool aSourceIsMSG)
         // or it might exit immediately.
         {
           MonitorAutoUnlock unlock(mMonitor);
+          LIFECYCLE_LOG("Reviving a graph (%p) ! %s\n",
+              this, CurrentDriver()->AsAudioCallbackDriver() ? "AudioDriver" :
+                                                               "SystemDriver");
           CurrentDriver()->Revive();
         }
       }
@@ -1622,7 +1659,10 @@ MediaStreamGraphImpl::RunInStableState(bool aSourceIsMSG)
         // 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();
       }
     }

content/media/MediaStreamGraphImpl.h

@@ -520,6 +520,9 @@ public:
    * 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.