Bug 1208289 - Log outstanding frames in GMP DrainComplete() and detect dropped ResetComplete. r=jwwang

* * *
Bug 1208289 - Yet another bustage fix. r=bustage

dom/media/eme/EMEUtils.cpp

@@ -7,6 +7,7 @@
 #include "mozilla/EMEUtils.h"
 #include "nsServiceManagerUtils.h"
 #include "nsIConsoleService.h"
+#include "nsThreadUtils.h"
 
 namespace mozilla {
 
@@ -113,6 +114,13 @@ ParseKeySystem(const nsAString& aInputKeySystem,
 void
 LogToBrowserConsole(const nsAString& aMsg)
 {
+  if (!NS_IsMainThread()) {
+    nsAutoString msg(aMsg);
+    nsCOMPtr<nsIRunnable> task =
+      NS_NewRunnableFunction([msg]() { LogToBrowserConsole(msg); });
+    NS_DispatchToMainThread(task.forget(), NS_DISPATCH_NORMAL);
+    return;
+  }
   nsCOMPtr<nsIConsoleService> console(
     do_GetService("@mozilla.org/consoleservice;1"));
   if (!console) {

dom/media/gmp/GMPVideoDecoderParent.cpp

@@ -14,6 +14,7 @@
 #include "GMPContentParent.h"
 #include "GMPMessageUtils.h"
 #include "mozilla/gmp/GMPTypes.h"
+#include "mozilla/EMEUtils.h"
 
 namespace mozilla {
 
@@ -50,6 +51,7 @@ GMPVideoDecoderParent::GMPVideoDecoderParent(GMPContentParent* aPlugin)
   , mCallback(nullptr)
   , mVideoHost(this)
   , mPluginId(aPlugin->GetPluginId())
+  , mFrameCount(0)
 {
   MOZ_ASSERT(mPlugin);
 }
@@ -157,6 +159,7 @@ GMPVideoDecoderParent::Decode(GMPUniquePtr<GMPVideoEncodedFrame> aInputFrame,
                   aRenderTimeMs)) {
     return NS_ERROR_FAILURE;
   }
+  mFrameCount++;
 
   // Async IPC, we don't have access to a return value.
   return NS_OK;
@@ -180,14 +183,33 @@ GMPVideoDecoderParent::Reset()
 
   mIsAwaitingResetComplete = true;
 
+  nsRefPtr<GMPVideoDecoderParent> self(this);
+  nsCOMPtr<nsIRunnable> task = NS_NewRunnableFunction([self]() -> void
+  {
+    LOGD(("GMPVideoDecoderParent[%p]::ResetCompleteTimeout() timed out waiting for ResetComplete", self.get()));
+    self->mResetCompleteTimeout = nullptr;
+    LogToBrowserConsole(NS_LITERAL_STRING("GMPVideoDecoderParent timed out waiting for ResetComplete()"));
+  });
+  CancelResetCompleteTimeout();
+  mResetCompleteTimeout = SimpleTimer::Create(task, 5000, mPlugin->GMPThread());
+
   // Async IPC, we don't have access to a return value.
   return NS_OK;
 }
 
+void
+GMPVideoDecoderParent::CancelResetCompleteTimeout()
+{
+  if (mResetCompleteTimeout) {
+    mResetCompleteTimeout->Cancel();
+    mResetCompleteTimeout = nullptr;
+  }
+}
+
 nsresult
 GMPVideoDecoderParent::Drain()
 {
-  LOGD(("GMPVideoDecoderParent[%p]::Drain()", this));
+  LOGD(("GMPVideoDecoderParent[%p]::Drain() frameCount=%d", this, mFrameCount));
 
   if (!mIsOpen) {
     NS_WARNING("Trying to use an dead GMP video decoder");
@@ -280,8 +302,9 @@ GMPVideoDecoderParent::ActorDestroy(ActorDestroyReason aWhy)
 bool
 GMPVideoDecoderParent::RecvDecoded(const GMPVideoi420FrameData& aDecodedFrame)
 {
-  LOGV(("GMPVideoDecoderParent[%p]::RecvDecoded() timestamp=%lld",
-        this, aDecodedFrame.mTimestamp()));
+  --mFrameCount;
+  LOGV(("GMPVideoDecoderParent[%p]::RecvDecoded() timestamp=%lld frameCount=%d",
+    this, aDecodedFrame.mTimestamp(), mFrameCount));
 
   if (!mCallback) {
     return false;
@@ -345,8 +368,11 @@ GMPVideoDecoderParent::RecvInputDataExhausted()
 bool
 GMPVideoDecoderParent::RecvDrainComplete()
 {
-  LOGD(("GMPVideoDecoderParent[%p]::RecvDrainComplete()", this));
-
+  LOGD(("GMPVideoDecoderParent[%p]::RecvDrainComplete() frameCount=%d", this, mFrameCount));
+  nsAutoString msg;
+  msg.AppendLiteral("GMPVideoDecoderParent::RecvDrainComplete() outstanding frames=");
+  msg.AppendInt(mFrameCount);
+  LogToBrowserConsole(msg);
   if (!mCallback) {
     return false;
   }
@@ -367,6 +393,8 @@ GMPVideoDecoderParent::RecvResetComplete()
 {
   LOGD(("GMPVideoDecoderParent[%p]::RecvResetComplete()", this));
 
+  CancelResetCompleteTimeout();
+
   if (!mCallback) {
     return false;
   }
@@ -375,6 +403,7 @@ GMPVideoDecoderParent::RecvResetComplete()
     return true;
   }
   mIsAwaitingResetComplete = false;
+  mFrameCount = 0;
 
   // Ignore any return code. It is OK for this to fail without killing the process.
   mCallback->ResetComplete();
@@ -457,7 +486,9 @@ GMPVideoDecoderParent::Recv__delete__()
 void
 GMPVideoDecoderParent::UnblockResetAndDrain()
 {
-  LOGD(("GMPVideoDecoderParent[%p]::UnblockResetAndDrain()", this));
+  LOGD(("GMPVideoDecoderParent[%p]::UnblockResetAndDrain() "
+        "awaitingResetComplete=%d awaitingDrainComplete=%d",
+       this, mIsAwaitingResetComplete, mIsAwaitingDrainComplete));
 
   if (!mCallback) {
     MOZ_ASSERT(!mIsAwaitingResetComplete);
@@ -472,6 +503,7 @@ GMPVideoDecoderParent::UnblockResetAndDrain()
     mIsAwaitingDrainComplete = false;
     mCallback->DrainComplete();
   }
+  CancelResetCompleteTimeout();
 }
 
 } // namespace gmp

dom/media/gmp/GMPVideoDecoderParent.h

@@ -14,6 +14,7 @@
 #include "GMPUtils.h"
 #include "GMPVideoHost.h"
 #include "GMPVideoDecoderProxy.h"
+#include "VideoUtils.h"
 
 namespace mozilla {
 namespace gmp {
@@ -80,6 +81,7 @@ private:
   virtual bool Recv__delete__() override;
 
   void UnblockResetAndDrain();
+  void CancelResetCompleteTimeout();
 
   bool mIsOpen;
   bool mShuttingDown;
@@ -90,6 +92,8 @@ private:
   GMPVideoDecoderCallbackProxy* mCallback;
   GMPVideoHostImpl mVideoHost;
   const uint32_t mPluginId;
+  int32_t mFrameCount;
+  nsRefPtr<SimpleTimer> mResetCompleteTimeout;
 };
 
 } // namespace gmp