diff --git a/content/media/GraphDriver.cpp b/content/media/GraphDriver.cpp index f35eb4534d5..d5d5abd086d 100644 --- a/content/media/GraphDriver.cpp +++ b/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 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 releaseEvent = @@ -185,6 +212,7 @@ private: void ThreadedDriver::Start() { + LIFECYCLE_LOG("Starting thread for a SystemClockDriver %p\n", mGraphImpl); nsCOMPtr 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; diff --git a/content/media/GraphDriver.h b/content/media/GraphDriver.h index 88e2887a8ed..de4263035fe 100644 --- a/content/media/GraphDriver.h +++ b/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; diff --git a/content/media/MediaStreamGraph.cpp b/content/media/MediaStreamGraph.cpp index a23ae98c72b..f141d0078c9 100644 --- a/content/media/MediaStreamGraph.cpp +++ b/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 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(); } } diff --git a/content/media/MediaStreamGraphImpl.h b/content/media/MediaStreamGraphImpl.h index 65228318100..f9fe4b725c5 100644 --- a/content/media/MediaStreamGraphImpl.h +++ b/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.