Bug 1219144 - Using the nsRefreshDriver's jank indication for performance monitoring;f?froydnj r=froydnj

This patch (currently WIP) alters the way we determine whether jank is user-visible or not.

Instead of measuring the total time spent doing JS, we now use an
indicator provided by the vsync driver: how long it takes to deliver
the signal from the vsync timer to the main thread. This lets us find
out more accurately if there is user-visible jank. In the future, this
will also let us add an observer to find out whether the process
itself is janky, regardless of JS.
This commit is contained in:
David Rajchenbach-Teller 2016-01-14 15:07:18 +01:00
parent ff240d99c8
commit 2e77b02d19
5 changed files with 238 additions and 120 deletions

View File

@ -95,6 +95,13 @@ namespace {
// jank-critical mode if and only if at least one vsync driver has
// at least one observer.
static uint64_t sActiveVsyncTimers = 0;
// The latest value of process-wide jank levels.
//
// For each i, sJankLevels[i] counts the number of times delivery of
// vsync to the main thread has been delayed by at least 2^i ms. Use
// GetJankLevels to grab a copy of this array.
uint64_t sJankLevels[12];
}
namespace mozilla {
@ -446,6 +453,7 @@ private:
sample);
Telemetry::Accumulate(Telemetry::FX_REFRESH_DRIVER_SYNC_SCROLL_FRAME_DELAY_MS,
sample);
RecordJank(sample);
} else if (mVsyncRate != TimeDuration::Forever()) {
TimeDuration contentDelay = (TimeStamp::Now() - mLastChildTick) - mVsyncRate;
if (contentDelay.ToMilliseconds() < 0 ){
@ -458,6 +466,7 @@ private:
sample);
Telemetry::Accumulate(Telemetry::FX_REFRESH_DRIVER_SYNC_SCROLL_FRAME_DELAY_MS,
sample);
RecordJank(sample);
} else {
// Request the vsync rate from the parent process. Might be a few vsyncs
// until the parent responds.
@ -466,6 +475,16 @@ private:
#endif
}
void RecordJank(uint32_t aJankMS)
{
uint32_t duration = 1 /* ms */;
for (size_t i = 0;
i < mozilla::ArrayLength(sJankLevels) && duration < aJankMS;
++i, duration *= 2) {
sJankLevels[i]++;
}
}
void TickRefreshDriver(TimeStamp aVsyncTimestamp)
{
MOZ_ASSERT(NS_IsMainThread());
@ -821,6 +840,7 @@ CreateVsyncRefreshTimer()
{
MOZ_ASSERT(NS_IsMainThread());
PodArrayZero(sJankLevels);
// Sometimes, gfxPrefs is not initialized here. Make sure the gfxPrefs is
// ready.
gfxPrefs::GetSingleton();
@ -2161,4 +2181,10 @@ nsRefreshDriver::IsJankCritical()
return sActiveVsyncTimers > 0;
}
/* static */ bool
nsRefreshDriver::GetJankLevels(Vector<uint64_t>& aJank) {
aJank.clear();
return aJank.append(sJankLevels, ArrayLength(sJankLevels));
}
#undef LOG

View File

@ -13,6 +13,8 @@
#define nsRefreshDriver_h_
#include "mozilla/TimeStamp.h"
#include "mozilla/Vector.h"
#include "mozFlushType.h"
#include "nsTObserverArray.h"
#include "nsTArray.h"
@ -296,6 +298,20 @@ public:
bool IsInRefresh() { return mInRefresh; }
/**
* The latest value of process-wide jank levels.
*
* For each i, sJankLevels[i] counts the number of times delivery of
* vsync to the main thread has been delayed by at least 2^i
* ms. This data structure has been designed to make it easy to
* determine how much jank has taken place between two instants in
* time.
*
* Return `false` if `aJank` needs to be grown to accomodate the
* data but we didn't have enough memory.
*/
static bool GetJankLevels(mozilla::Vector<uint64_t>& aJank);
// mozilla::layers::TransactionIdAllocator
virtual uint64_t GetTransactionId() override;
void NotifyTransactionCompleted(uint64_t aTransactionId) override;

View File

@ -126,38 +126,71 @@ interface nsIPerformanceSnapshot: nsISupports {
/**
* A performance alert.
*/
[scriptable, builtinclass, uuid(d5379791-3f90-4edc-bcbb-5d4edea03e57)]
[scriptable, builtinclass, uuid(a85706ab-d703-4687-8865-78cd771eab93)]
interface nsIPerformanceAlert: nsISupports {
// Alert was caused by jank exceeding the threshold.
const unsigned long REASON_JANK = 0;
/**
* A slowdown was detected.
*
* See REASON_JANK_* for details on whether this slowdown was user-noticeable.
*/
const unsigned long REASON_SLOWDOWN = 1;
/**
* The reason for the alert.
* This alert was triggered during a jank in animation.
*
* In the current implementation, we consider that there is a jank
* in animation if delivery of the vsync message to the main thread
* has been delayed too much (see
* nsIPerformanceStatsService.animationJankLevelThreshold).
*
* Note that this is a heuristic which may provide false positives,
* so clients of this API are expected to perform post-processing to
* filter out such false positives.
*/
const unsigned long REASON_JANK_IN_ANIMATION = 2;
/**
* This alert was triggered during a jank in user input.
*
* In the current implementation, we consider that there is a jank
* in animation if a user input was received either immediately
* before executing the offending code (see
* nsIPerformanceStatsService.userInputDelayThreshold) or while
* executing the offending code.
*
* Note that this is a heuristic which may provide false positives,
* so clients of this API are expected to perform post-processing to
* filter out such false positives.
*/
const unsigned long REASON_JANK_IN_INPUT = 4;
/**
* The reason for the alert, as a bitwise or of the various REASON_*
* constants.
*/
readonly attribute unsigned long reason;
/**
* Longest interval spent executing code in this group
* since the latest alert, in microseconds.
*
* Note that the underlying algorithm is probabilistic and may
* provide false positives, so clients of this API are expected to
* perform post-processing to filter out such false positives. In
* particular, a high system load will increase the noise level on
* this measure.
*/
readonly attribute unsigned long long highestJank;
/**
* Longest interval spent executing CPOW in this group
* since the latest alert, in microseconds.
*
* This measure is reliable and involves no heuristics. However,
* note that the duration of CPOWs is increased by high system
* loads.
*/
readonly attribute unsigned long long highestCPOW;
/**
* `true` if the jank is expected to be noticeable by the user,
* `false` otherwise.
*
* In the current implementation, we consider that jank is noticeable
* if it arrives during an animation, shortly after a user input, or
* if a user input is triggered during the same iteration of the event
* loop.
*/
readonly attribute bool isJankVisible;
};
@ -204,7 +237,7 @@ interface nsIPerformanceObservable: nsISupports {
};
[scriptable, uuid(5675d1d9-638e-4af0-9392-b04aacfad79a)]
[scriptable, uuid(505bc42e-be38-4a53-baba-92cb33690cde)]
interface nsIPerformanceStatsService : nsISupports {
/**
* `true` if we should monitor CPOW, `false` otherwise.
@ -234,6 +267,26 @@ interface nsIPerformanceStatsService : nsISupports {
*/
attribute unsigned long long jankAlertThreshold;
/**
* If a user is seeing an animation and we spend too long executing
* JS code while blocking refresh, this will be visible to the user.
*
* We assume that any jank during an animation and lasting more than
* 2^animationJankLevelThreshold ms will be visible.
*/
attribute short animationJankLevelThreshold;
/**
* If a user performs an input (e.g. clicking, pressing a key, but
* *NOT* moving the mouse), and we spend too long executing JS code
* before displaying feedback, this will be visible to the user even
* if there is no ongoing animation.
*
* We assume that any jank during `userInputDelayThreshold` us after
* the user input will be visible.
*/
attribute unsigned long long userInputDelayThreshold;
/**
* A buffering delay, in milliseconds, used by the service to
* regroup performance alerts, before observers are actually

View File

@ -522,9 +522,6 @@ private:
// in microseconds.
const uint64_t mHighestJank;
const uint64_t mHighestCPOW;
// `true` if jank may be noticed by the user.
const bool mIsJankVisible;
};
NS_IMPL_ISUPPORTS(PerformanceAlert, nsIPerformanceAlert);
@ -533,7 +530,6 @@ PerformanceAlert::PerformanceAlert(const uint32_t reason, nsPerformanceGroup* so
: mReason(reason)
, mHighestJank(source->HighestRecentJank())
, mHighestCPOW(source->HighestRecentCPOW())
, mIsJankVisible(source->RecentJankVisibility())
{ }
NS_IMETHODIMP
@ -553,12 +549,6 @@ PerformanceAlert::GetReason(uint32_t* result) {
*result = mReason;
return NS_OK;
}
NS_IMETHODIMP
PerformanceAlert::GetIsJankVisible(bool* result) {
*result = mIsJankVisible;
return NS_OK;
}
/* ------------------------------------------------------
*
* class PendingAlertsCollector
@ -581,6 +571,7 @@ public:
nsresult Start(uint32_t timerDelayMS);
nsresult Dispose();
private:
~PendingAlertsCollector() {}
@ -588,6 +579,8 @@ private:
bool mPending;
nsCOMPtr<nsITimer> mTimer;
mozilla::Vector<uint64_t> mJankLevels;
};
NS_IMPL_ISUPPORTS(PendingAlertsCollector, nsITimerCallback);
@ -595,7 +588,7 @@ NS_IMPL_ISUPPORTS(PendingAlertsCollector, nsITimerCallback);
NS_IMETHODIMP
PendingAlertsCollector::Notify(nsITimer*) {
mPending = false;
mService->NotifyJankObservers();
mService->NotifyJankObservers(mJankLevels);
return NS_OK;
}
@ -616,6 +609,11 @@ PendingAlertsCollector::Start(uint32_t timerDelayMS) {
}
mPending = true;
{
mozilla::DebugOnly<bool> result = nsRefreshDriver::GetJankLevels(mJankLevels);
MOZ_ASSERT(result);
}
return NS_OK;
}
@ -657,13 +655,15 @@ nsPerformanceStatsService::nsPerformanceStatsService()
true, // isSystem
nsPerformanceGroup::GroupScope::RUNTIME // scope
))
, mIsJankCritical(false)
, mIsHandlingUserInput(false)
, mProcessStayed(0)
, mProcessMoved(0)
, mProcessUpdateCounter(0)
, mIsMonitoringPerCompartment(false)
, mJankAlertThreshold(mozilla::MaxValue<uint64_t>::value) // By default, no alerts
, mJankAlertBufferingDelay(1000 /* ms */)
, mJankLevelVisibilityThreshold(/* 2 ^ */ 8 /* ms */)
, mMaxExpectedDurationOfInteractionUS(150 * 1000)
{
mPendingAlertsCollector = new PendingAlertsCollector(mRuntime, this);
@ -821,30 +821,15 @@ nsPerformanceStatsService::Observe(nsISupports *aSubject, const char *aTopic,
return NS_OK;
}
/*static*/
bool
/*static*/ bool
nsPerformanceStatsService::IsHandlingUserInput() {
if (mozilla::EventStateManager::LatestUserInputStart().IsNull()) {
return false;
}
bool result = mozilla::TimeStamp::Now() - mozilla::EventStateManager::LatestUserInputStart() <= mozilla::TimeDuration::FromMilliseconds(MAX_DURATION_OF_INTERACTION_MS);
bool result = mozilla::TimeStamp::Now() - mozilla::EventStateManager::LatestUserInputStart() <= mozilla::TimeDuration::FromMicroseconds(mMaxExpectedDurationOfInteractionUS);
return result;
}
/*static*/ bool
nsPerformanceStatsService::IsJankCritical() {
bool result = IsAnimating() || IsHandlingUserInput();
return result;
}
/*static*/ bool
nsPerformanceStatsService::IsAnimating() {
bool result = nsRefreshDriver::IsJankCritical();
return result;
}
/* [implicit_jscontext] attribute bool isMonitoringCPOW; */
NS_IMETHODIMP
nsPerformanceStatsService::GetIsMonitoringCPOW(JSContext* cx, bool *aIsStopwatchActive)
@ -1132,7 +1117,7 @@ bool
nsPerformanceStatsService::StopwatchStart(uint64_t iteration) {
mIteration = iteration;
mIsJankCritical = IsJankCritical();
mIsHandlingUserInput = IsHandlingUserInput();
mUserInputCount = mozilla::EventStateManager::UserInputCount();
nsresult rv = GetResources(&mUserTimeStart, &mSystemTimeStart);
@ -1174,13 +1159,13 @@ nsPerformanceStatsService::StopwatchCommit(uint64_t iteration, JSGroupVector& re
MOZ_ASSERT(mTopGroup->isUsedInThisIteration());
const uint64_t totalRecentCycles = mTopGroup->recentCycles(iteration);
const bool isJankVisible = mIsJankCritical || mozilla::EventStateManager::UserInputCount() > mUserInputCount;
const bool isHandlingUserInput = mIsHandlingUserInput || mozilla::EventStateManager::UserInputCount() > mUserInputCount;
// We should only reach this stage if `group` has had some activity.
MOZ_ASSERT(mTopGroup->recentTicks(iteration) > 0);
for (auto iter = recentGroups.begin(), end = recentGroups.end(); iter != end; ++iter) {
RefPtr<nsPerformanceGroup> group = nsPerformanceGroup::Get(*iter);
CommitGroup(iteration, userTimeDelta, systemTimeDelta, totalRecentCycles, isJankVisible, group);
CommitGroup(iteration, userTimeDelta, systemTimeDelta, totalRecentCycles, isHandlingUserInput, group);
}
// Make sure that `group` was treated along with the other items of `recentGroups`.
@ -1198,7 +1183,7 @@ void
nsPerformanceStatsService::CommitGroup(uint64_t iteration,
uint64_t totalUserTimeDelta, uint64_t totalSystemTimeDelta,
uint64_t totalCyclesDelta,
bool isJankVisible,
bool isHandlingUserInput,
nsPerformanceGroup* group) {
MOZ_ASSERT(group->isUsedInThisIteration());
@ -1247,7 +1232,9 @@ nsPerformanceStatsService::CommitGroup(uint64_t iteration,
group->RecordJank(totalTimeDelta);
group->RecordCPOW(cpowTimeDelta);
group->RecordJankVisibility();
if (isHandlingUserInput) {
group->RecordUserInput();
}
if (totalTimeDelta >= mJankAlertThreshold) {
if (!group->HasPendingAlert()) {
@ -1340,7 +1327,7 @@ nsPerformanceStatsService::GetResources(uint64_t* userTime,
}
void
nsPerformanceStatsService::NotifyJankObservers() {
nsPerformanceStatsService::NotifyJankObservers(const mozilla::Vector<uint64_t>& aPreviousJankLevels) {
GroupVector alerts;
mPendingAlerts.swap(alerts);
if (!mPendingAlertsCollector) {
@ -1348,10 +1335,32 @@ nsPerformanceStatsService::NotifyJankObservers() {
return;
}
// Find out if we have noticed any user-noticeable delay in an
// animation recently (i.e. since the start of the execution of JS
// code that caused this collector to start). If so, we'll mark any
// alert as part of a user-noticeable jank. Note that this doesn't
// mean with any certainty that the alert is the only cause of jank,
// or even the main cause of jank.
mozilla::Vector<uint64_t> latestJankLevels;
{
mozilla::DebugOnly<bool> result = nsRefreshDriver::GetJankLevels(latestJankLevels);
MOZ_ASSERT(result);
}
MOZ_ASSERT(latestJankLevels.length() == aPreviousJankLevels.length());
bool isJankInAnimation = false;
for (size_t i = mJankLevelVisibilityThreshold; i < latestJankLevels.length(); ++i) {
if (latestJankLevels[i] > aPreviousJankLevels[i]) {
isJankInAnimation = true;
break;
}
}
MOZ_ASSERT(!alerts.empty());
const bool hasUniversalAddonObservers = mUniversalTargets.mAddons->HasObservers();
const bool hasUniversalWindowObservers = mUniversalTargets.mWindows->HasObservers();
for (auto iter = alerts.begin(); iter < alerts.end(); ++iter) {
MOZ_ASSERT(iter);
RefPtr<nsPerformanceGroup> group = *iter;
group->SetHasPendingAlert(false);
@ -1362,19 +1371,24 @@ nsPerformanceStatsService::NotifyJankObservers() {
group->ObservationTarget()
};
bool isJankInInput = group->HasRecentUserInput();
RefPtr<PerformanceAlert> alert;
for (nsPerformanceObservationTarget* target : targets) {
if (!target) {
continue;
}
if (!alert) {
const uint32_t reason = nsIPerformanceAlert::REASON_SLOWDOWN
| (isJankInAnimation ? nsIPerformanceAlert::REASON_JANK_IN_ANIMATION : 0)
| (isJankInInput ? nsIPerformanceAlert::REASON_JANK_IN_INPUT : 0);
// Wait until we are sure we need to allocate before we allocate.
alert = new PerformanceAlert(nsIPerformanceAlert::REASON_JANK, group);
alert = new PerformanceAlert(reason, group);
}
target->NotifyJankObservers(details, alert);
}
group->ResetHighest();
group->ResetRecent();
}
}
@ -1403,6 +1417,32 @@ nsPerformanceStatsService::GetObservableWindow(uint64_t windowId,
return NS_OK;
}
NS_IMETHODIMP
nsPerformanceStatsService::GetAnimationJankLevelThreshold(short* result) {
*result = mJankLevelVisibilityThreshold;
return NS_OK;
}
NS_IMETHODIMP
nsPerformanceStatsService::SetAnimationJankLevelThreshold(short value) {
mJankLevelVisibilityThreshold = value;
return NS_OK;
}
NS_IMETHODIMP
nsPerformanceStatsService::GetUserInputDelayThreshold(uint64_t* result) {
*result = mMaxExpectedDurationOfInteractionUS;
return NS_OK;
}
NS_IMETHODIMP
nsPerformanceStatsService::SetUserInputDelayThreshold(uint64_t value) {
mMaxExpectedDurationOfInteractionUS = value;
return NS_OK;
}
nsPerformanceStatsService::UniversalTargets::UniversalTargets()
: mAddons(new nsPerformanceObservationTarget())
, mWindows(new nsPerformanceObservationTarget())
@ -1442,7 +1482,7 @@ nsPerformanceGroup::nsPerformanceGroup(nsPerformanceStatsService* service,
, mScope(scope)
, mHighestJank(0)
, mHighestCPOW(0)
, mIsJankVisible(false)
, mHasRecentUserInput(false)
, mHasPendingAlert(false)
{
mozilla::Unused << mService->mGroups.PutEntry(this);
@ -1538,11 +1578,6 @@ nsPerformanceGroup::RecordCPOW(uint64_t cpow) {
}
}
void
nsPerformanceGroup::RecordJankVisibility() {
mIsJankVisible = true;
}
uint64_t
nsPerformanceGroup::HighestRecentJank() {
return mHighestJank;
@ -1554,14 +1589,18 @@ nsPerformanceGroup::HighestRecentCPOW() {
}
bool
nsPerformanceGroup::RecentJankVisibility() {
return mIsJankVisible;
nsPerformanceGroup::HasRecentUserInput() {
return mHasRecentUserInput;
}
void
nsPerformanceGroup::ResetHighest() {
mHighestJank = 0;
mHighestCPOW = 0;
mIsJankVisible = false;
nsPerformanceGroup::RecordUserInput() {
mHasRecentUserInput = true;
}
void
nsPerformanceGroup::ResetRecent() {
mHighestJank = 0;
mHighestCPOW = 0;
mHasRecentUserInput = false;
}

View File

@ -129,17 +129,6 @@ public:
nsPerformanceStatsService();
nsresult Init();
/**
* `true` if we are currently in a jank-critical section, i.e. if a
* slowdown can cause user-visible jank.
*
* In the current implementation, we consider that the code is in a
* jank-critical section if either we are handling user input (see
* `IsHandlingUserInput()`) or we are running an animation (see
* `IsAnimating()`).
*/
static bool IsJankCritical();
private:
nsresult InitInternal();
void Dispose();
@ -285,12 +274,7 @@ protected:
uint64_t mUserTimeStart;
uint64_t mSystemTimeStart;
/**
* `true` if the iteration currently being examined is jank
* critical, i.e. if we expect that any slowdown during this
* iteration will be noticed by the user.
*/
bool mIsJankCritical;
bool mIsHandlingUserInput;
/**
* The number of user inputs since the start of the process. Used to
@ -406,18 +390,6 @@ protected:
* Determining whether jank is user-visible.
*/
/**
* `true` if we believe that any slowdown can cause an animation to
* jank, `false` otherwise.
*
* In the current implementation, we return `true` iff the vsync
* driver of the current process has at least one client. This is a
* pessimistic approximation, insofar as the vsync driver is also
* used by off-main thread animations, which would not jank in case
* of slowdown.
*/
static bool IsAnimating();
/**
* `true` if we believe that any slowdown can cause a noticeable
* delay in handling user-input.
@ -427,7 +399,7 @@ protected:
* includes all inputs (mouse, keyboard, other devices), with the
* exception of mousemove.
*/
static bool IsHandlingUserInput();
bool IsHandlingUserInput();
public:
@ -449,7 +421,7 @@ public:
* Clear the set of pending alerts and dispatch the pending alerts
* to observers.
*/
void NotifyJankObservers();
void NotifyJankObservers(const mozilla::Vector<uint64_t>& previousJankLevels);
private:
/**
@ -500,6 +472,27 @@ private:
* performance.
*/
uint32_t mJankAlertBufferingDelay;
/**
* The threshold above which jank, as reported by the refresh drivers,
* is considered user-visible.
*
* A value of n means that any jank above 2^n ms will be considered
* user visible.
*/
short mJankLevelVisibilityThreshold;
/**
* The number of microseconds during which we assume that a
* user-interaction can keep the code jank-critical. Any user
* interaction that lasts longer than this duration is expected to
* either have already caused jank or have caused a nested event
* loop.
*
* In either case, we consider that monitoring
* jank-during-interaction after this duration is useless.
*/
uint64_t mMaxExpectedDurationOfInteractionUS;
};
@ -768,16 +761,18 @@ public:
uint64_t HighestRecentCPOW();
/**
* Record that any slowdown will be noticed by the user and may
* therefore need to trigger a slowdown alert.
* Record that this group has recently been involved in handling
* user input. Note that heuristics are involved here, so the
* result is not 100% accurate.
*/
void RecordJankVisibility();
bool RecentJankVisibility();
void RecordUserInput();
bool HasRecentUserInput();
/**
* Reset highest recent CPOW/jank to 0.
* Reset recent values (recent highest CPOW and jank, involvement in
* user input).
*/
void ResetHighest();
void ResetRecent();
private:
/**
* The target used by observers to register for watching slow
@ -800,11 +795,14 @@ private:
uint64_t mHighestCPOW;
/**
* `true` if the iteration currently being examined is jank
* critical, i.e. if we expect that any slowdown during this
* iteration will be noticed by the user.
* `true` if this group has been involved in handling user input,
* `false` otherwise.
*
* Note that we use heuristics to determine whether a group is
* involved in handling user input, so this value is not 100%
* accurate.
*/
bool mIsJankVisible;
bool mHasRecentUserInput;
/**
* `true` if this group has caused a performance alert and this alert
@ -818,18 +816,4 @@ private:
bool mHasPendingAlert;
};
namespace {
/**
* The number of milliseconds during which we assume that a
* user-interaction can keep the code jank-critical. Any user
* interaction that lasts longer than this duration is expected to
* either have already caused jank or have caused a nested event
* loop.
*
* In either case, we consider that monitoring
* jank-during-interaction after this duration is useless.
*/
const uint64_t MAX_DURATION_OF_INTERACTION_MS = 150;
}
#endif