Bug 1366640 - add a telemetry probe to debug main thread hang in VideoFrameContainer.
MozReview-Commit-ID: 6crTtq1IeD9
--- 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."
}
}