Bug 1366640 - add a telemetry probe to debug main thread hang in VideoFrameContainer. r=cpearce,francois
authorJW Wang <jwwang@mozilla.com>
Fri, 19 May 2017 12:37:37 +0800
changeset 360118 3b05e00b1a14365d9067458d988cc4679c7ba5e0
parent 360117 03691a66df904e15a39126ad58ee767dd1d66fd6
child 360119 1ffcbd8d55f650f7856290eed7ce111a04076a9c
push id31868
push userryanvm@gmail.com
push dateTue, 23 May 2017 14:32:52 +0000
treeherdermozilla-central@3a82a745123f [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewerscpearce, francois
bugs1366640
milestone55.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1366640 - add a telemetry probe to debug main thread hang in VideoFrameContainer. r=cpearce,francois 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."
   }
 }