Bug 1392747 - add debug message to trace media shutdown process. r?jwwang
MozReview-Commit-ID: LL19lxlSJem
--- a/dom/media/MediaDecoder.cpp
+++ b/dom/media/MediaDecoder.cpp
@@ -458,16 +458,19 @@ MediaDecoder::Shutdown()
UnpinForSeek();
// Unwatch all watch targets to prevent further notifications.
mWatchManager.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.
if (mDecoderStateMachine) {
mTimedMetadataListener.Disconnect();
mMetadataLoadedListener.Disconnect();
mFirstFrameLoadedListener.Disconnect();
mOnPlaybackEvent.Disconnect();
--- a/dom/media/MediaDecoderStateMachine.cpp
+++ b/dom/media/MediaDecoderStateMachine.cpp
@@ -81,16 +81,22 @@ using namespace mozilla::media;
#define LOGE(x, ...) NS_DebugBreak(NS_DEBUG_WARNING, nsPrintfCString(FMT(x, ##__VA_ARGS__)).get(), nullptr, __FILE__, __LINE__)
// Used by StateObject and its sub-classes
#define SFMT(x, ...) "Decoder=%p state=%s " x, mMaster->mDecoderID, ToStateStr(GetState()), ##__VA_ARGS__
#define SLOG(x, ...) MOZ_LOG(gMediaDecoderLog, LogLevel::Debug, (SFMT(x, ##__VA_ARGS__)))
#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.
namespace detail {
// Resume a suspended video decoder to the current playback position plus this
// time premium for compensating the seeking delay.
static constexpr auto RESUME_VIDEO_PREMIUM = TimeUnit::FromMicroseconds(125000);
@@ -2634,16 +2640,18 @@ ShutdownState::Enter()
master->mDuration.DisconnectAll();
master->mCurrentPosition.DisconnectAll();
master->mPlaybackOffset.DisconnectAll();
master->mIsAudioDataAudible.DisconnectAll();
// 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,
&MediaDecoderStateMachine::FinishShutdown);
}
#define INIT_WATCHABLE(name, val) \
name(val, "MediaDecoderStateMachine::" #name)
@@ -3449,16 +3457,17 @@ MediaDecoderStateMachine::BeginShutdown(
&MediaDecoderStateMachine::Shutdown);
}
RefPtr<ShutdownPromise>
MediaDecoderStateMachine::FinishShutdown()
{
MOZ_ASSERT(OnTaskQueue());
LOG("Shutting down state machine task queue");
+ DEBUG_SHUTDOWN("state machine=%p", this);
return OwnerThread()->BeginShutdown();
}
void
MediaDecoderStateMachine::RunStateMachine()
{
MOZ_ASSERT(OnTaskQueue());
--- a/dom/media/MediaFormatReader.cpp
+++ b/dom/media/MediaFormatReader.cpp
@@ -38,16 +38,22 @@ using mozilla::layers::LayersBackend;
static mozilla::LazyLogModule sFormatDecoderLog("MediaFormatReader");
mozilla::LazyLogModule gMediaDemuxerLog("MediaDemuxer");
#define LOG(arg, ...) MOZ_LOG(sFormatDecoderLog, mozilla::LogLevel::Debug, ("MediaFormatReader(%p)::%s: " arg, this, __func__, ##__VA_ARGS__))
#define LOGV(arg, ...) MOZ_LOG(sFormatDecoderLog, mozilla::LogLevel::Verbose, ("MediaFormatReader(%p)::%s: " arg, this, __func__, ##__VA_ARGS__))
#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 {
typedef void* MediaDataDecoderID;
/**
* This helper class is used to report telemetry of the time used to recover a
* decoder from GPU crash.
@@ -441,16 +447,17 @@ private:
nsTHashtable<nsRefPtrHashKey<ShutdownPromise>> mPromises;
};
RefPtr<ShutdownPromise>
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__);
}
return mOnShutdownComplete;
}
void
MediaFormatReader::ShutdownPromisePool::Track(RefPtr<ShutdownPromise> aPromise)
@@ -458,32 +465,34 @@ MediaFormatReader::ShutdownPromisePool::
MOZ_DIAGNOSTIC_ASSERT(!mShutdown);
MOZ_DIAGNOSTIC_ASSERT(!mPromises.Contains(aPromise));
mPromises.PutEntry(aPromise);
aPromise->Then(
AbstractThread::GetCurrent(), __func__,
[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__);
}
});
}
void
MediaFormatReader::DecoderData::ShutdownDecoder()
{
MutexAutoLock lock(mMutex);
if (!mDecoder) {
// No decoder to shut down.
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);
mOwner->mShutdownPromisePool->Track(mShutdownPromise->Ensure(__func__));
// The order of decoder creation and shutdown is handled by LocalAllocPolicy
// and ShutdownPromisePool. MFR can now reset these members to a fresh state
// and be ready to create new decoders again without explicitly waiting for
// flush/shutdown to complete.
@@ -1269,16 +1278,17 @@ MediaFormatReader::Shutdown()
if (HasVideo()) {
mVideo.ResetDemuxer();
mVideo.mTrackDemuxer->BreakCycles();
mVideo.mTrackDemuxer = nullptr;
mVideo.ResetState();
ShutdownDecoder(TrackInfo::kVideoTrack);
}
+ DEBUG_SHUTDOWN("reader=%p shutdown demuxer=%p", this, mDemuxer.get());
mShutdownPromisePool->Track(mDemuxer->Shutdown());
mDemuxer = nullptr;
mOnTrackWaitingForKeyListener.Disconnect();
mShutdown = true;
return mShutdownPromisePool->Shutdown()
->Then(OwnerThread(), __func__, this,
@@ -1303,21 +1313,23 @@ MediaFormatReader::ShutdownDecoder(Track
RefPtr<ShutdownPromise>
MediaFormatReader::TearDownDecoders()
{
if (mAudio.mTaskQueue) {
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;
mPlatform = nullptr;
mVideoFrameContainer = nullptr;
ReleaseResources();
mBuffered.DisconnectAll();
--- a/dom/media/MediaShutdownManager.cpp
+++ b/dom/media/MediaShutdownManager.cpp
@@ -14,16 +14,22 @@
namespace mozilla {
#undef LOGW
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()
{
MOZ_ASSERT(NS_IsMainThread());
MOZ_DIAGNOSTIC_ASSERT(sInitPhase == NotInited);
}
@@ -113,29 +119,31 @@ MediaShutdownManager::Register(MediaDeco
}
if (sInitPhase == XPCOMShutdownStarted) {
return NS_ERROR_ABORT;
}
// Don't call Register() after you've Unregistered() all the decoders,
// 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;
}
void
MediaShutdownManager::Unregister(MediaDecoder* aDecoder)
{
MOZ_ASSERT(NS_IsMainThread());
if (!mDecoders.Contains(aDecoder)) {
return;
}
mDecoders.RemoveEntry(aDecoder);
+ DEBUG_SHUTDOWN("decoder=%p, count=%d", aDecoder, mDecoders.Count());
if (sInitPhase == XPCOMShutdownStarted && mDecoders.Count() == 0) {
RemoveBlocker();
}
}
NS_IMETHODIMP
MediaShutdownManager::GetName(nsAString& aName)
{
--- a/dom/media/platforms/android/RemoteDataDecoder.cpp
+++ b/dom/media/platforms/android/RemoteDataDecoder.cpp
@@ -15,16 +15,22 @@
#include "mozilla/Telemetry.h"
#include "nsIGfxInfo.h"
#include "nsPromiseFlatString.h"
#include "nsThreadUtils.h"
#include "prlog.h"
#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, \
mozilla::LogLevel::Debug, \
("RemoteDataDecoder(%p)::%s: " arg, this, __func__, ##__VA_ARGS__))
using namespace mozilla;
using namespace mozilla::gl;
@@ -535,16 +541,17 @@ RemoteDataDecoder::ProcessShutdown()
if (mJavaCallbacks) {
JavaCallbacksSupport::GetNative(mJavaCallbacks)->Cancel();
JavaCallbacksSupport::DisposeNative(mJavaCallbacks);
mJavaCallbacks = nullptr;
}
mFormat = nullptr;
+ DEBUG_SHUTDOWN("decoder=%p mime=%s", this, mMimeType.get());
return ShutdownPromise::CreateAndResolve(true, __func__);
}
static CryptoInfo::LocalRef
GetCryptoInfoFromSample(const MediaRawData* aSample)
{
auto& cryptoObj = aSample->mCrypto;