Bug 1392747 - add debug message to trace media shutdown process. r=jwwang

MozReview-Commit-ID: LL19lxlSJem

--HG--
extra : rebase_source : 57ace04484fd3c4f9687e0f79745249358edf56b

dom/media/MediaDecoder.cpp

@@ -462,6 +462,9 @@ MediaDecoder::Shutdown()
 
   DiscardOngoingSeekIfExists();
 
+#ifdef NIGHTLY_BUILD
+  DUMP("[DEBUG SHUTDOWN] %s: decoder=%p state machine=%p", __func__, this, mDecoderStateMachine.get());
+#endif
   // This changes the decoder state to SHUTDOWN and does other things
   // necessary to unblock the state machine thread if it's blocked, so
   // the asynchronous shutdown in nsDestroyStateMachine won't deadlock.

dom/media/MediaDecoderStateMachine.cpp

@@ -86,6 +86,12 @@ using namespace mozilla::media;
 #define SLOGW(x, ...) NS_WARNING(nsPrintfCString(SFMT(x, ##__VA_ARGS__)).get())
 #define SLOGE(x, ...) NS_DebugBreak(NS_DEBUG_WARNING, nsPrintfCString(SFMT(x, ##__VA_ARGS__)).get(), nullptr, __FILE__, __LINE__)
 
+#ifdef NIGHTLY_BUILD
+#define DEBUG_SHUTDOWN(fmt, ...) printf_stderr("[DEBUG SHUTDOWN] %s: " fmt "\n", __func__, ##__VA_ARGS__)
+#else
+#define DEBUG_SHUTDOWN(...) do { } while (0)
+#endif
+
 // Certain constants get stored as member variables and then adjusted by various
 // scale factors on a per-decoder basis. We want to make sure to avoid using these
 // constants directly, so we put them in a namespace.
@@ -2639,6 +2645,8 @@ ShutdownState::Enter()
   // Shut down the watch manager to stop further notifications.
   master->mWatchManager.Shutdown();
 
+  DEBUG_SHUTDOWN("state machine=%p reader=%p", this, Reader());
+
   return Reader()->Shutdown()->Then(
     OwnerThread(), __func__, master,
     &MediaDecoderStateMachine::FinishShutdown,
@@ -3463,6 +3471,7 @@ MediaDecoderStateMachine::FinishShutdown()
 {
   MOZ_ASSERT(OnTaskQueue());
   LOG("Shutting down state machine task queue");
+  DEBUG_SHUTDOWN("state machine=%p", this);
   return OwnerThread()->BeginShutdown();
 }
 

dom/media/MediaFormatReader.cpp

@@ -43,6 +43,12 @@ mozilla::LazyLogModule gMediaDemuxerLog("MediaDemuxer");
 
 #define NS_DispatchToMainThread(...) CompileError_UseAbstractMainThreadInstead
 
+#ifdef NIGHTLY_BUILD
+#define DEBUG_SHUTDOWN(fmt, ...) printf_stderr("[DEBUG SHUTDOWN] %s: " fmt "\n", __func__, ##__VA_ARGS__)
+#else
+#define DEBUG_SHUTDOWN(...) do { } while (0)
+#endif
+
 namespace mozilla {
 
 
@@ -446,6 +452,7 @@ MediaFormatReader::ShutdownPromisePool::Shutdown()
 {
   MOZ_DIAGNOSTIC_ASSERT(!mShutdown);
   mShutdown = true;
+  DEBUG_SHUTDOWN("pool=%p count=%d", this, mPromises.Count());
   if (mPromises.Count() == 0) {
     mOnShutdownComplete->Resolve(true, __func__);
   }
@@ -463,6 +470,7 @@ MediaFormatReader::ShutdownPromisePool::Track(RefPtr<ShutdownPromise> aPromise)
     [aPromise, this]() {
       MOZ_DIAGNOSTIC_ASSERT(mPromises.Contains(aPromise));
       mPromises.RemoveEntry(aPromise);
+      DEBUG_SHUTDOWN("pool=%p shutdown=%s count=%d", this, mShutdown ? "true" : "false", mPromises.Count());
       if (mShutdown && mPromises.Count() == 0) {
         mOnShutdownComplete->Resolve(true, __func__);
       }
@@ -479,6 +487,7 @@ MediaFormatReader::DecoderData::ShutdownDecoder()
     return;
   }
 
+  DEBUG_SHUTDOWN("decoder: '%s' (%p) flush:%d", mDecoder->GetDescriptionName().get(), mDecoder.get(), mFlushing);
   if (mFlushing) {
     // Flush is is in action. Shutdown will be initiated after flush completes.
     MOZ_DIAGNOSTIC_ASSERT(mShutdownPromise);
@@ -1274,6 +1283,7 @@ MediaFormatReader::Shutdown()
     ShutdownDecoder(TrackInfo::kVideoTrack);
   }
 
+  DEBUG_SHUTDOWN("reader=%p shutdown demuxer=%p", this, mDemuxer.get());
   mShutdownPromisePool->Track(mDemuxer->Shutdown());
   mDemuxer = nullptr;
 
@@ -1308,11 +1318,13 @@ MediaFormatReader::TearDownDecoders()
     mAudio.mTaskQueue->BeginShutdown();
     mAudio.mTaskQueue->AwaitShutdownAndIdle();
     mAudio.mTaskQueue = nullptr;
+    DEBUG_SHUTDOWN("reader=%p shut down audio task queue", this);
   }
   if (mVideo.mTaskQueue) {
     mVideo.mTaskQueue->BeginShutdown();
     mVideo.mTaskQueue->AwaitShutdownAndIdle();
     mVideo.mTaskQueue = nullptr;
+    DEBUG_SHUTDOWN("reader=%p shut down video task queue", this);
   }
 
   mDecoderFactory = nullptr;

dom/media/MediaShutdownManager.cpp

@@ -19,6 +19,12 @@ extern LazyLogModule gMediaDecoderLog;
 #define DECODER_LOG(type, msg) MOZ_LOG(gMediaDecoderLog, type, msg)
 #define LOGW(...) NS_WARNING(nsPrintfCString(__VA_ARGS__).get())
 
+#ifdef NIGHTLY_BUILD
+#define DEBUG_SHUTDOWN(fmt, ...) printf_stderr("[DEBUG SHUTDOWN] %s: " fmt "\n", __func__, ##__VA_ARGS__)
+#else
+#define DEBUG_SHUTDOWN(...) do { } while (0)
+#endif
+
 NS_IMPL_ISUPPORTS(MediaShutdownManager, nsIAsyncShutdownBlocker)
 
 MediaShutdownManager::MediaShutdownManager()
@@ -118,6 +124,7 @@ MediaShutdownManager::Register(MediaDecoder* aDecoder)
   // that's not going to work.
   MOZ_ASSERT(!mDecoders.Contains(aDecoder));
   mDecoders.PutEntry(aDecoder);
+  DEBUG_SHUTDOWN("decoder=%p, count=%d", aDecoder, mDecoders.Count());
   MOZ_ASSERT(mDecoders.Contains(aDecoder));
   MOZ_ASSERT(mDecoders.Count() > 0);
   return NS_OK;
@@ -131,6 +138,7 @@ MediaShutdownManager::Unregister(MediaDecoder* aDecoder)
     return;
   }
   mDecoders.RemoveEntry(aDecoder);
+  DEBUG_SHUTDOWN("decoder=%p, count=%d", aDecoder, mDecoders.Count());
   if (sInitPhase == XPCOMShutdownStarted && mDecoders.Count() == 0) {
     RemoveBlocker();
   }

dom/media/platforms/android/RemoteDataDecoder.cpp

@@ -20,6 +20,12 @@
 
 #include <jni.h>
 
+#ifdef NIGHTLY_BUILD
+#define DEBUG_SHUTDOWN(fmt, ...) printf_stderr("[DEBUG SHUTDOWN] %s: " fmt "\n", __func__, ##__VA_ARGS__)
+#else
+#define DEBUG_SHUTDOWN(...) do { } while (0)
+#endif
+
 #undef LOG
 #define LOG(arg, ...)                                                          \
   MOZ_LOG(sAndroidDecoderModuleLog,                                            \
@@ -540,6 +546,7 @@ RemoteDataDecoder::ProcessShutdown()
 
   mFormat = nullptr;
 
+  DEBUG_SHUTDOWN("decoder=%p mime=%s", this, mMimeType.get());
   return ShutdownPromise::CreateAndResolve(true, __func__);
 }