Bug 1366640 - add a telemetry probe to debug main thread hang in VideoFrameContainer. draft
authorJW Wang <jwwang@mozilla.com>
Fri, 19 May 2017 12:37:37 +0800
changeset 582216 3f559a1b48e780815bbc597dd10af25979218db9
parent 582215 a85ad17a85ff37e4e20abf30c261784e99f77c91
child 629700 1094caebfd63b41def03902f44ea63bb31de90f5
push id60007
push userjwwang@mozilla.com
push dateMon, 22 May 2017 03:30:21 +0000
bugs1366640
milestone55.0a1
Bug 1366640 - add a telemetry probe to debug main thread hang in VideoFrameContainer. MozReview-Commit-ID: 6crTtq1IeD9
dom/media/VideoFrameContainer.cpp
toolkit/components/telemetry/Histograms.json
--- a/dom/media/VideoFrameContainer.cpp
+++ b/dom/media/VideoFrameContainer.cpp
@@ -2,28 +2,51 @@
 /* vim:set ts=2 sw=2 sts=2 et cindent: */
 /* 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 "VideoFrameContainer.h"
 
 #include "mozilla/dom/HTMLMediaElement.h"
+#include "mozilla/Telemetry.h"
+
 #include "nsIFrame.h"
 #include "nsDisplayList.h"
 #include "nsSVGEffects.h"
 
 using namespace mozilla::layers;
 
 namespace mozilla {
 static LazyLogModule gVideoFrameContainerLog("VideoFrameContainer");
 #define CONTAINER_LOG(type, msg) MOZ_LOG(gVideoFrameContainerLog, type, msg)
 
 #define NS_DispatchToMainThread(...) CompileError_UseAbstractMainThreadInstead
 
+namespace {
+template<Telemetry::HistogramID ID>
+class AutoTimer
+{
+  // Set a threshold to reduce performance overhead
+  // for we're measuring hot spots.
+  static const uint32_t sThresholdMS = 1000;
+public:
+  ~AutoTimer()
+  {
+    auto end = TimeStamp::Now();
+    auto diff = uint32_t((end - mStart).ToMilliseconds());
+    if (diff > sThresholdMS) {
+      Telemetry::Accumulate(ID, diff);
+    }
+  }
+private:
+  const TimeStamp mStart = TimeStamp::Now();
+};
+}
+
 VideoFrameContainer::VideoFrameContainer(dom::HTMLMediaElement* aElement,
                                          already_AddRefed<ImageContainer> aContainer)
   : mElement(aElement),
     mImageContainer(aContainer), mMutex("nsVideoFrameContainer"),
     mBlackImage(nullptr),
     mFrameID(0),
     mIntrinsicSizeChanged(false), mImageSizeChanged(false),
     mPendingPrincipalHandle(PRINCIPAL_HANDLE_NONE),
@@ -99,16 +122,17 @@ private:
 
 void VideoFrameContainer::SetCurrentFrames(const VideoSegment& aSegment)
 {
   if (aSegment.IsEmpty()) {
     return;
   }
 
   MutexAutoLock lock(mMutex);
+  AutoTimer<Telemetry::VFC_SETVIDEOSEGMENT_LOCK_HOLD_MS> lockHold;
 
   // Collect any new frames produced in this iteration.
   AutoTArray<ImageContainer::NonOwningImage,4> newImages;
   PrincipalHandle lastPrincipalHandle = PRINCIPAL_HANDLE_NONE;
 
   VideoSegment::ConstChunkIterator iter(aSegment);
   while (!iter.IsEnded()) {
     VideoChunk chunk = *iter;
@@ -187,29 +211,31 @@ void VideoFrameContainer::ClearFrames()
 }
 
 void VideoFrameContainer::SetCurrentFrame(const gfx::IntSize& aIntrinsicSize,
                                           Image* aImage,
                                           const TimeStamp& aTargetTime)
 {
   if (aImage) {
     MutexAutoLock lock(mMutex);
+    AutoTimer<Telemetry::VFC_SETCURRENTFRAME_LOCK_HOLD_MS> lockHold;
     AutoTArray<ImageContainer::NonOwningImage,1> imageList;
     imageList.AppendElement(
         ImageContainer::NonOwningImage(aImage, aTargetTime, ++mFrameID));
     SetCurrentFramesLocked(aIntrinsicSize, imageList);
   } else {
     ClearCurrentFrame(aIntrinsicSize);
   }
 }
 
 void VideoFrameContainer::SetCurrentFrames(const gfx::IntSize& aIntrinsicSize,
                                            const nsTArray<ImageContainer::NonOwningImage>& aImages)
 {
   MutexAutoLock lock(mMutex);
+  AutoTimer<Telemetry::VFC_SETIMAGES_LOCK_HOLD_MS> lockHold;
   SetCurrentFramesLocked(aIntrinsicSize, aImages);
 }
 
 void VideoFrameContainer::SetCurrentFramesLocked(const gfx::IntSize& aIntrinsicSize,
                                                  const nsTArray<ImageContainer::NonOwningImage>& aImages)
 {
   mMutex.AssertCurrentThreadOwns();
 
@@ -268,29 +294,31 @@ void VideoFrameContainer::SetCurrentFram
   if (oldFrameSize != newFrameSize) {
     mImageSizeChanged = true;
   }
 }
 
 void VideoFrameContainer::ClearCurrentFrame()
 {
   MutexAutoLock lock(mMutex);
+  AutoTimer<Telemetry::VFC_CLEARCURRENTFRAME_LOCK_HOLD_MS> lockHold;
 
   // See comment in SetCurrentFrame for the reasoning behind
   // using a kungFuDeathGrip here.
   nsTArray<ImageContainer::OwningImage> kungFuDeathGrip;
   mImageContainer->GetCurrentImages(&kungFuDeathGrip);
 
   mImageContainer->ClearAllImages();
   mImageContainer->ClearCachedResources();
 }
 
 void VideoFrameContainer::ClearFutureFrames()
 {
   MutexAutoLock lock(mMutex);
+  AutoTimer<Telemetry::VFC_CLEARFUTUREFRAMES_LOCK_HOLD_MS> lockHold;
 
   // See comment in SetCurrentFrame for the reasoning behind
   // using a kungFuDeathGrip here.
   nsTArray<ImageContainer::OwningImage> kungFuDeathGrip;
   mImageContainer->GetCurrentImages(&kungFuDeathGrip);
 
   if (!kungFuDeathGrip.IsEmpty()) {
     nsTArray<ImageContainer::NonOwningImage> currentFrame;
@@ -325,18 +353,24 @@ void VideoFrameContainer::InvalidateWith
     // Element has been destroyed
     return;
   }
 
   nsIFrame* frame = mElement->GetPrimaryFrame();
   bool invalidateFrame = false;
 
   {
+    Maybe<AutoTimer<Telemetry::VFC_INVALIDATE_LOCK_WAIT_MS>> lockWait;
+    lockWait.emplace();
+
     MutexAutoLock lock(mMutex);
 
+    lockWait.reset();
+    AutoTimer<Telemetry::VFC_INVALIDATE_LOCK_HOLD_MS> lockHold;
+
     // Get mImageContainerSizeChanged while holding the lock.
     invalidateFrame = mImageSizeChanged;
     mImageSizeChanged = false;
 
     if (mIntrinsicSizeChanged) {
       mElement->UpdateMediaSize(mIntrinsicSize);
       mIntrinsicSizeChanged = false;
 
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -13110,10 +13110,87 @@
     "record_in_processes": ["content"],
     "alert_emails": ["wmccloskey@mozilla.com"],
     "expires_in_version": "60",
     "kind": "exponential",
     "high": 30000,
     "n_buckets": 30,
     "bug_numbers": [1351021],
     "description": "Every time we run an unlabeled runnable, this histogram records the time (in ms) since the last unlabeled runnable ran."
+  },
+  "VFC_INVALIDATE_LOCK_WAIT_MS": {
+    "record_in_processes": ["main", "content"],
+    "alert_emails": ["jwwang@mozilla.com"],
+    "expires_in_version": "57",
+    "kind": "exponential",
+    "low": 1000,
+    "high": 100000,
+    "n_buckets": 100,
+    "bug_numbers": [1366640],
+    "description": "Time (ms) VideoFrameContainer::InvalidateWithFlags spent waiting for a lock."
+  },
+  "VFC_INVALIDATE_LOCK_HOLD_MS": {
+    "record_in_processes": ["main", "content"],
+    "alert_emails": ["jwwang@mozilla.com"],
+    "expires_in_version": "57",
+    "kind": "exponential",
+    "low": 1000,
+    "high": 100000,
+    "n_buckets": 100,
+    "bug_numbers": [1366640],
+    "description": "Time (ms) VideoFrameContainer::InvalidateWithFlags spent holding a lock."
+  },
+  "VFC_SETVIDEOSEGMENT_LOCK_HOLD_MS": {
+    "record_in_processes": ["main", "content"],
+    "alert_emails": ["jwwang@mozilla.com"],
+    "expires_in_version": "57",
+    "kind": "exponential",
+    "low": 1000,
+    "high": 100000,
+    "n_buckets": 100,
+    "bug_numbers": [1366640],
+    "description": "Time (ms) VideoFrameContainer::SetCurrentFrames(VideoSegment) spent holding a lock."
+  },
+  "VFC_SETIMAGES_LOCK_HOLD_MS": {
+    "record_in_processes": ["main", "content"],
+    "alert_emails": ["jwwang@mozilla.com"],
+    "expires_in_version": "57",
+    "kind": "exponential",
+    "low": 1000,
+    "high": 100000,
+    "n_buckets": 100,
+    "bug_numbers": [1366640],
+    "description": "Time (ms) VideoFrameContainer::SetCurrentFrames(nsTArray<ImageContainer::NonOwningImage>) spent holding a lock."
+  },
+  "VFC_SETCURRENTFRAME_LOCK_HOLD_MS": {
+    "record_in_processes": ["main", "content"],
+    "alert_emails": ["jwwang@mozilla.com"],
+    "expires_in_version": "57",
+    "kind": "exponential",
+    "low": 1000,
+    "high": 100000,
+    "n_buckets": 100,
+    "bug_numbers": [1366640],
+    "description": "Time (ms) VideoFrameContainer::SetCurrentFrame spent holding a lock."
+  },
+  "VFC_CLEARCURRENTFRAME_LOCK_HOLD_MS": {
+    "record_in_processes": ["main", "content"],
+    "alert_emails": ["jwwang@mozilla.com"],
+    "expires_in_version": "57",
+    "kind": "exponential",
+    "low": 1000,
+    "high": 100000,
+    "n_buckets": 100,
+    "bug_numbers": [1366640],
+    "description": "Time (ms) VideoFrameContainer::ClearCurrentFrame spent holding a lock."
+  },
+  "VFC_CLEARFUTUREFRAMES_LOCK_HOLD_MS": {
+    "record_in_processes": ["main", "content"],
+    "alert_emails": ["jwwang@mozilla.com"],
+    "expires_in_version": "57",
+    "kind": "exponential",
+    "low": 1000,
+    "high": 100000,
+    "n_buckets": 100,
+    "bug_numbers": [1366640],
+    "description": "Time (ms) VideoFrameContainer::ClearFutureFrames spent holding a lock."
   }
 }