Bug 1042765 - Better logging for GMP plugins r=cpearce a=sylvestre
authorRandell Jesup <rjesup@jesup.org>
Thu, 24 Jul 2014 21:47:44 -0400
changeset 217417 126d41d598be3b3f5b0c0080d8ebb885f89e5d69
parent 217416 cf771b63d6d78d648de5e220bc3751f48ef54c5b
child 217418 79626072eee791fda8e9b994f7b862ffc32db9ea
push id515
push userraliiev@mozilla.com
push dateMon, 06 Oct 2014 12:51:51 +0000
treeherdermozilla-release@267c7a481bef [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewerscpearce, sylvestre
bugs1042765
milestone33.0a2
Bug 1042765 - Better logging for GMP plugins r=cpearce a=sylvestre
content/media/gmp/GMPParent.cpp
content/media/gmp/GMPService.cpp
content/media/gmp/GMPVideoDecoderParent.cpp
content/media/gmp/GMPVideoEncoderParent.cpp
media/webrtc/signaling/src/media-conduit/WebrtcGmpVideoCodec.cpp
--- a/content/media/gmp/GMPParent.cpp
+++ b/content/media/gmp/GMPParent.cpp
@@ -1,14 +1,15 @@
 /* -*- Mode: C++; tab-width: 2; indent-tabs-mode: nil; c-basic-offset: 2 -*- */
 /* This Source Code Form is subject to the terms of the Mozilla Public
  * License, v. 2.0. If a copy of the MPL was not distributed with this
  * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
 
 #include "GMPParent.h"
+#include "prlog.h"
 #include "nsComponentManagerUtils.h"
 #include "nsComponentManagerUtils.h"
 #include "nsIInputStream.h"
 #include "nsILineInputStream.h"
 #include "nsNetUtil.h"
 #include "nsCharSeparatedTokenizer.h"
 #include "nsThreadUtils.h"
 #include "nsIRunnable.h"
@@ -21,16 +22,36 @@
 using mozilla::dom::CrashReporterParent;
 
 #ifdef MOZ_CRASHREPORTER
 using CrashReporter::AnnotationTable;
 using CrashReporter::GetIDFromMinidump;
 #endif
 
 namespace mozilla {
+
+#ifdef LOG
+#undef LOG
+#endif
+
+#ifdef PR_LOGGING
+extern PRLogModuleInfo* GetGMPLog();
+
+#define LOGD(msg) PR_LOG(GetGMPLog(), PR_LOG_DEBUG, msg)
+#define LOG(level, msg) PR_LOG(GetGMPLog(), (level), msg)
+#else
+#define LOGD(msg)
+#define LOG(level, msg)
+#endif
+
+#ifdef __CLASS__
+#undef __CLASS__
+#endif
+#define __CLASS__ "GMPParent"
+
 namespace gmp {
 
 GMPParent::GMPParent()
   : mState(GMPStateNotLoaded)
   , mProcess(nullptr)
   , mDeleteProcessOnlyOnUnload(false)
   , mAbnormalShutdownInProgress(false)
 {
@@ -66,16 +87,18 @@ GMPParent::Init(GeckoMediaPluginService 
   mService = aService;
   mDirectory = aPluginDir;
 
   nsAutoString leafname;
   nsresult rv = aPluginDir->GetLeafName(leafname);
   if (NS_FAILED(rv)) {
     return rv;
   }
+  LOGD(("%s::%s: %p for %s", __CLASS__, __FUNCTION__, this, 
+       NS_LossyConvertUTF16toASCII(leafname).get()));
 
   MOZ_ASSERT(leafname.Length() > 4);
   mName = Substring(leafname, 4);
 
   return ReadGMPMetaData();
 }
 
 void
@@ -92,16 +115,17 @@ GMPParent::LoadProcess()
   MOZ_ASSERT(mDirectory, "Plugin directory cannot be NULL!");
   MOZ_ASSERT(GMPThread() == NS_GetCurrentThread());
   MOZ_ASSERT(mState == GMPStateNotLoaded);
 
   nsAutoCString path;
   if (NS_FAILED(mDirectory->GetNativePath(path))) {
     return NS_ERROR_FAILURE;
   }
+  LOGD(("%s::%s: %p for %s", __CLASS__, __FUNCTION__, this, path.get()));
 
   if (!mProcess) {
     mProcess = new GMPProcessParent(path.get());
     if (!mProcess->Launch(30 * 1000)) {
       mProcess->Delete();
       mProcess = nullptr;
       return NS_ERROR_FAILURE;
     }
@@ -131,16 +155,17 @@ GMPParent::CloseIfUnused()
       mVideoEncoders.IsEmpty()) {
     Shutdown();
   }
 }
 
 void
 GMPParent::CloseActive(bool aDieWhenUnloaded)
 {
+  LOGD(("%s::%s: %p state %d", __CLASS__, __FUNCTION__, this, mState));
   if (aDieWhenUnloaded) {
     mDeleteProcessOnlyOnUnload = true; // don't allow this to go back...
   }
   if (mState == GMPStateLoaded) {
     mState = GMPStateUnloading;
   }
 
   // Invalidate and remove any remaining API objects.
@@ -157,16 +182,17 @@ GMPParent::CloseActive(bool aDieWhenUnlo
   // the plugin-container until they're all safely shut down via
   // CloseIfUnused();
   CloseIfUnused();
 }
 
 void
 GMPParent::Shutdown()
 {
+  LOGD(("%s::%s: %p", __CLASS__, __FUNCTION__, this));
   MOZ_ASSERT(GMPThread() == NS_GetCurrentThread());
 
   if (mAbnormalShutdownInProgress) {
     return;
   }
   MOZ_ASSERT(mVideoDecoders.IsEmpty() && mVideoEncoders.IsEmpty());
   if (mState == GMPStateNotLoaded || mState == GMPStateClosing) {
     return;
@@ -182,16 +208,17 @@ GMPParent::Shutdown()
     mService->ReAddOnGMPThread(self);
   } // else we've been asked to die and stay dead
   MOZ_ASSERT(mState == GMPStateNotLoaded);
 }
 
 void
 GMPParent::DeleteProcess()
 {
+  LOGD(("%s::%s: %p", __CLASS__, __FUNCTION__, this));
   // Don't Close() twice!
   // Probably remove when bug 1043671 is resolved
   MOZ_ASSERT(mState == GMPStateClosing);
   Close();
   mProcess->Delete();
   mProcess = nullptr;
   mState = GMPStateNotLoaded;
 }
@@ -380,20 +407,20 @@ GMPNotifyObservers(nsAString& aData)
 {
   nsCOMPtr<nsIObserverService> obs = mozilla::services::GetObserverService();
   if (obs) {
     nsString temp(aData);
     obs->NotifyObservers(nullptr, "gmp-plugin-crash", temp.get());
   }
 }
 #endif
-
 void
 GMPParent::ActorDestroy(ActorDestroyReason aWhy)
 {
+  LOGD(("%s::%s: %p (%d)", __CLASS__, __FUNCTION__, this, (int) aWhy));
 #ifdef MOZ_CRASHREPORTER
   if (AbnormalShutdown == aWhy) {
     nsString dumpID;
     GetCrashID(dumpID);
     nsString id;
     // use the parent address to identify it
     // We could use any unique-to-the-parent value
     id.AppendInt(reinterpret_cast<uint64_t>(this));
--- a/content/media/gmp/GMPService.cpp
+++ b/content/media/gmp/GMPService.cpp
@@ -1,29 +1,52 @@
 /* -*- Mode: C++; tab-width: 2; indent-tabs-mode: nil; c-basic-offset: 2 -*- */
 /* This Source Code Form is subject to the terms of the Mozilla Public
  * License, v. 2.0. If a copy of the MPL was not distributed with this
  * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
 
 #include "GMPService.h"
+#include "prlog.h"
 #include "GMPParent.h"
 #include "GMPVideoDecoderParent.h"
 #include "nsIObserverService.h"
 #include "GeckoChildProcessHost.h"
 #include "mozilla/Preferences.h"
 #include "mozilla/ClearOnShutdown.h"
 #include "mozilla/SyncRunnable.h"
 #include "nsXPCOMPrivate.h"
 #include "mozilla/Services.h"
 #include "nsNativeCharsetUtils.h"
 #include "nsIConsoleService.h"
 #include "mozilla/unused.h"
 #include "runnable_utils.h"
 
 namespace mozilla {
+
+#ifdef LOG
+#undef LOG
+#endif
+
+#ifdef PR_LOGGING
+PRLogModuleInfo*
+GetGMPLog()
+{
+  static PRLogModuleInfo *sLog;
+  if (!sLog)
+    sLog = PR_NewLogModule("GMP");
+  return sLog;
+}
+
+#define LOGD(msg) PR_LOG(GetGMPLog(), PR_LOG_DEBUG, msg)
+#define LOG(level, msg) PR_LOG(GetGMPLog(), (level), msg)
+#else
+#define LOGD(msg)
+#define LOG(leve1, msg)
+#endif
+
 namespace gmp {
 
 static StaticRefPtr<GeckoMediaPluginService> sSingletonService;
 
 class GMPServiceCreateHelper MOZ_FINAL : public nsRunnable
 {
   nsRefPtr<GeckoMediaPluginService> mService;
 
@@ -224,20 +247,25 @@ GeckoMediaPluginService::GetGMPVideoDeco
 
   if (mShuttingDownOnGMPThread) {
     return NS_ERROR_FAILURE;
   }
 
   nsRefPtr<GMPParent> gmp = SelectPluginForAPI(aOrigin,
                                                NS_LITERAL_CSTRING("decode-video"),
                                                *aTags);
+#ifdef PR_LOGGING
+  nsCString api = (*aTags)[0];
+  LOGD(("%s: %p returning %p for api %s", __FUNCTION__, (void *)this, (void *)gmp, api.get()));
+#endif
   if (!gmp) {
     return NS_ERROR_FAILURE;
   }
 
+
   GMPVideoDecoderParent* gmpVDP;
   nsresult rv = gmp->GetGMPVideoDecoder(&gmpVDP);
   if (NS_FAILED(rv)) {
     return rv;
   }
 
   *aGMPVD = gmpVDP;
   *aOutVideoHost = &gmpVDP->Host();
@@ -258,16 +286,20 @@ GeckoMediaPluginService::GetGMPVideoEnco
 
   if (mShuttingDownOnGMPThread) {
     return NS_ERROR_FAILURE;
   }
 
   nsRefPtr<GMPParent> gmp = SelectPluginForAPI(aOrigin,
                                                NS_LITERAL_CSTRING("encode-video"),
                                                *aTags);
+#ifdef PR_LOGGING
+  nsCString api = (*aTags)[0];
+  LOGD(("%s: %p returning %p for api %s", __FUNCTION__, (void *)this, (void *)gmp, api.get()));
+#endif
   if (!gmp) {
     return NS_ERROR_FAILURE;
   }
 
   GMPVideoEncoderParent* gmpVEP;
   nsresult rv = gmp->GetGMPVideoEncoder(&gmpVEP);
   if (NS_FAILED(rv)) {
     return rv;
--- a/content/media/gmp/GMPVideoDecoderParent.cpp
+++ b/content/media/gmp/GMPVideoDecoderParent.cpp
@@ -1,32 +1,47 @@
 /* -*- Mode: C++; tab-width: 2; indent-tabs-mode: nil; c-basic-offset: 2 -*- */
 /* This Source Code Form is subject to the terms of the Mozilla Public
  * License, v. 2.0. If a copy of the MPL was not distributed with this
  * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
 
 #include "GMPVideoDecoderParent.h"
+#include "prlog.h"
+#include "mozilla/unused.h"
+#include "nsAutoRef.h"
+#include "nsThreadUtils.h"
 #include "GMPVideoEncodedFrameImpl.h"
 #include "GMPVideoi420FrameImpl.h"
 #include "GMPParent.h"
-#include <stdio.h>
-#include "mozilla/unused.h"
 #include "GMPMessageUtils.h"
-#include "nsAutoRef.h"
-#include "nsThreadUtils.h"
 #include "mozilla/gmp/GMPTypes.h"
 
 template <>
 class nsAutoRefTraits<GMPVideoEncodedFrame> : public nsPointerRefTraits<GMPVideoEncodedFrame>
 {
 public:
   static void Release(GMPVideoEncodedFrame* aFrame) { aFrame->Destroy(); }
 };
 
 namespace mozilla {
+
+#ifdef LOG
+#undef LOG
+#endif
+
+#ifdef PR_LOGGING
+extern PRLogModuleInfo* GetGMPLog();
+
+#define LOGD(msg) PR_LOG(GetGMPLog(), PR_LOG_DEBUG, msg)
+#define LOG(level, msg) PR_LOG(GetGMPLog(), (level), msg)
+#else
+#define LOGD(msg)
+#define LOG(level, msg)
+#endif
+
 namespace gmp {
 
 // States:
 // Initial: mIsOpen == false
 //    on InitDecode success -> Open
 //    on Shutdown -> Dead
 // Open: mIsOpen == true
 //    on Close -> Dead
@@ -53,16 +68,17 @@ GMPVideoDecoderParent::Host()
 {
   return mVideoHost;
 }
 
 // Note: may be called via Terminated()
 void
 GMPVideoDecoderParent::Close()
 {
+  LOGD(("%s: %p", __FUNCTION__, this));
   MOZ_ASSERT(mPlugin->GMPThread() == NS_GetCurrentThread());
   // Consumer is done with us; we can shut down.  No more callbacks should
   // be made to mCallback.  Note: do this before Shutdown()!
   mCallback = nullptr;
   // Let Shutdown mark us as dead so it knows if we had been alive
 
   // In case this is the last reference
   nsRefPtr<GMPVideoDecoderParent> kungfudeathgrip(this);
@@ -171,16 +187,17 @@ GMPVideoDecoderParent::Drain()
   // Async IPC, we don't have access to a return value.
   return NS_OK;
 }
 
 // Note: Consider keeping ActorDestroy sync'd up when making changes here.
 nsresult
 GMPVideoDecoderParent::Shutdown()
 {
+  LOGD(("%s: %p", __FUNCTION__, this));
   MOZ_ASSERT(mPlugin->GMPThread() == NS_GetCurrentThread());
 
   // Notify client we're gone!  Won't occur after Close()
   if (mCallback) {
     mCallback->Terminated();
     mCallback = nullptr;
   }
   mVideoHost.DoneWithAPI();
@@ -307,16 +324,18 @@ GMPVideoDecoderParent::AnswerNeedShmem(c
                                        Shmem* aMem)
 {
   ipc::Shmem mem;
 
   if (!mVideoHost.SharedMemMgr()->MgrAllocShmem(GMPSharedMem::kGMPFrameData,
                                                 aFrameBufferSize,
                                                 ipc::SharedMemory::TYPE_BASIC, &mem))
   {
+    LOG(PR_LOG_ERROR, ("%s: Failed to get a shared mem buffer for Child! size %u",
+                       __FUNCTION__, aFrameBufferSize));
     return false;
   }
   *aMem = mem;
   mem = ipc::Shmem();
   return true;
 }
 
 bool
--- a/content/media/gmp/GMPVideoEncoderParent.cpp
+++ b/content/media/gmp/GMPVideoEncoderParent.cpp
@@ -1,32 +1,52 @@
 /* -*- Mode: C++; tab-width: 2; indent-tabs-mode: nil; c-basic-offset: 2 -*- */
 /* This Source Code Form is subject to the terms of the Mozilla Public
  * License, v. 2.0. If a copy of the MPL was not distributed with this
  * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
 
 #include "GMPVideoEncoderParent.h"
+#include "prlog.h"
 #include "GMPVideoi420FrameImpl.h"
 #include "GMPVideoEncodedFrameImpl.h"
-#include <stdio.h>
 #include "mozilla/unused.h"
 #include "GMPMessageUtils.h"
 #include "nsAutoRef.h"
 #include "GMPParent.h"
 #include "mozilla/gmp/GMPTypes.h"
 #include "nsThreadUtils.h"
 
 template <>
 class nsAutoRefTraits<GMPVideoi420Frame> : public nsPointerRefTraits<GMPVideoi420Frame>
 {
 public:
   static void Release(GMPVideoi420Frame* aFrame) { aFrame->Destroy(); }
 };
 
 namespace mozilla {
+
+#ifdef LOG
+#undef LOG
+#endif
+
+#ifdef PR_LOGGING
+extern PRLogModuleInfo* GetGMPLog();
+
+#define LOGD(msg) PR_LOG(GetGMPLog(), PR_LOG_DEBUG, msg)
+#define LOG(level, msg) PR_LOG(GetGMPLog(), (level), msg)
+#else
+#define LOGD(msg)
+#define LOG(level, msg)
+#endif
+
+#ifdef __CLASS__
+#undef __CLASS__
+#endif
+#define __CLASS__ "GMPVideoEncoderParent"
+
 namespace gmp {
 
 // States:
 // Initial: mIsOpen == false
 //    on InitDecode success -> Open
 //    on Shutdown -> Dead
 // Open: mIsOpen == true
 //    on Close -> Dead
@@ -53,16 +73,17 @@ GMPVideoEncoderParent::Host()
 {
   return mVideoHost;
 }
 
 // Note: may be called via Terminated()
 void
 GMPVideoEncoderParent::Close()
 {
+  LOGD(("%s::%s: %p", __CLASS__, __FUNCTION__, this));
   MOZ_ASSERT(mPlugin->GMPThread() == NS_GetCurrentThread());
   // Consumer is done with us; we can shut down.  No more callbacks should
   // be made to mCallback.  Note: do this before Shutdown()!
   mCallback = nullptr;
   // Let Shutdown mark us as dead so it knows if we had been alive
 
   // In case this is the last reference
   nsRefPtr<GMPVideoEncoderParent> kungfudeathgrip(this);
@@ -72,16 +93,17 @@ GMPVideoEncoderParent::Close()
 
 GMPErr
 GMPVideoEncoderParent::InitEncode(const GMPVideoCodec& aCodecSettings,
                                   const nsTArray<uint8_t>& aCodecSpecific,
                                   GMPVideoEncoderCallbackProxy* aCallback,
                                   int32_t aNumberOfCores,
                                   uint32_t aMaxPayloadSize)
 {
+  LOGD(("%s::%s: %p", __CLASS__, __FUNCTION__, this));
   if (mIsOpen) {
     NS_WARNING("Trying to re-init an in-use GMP video encoder!");
     return GMPGenericErr;;
   }
 
   MOZ_ASSERT(mPlugin->GMPThread() == NS_GetCurrentThread());
 
   if (!aCallback) {
@@ -188,16 +210,17 @@ GMPVideoEncoderParent::SetPeriodicKeyFra
   // Async IPC, we don't have access to a return value.
   return GMPNoErr;
 }
 
 // Note: Consider keeping ActorDestroy sync'd up when making changes here.
 void
 GMPVideoEncoderParent::Shutdown()
 {
+  LOGD(("%s::%s: %p", __CLASS__, __FUNCTION__, this));
   MOZ_ASSERT(mPlugin->GMPThread() == NS_GetCurrentThread());
 
   // Notify client we're gone!  Won't occur after Close()
   if (mCallback) {
     mCallback->Terminated();
     mCallback = nullptr;
   }
   mVideoHost.DoneWithAPI();
@@ -207,16 +230,17 @@ GMPVideoEncoderParent::Shutdown()
     unused << SendEncodingComplete();
   }
 }
 
 // Note: Keep this sync'd up with Shutdown
 void
 GMPVideoEncoderParent::ActorDestroy(ActorDestroyReason aWhy)
 {
+  LOGD(("%s::%s: %p (%d)", __CLASS__, __FUNCTION__, this, (int) aWhy));
   mIsOpen = false;
   if (mCallback) {
     // May call Close() (and Shutdown()) immediately or with a delay
     mCallback->Terminated();
     mCallback = nullptr;
   }
   if (mPlugin) {
     // Ignore any return code. It is OK for this to fail without killing the process.
--- a/media/webrtc/signaling/src/media-conduit/WebrtcGmpVideoCodec.cpp
+++ b/media/webrtc/signaling/src/media-conduit/WebrtcGmpVideoCodec.cpp
@@ -26,24 +26,29 @@
 
 namespace mozilla {
 
 #ifdef LOG
 #undef LOG
 #endif
 
 #ifdef PR_LOGGING
+#ifdef MOZILLA_INTERNAL_API
+extern PRLogModuleInfo* GetGMPLog();
+#else
+// For CPP unit tests
 PRLogModuleInfo*
 GetGMPLog()
 {
   static PRLogModuleInfo *sLog;
   if (!sLog)
     sLog = PR_NewLogModule("GMP");
   return sLog;
 }
+#endif
 #define LOGD(msg) PR_LOG(GetGMPLog(), PR_LOG_DEBUG, msg)
 #define LOG(level, msg) PR_LOG(GetGMPLog(), (level), msg)
 #else
 #define LOGD(msg)
 #define LOG(leve, msg)
 #endif
 
 // Encoder.
@@ -297,16 +302,17 @@ WebrtcGmpVideoEncoder::RegisterEncodeCom
   mCallback = aCallback;
 
   return WEBRTC_VIDEO_CODEC_OK;
 }
 
 int32_t
 WebrtcGmpVideoEncoder::Release()
 {
+  LOGD(("GMP Released:"));
   // Note: we only use SyncRunnables to access mGMP
   // Callbacks may occur at any time until we call Close (or receive
   // Terminated()), so call Close here synchronously.
   if (mGMPThread && mGMP) {
     mozilla::SyncRunnable::DispatchToThread(mGMPThread,
                                             WrapRunnableNM(&Encoder_Close_g, mGMP));
   }
   // Now safe to forget things
@@ -351,16 +357,17 @@ WebrtcGmpVideoEncoder::SetRates_g(uint32
 
   return WEBRTC_VIDEO_CODEC_OK;
 }
 
 // GMPVideoEncoderCallback virtual functions.
 void
 WebrtcGmpVideoEncoder::Terminated()
 {
+  LOGD(("GMP Encoder Terminated: %p", (void *)this));
   mCachedPluginId = PluginID();
 
   // We need to drop our reference to this
   mGMP->Close();
   mGMP = nullptr;
   // Could now notify that it's dead
 }
 
@@ -636,16 +643,17 @@ WebrtcGmpVideoDecoder::Reset()
 {
   // XXX ?
   return WEBRTC_VIDEO_CODEC_OK;
 }
 
 void
 WebrtcGmpVideoDecoder::Terminated()
 {
+  LOGD(("GMP Decoder Terminated: %p", (void *)this));
   mCachedPluginId = PluginID();
 
   mGMP->Close();
   mGMP = nullptr;
   // Could now notify that it's dead
 }
 
 void