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.
--- 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