Bug 1345540 - Measure input event handling latency. r?smaug, data-review?bsmedberg
This patch accumulates time spent in handlers that belongs to the same
WidgetEvent, then report the accumulated time to Telemetry.
MozReview-Commit-ID: 9mvwMewgIkJ
--- a/dom/events/EventListenerManager.cpp
+++ b/dom/events/EventListenerManager.cpp
@@ -65,16 +65,45 @@ using namespace hal;
#define EVENT_TYPE_EQUALS(ls, message, userType, typeString, allEvents) \
((ls->mEventMessage == message && \
(ls->mEventMessage != eUnidentifiedEvent || \
(mIsMainThreadELM && ls->mTypeAtom == userType) || \
(!mIsMainThreadELM && ls->mTypeString.Equals(typeString)))) || \
(allEvents && ls->mAllEvents))
+
+class AutoAccumulateHandlerTime {
+public:
+ AutoAccumulateHandlerTime(nsIDOMEvent* aDOMEvent)
+ : mStartTime(TimeStamp::Now())
+ , mDOMEvent(aDOMEvent)
+ {
+ }
+
+ ~AutoAccumulateHandlerTime()
+ {
+ bool trusted = false;
+ Unused << mDOMEvent->GetIsTrusted(&trusted);
+ if (!trusted) {
+ return;
+ }
+ WidgetEvent* widgetEvent = mDOMEvent->WidgetEventPtr();
+ if (!widgetEvent) {
+ return;
+ }
+ widgetEvent->mTimeSpentInHandlers += (TimeStamp::Now() - mStartTime);
+ }
+
+private:
+ TimeStamp mStartTime;
+ nsCOMPtr<nsIDOMEvent> mDOMEvent;
+};
+
+
static const uint32_t kAllMutationBits =
NS_EVENT_BITS_MUTATION_SUBTREEMODIFIED |
NS_EVENT_BITS_MUTATION_NODEINSERTED |
NS_EVENT_BITS_MUTATION_NODEREMOVED |
NS_EVENT_BITS_MUTATION_NODEREMOVEDFROMDOCUMENT |
NS_EVENT_BITS_MUTATION_NODEINSERTEDINTODOCUMENT |
NS_EVENT_BITS_MUTATION_ATTRMODIFIED |
NS_EVENT_BITS_MUTATION_CHARACTERDATAMODIFIED;
@@ -1119,16 +1148,18 @@ EventListenerManager::HandleEventSubType
// compiled the event handler itself
if ((aListener->mListenerType == Listener::eJSEventListener) &&
aListener->mHandlerIsString) {
result = CompileEventHandlerInternal(aListener, nullptr, nullptr);
aListener = nullptr;
}
if (NS_SUCCEEDED(result)) {
+ AutoAccumulateHandlerTime timer(aDOMEvent);
+
if (mIsMainThreadELM) {
nsContentUtils::EnterMicroTask();
}
// nsIDOMEvent::currentTarget is set in EventDispatcher.
if (listenerHolder.HasWebIDLCallback()) {
ErrorResult rv;
listenerHolder.GetWebIDLCallback()->
HandleEvent(aCurrentTarget, *(aDOMEvent->InternalDOMEvent()), rv);
--- a/layout/base/PresShell.cpp
+++ b/layout/base/PresShell.cpp
@@ -297,16 +297,59 @@ ShowVerifyReflowFlags()
printf(" %s\n", flag->name);
++flag;
}
printf("Note: GECKO_VERIFY_REFLOW_FLAGS is a comma separated list of flag\n");
printf("names (no whitespace)\n");
}
#endif
+
+static void
+RecordTimeSpentInHandlers (WidgetEvent* aEvent)
+{
+ if (!XRE_IsContentProcess()) {
+ return;
+ }
+ if (aEvent->mTimeSpentInHandlers.IsZero()) {
+ return;
+ }
+ double duration = aEvent->mTimeSpentInHandlers.ToMilliseconds();
+ switch (aEvent->mMessage) {
+ case eKeyPress:
+ case eKeyDown:
+ case eKeyUp:
+ Telemetry::Accumulate(Telemetry::INPUT_EVENT_HANDLED_KEYBOARD_MS, duration);
+ break;
+ case eMouseDown:
+ Telemetry::Accumulate(Telemetry::INPUT_EVENT_HANDLED_MOUSE_DOWN_MS, duration);
+ break;
+ case eMouseUp:
+ Telemetry::Accumulate(Telemetry::INPUT_EVENT_HANDLED_MOUSE_UP_MS, duration);
+ break;
+ case eMouseMove:
+ if (aEvent->mFlags.mHandledByAPZ) {
+ Telemetry::Accumulate(Telemetry::INPUT_EVENT_HANDLED_APZ_MOUSE_MOVE_MS, duration);
+ }
+ break;
+ case eWheel:
+ if (aEvent->mFlags.mHandledByAPZ) {
+ Telemetry::Accumulate(Telemetry::INPUT_EVENT_HANDLED_APZ_WHEEL_MS, duration);
+ }
+ break;
+ case eTouchMove:
+ if (aEvent->mFlags.mHandledByAPZ) {
+ Telemetry::Accumulate(Telemetry::INPUT_EVENT_HANDLED_APZ_TOUCH_MOVE_MS, duration);
+ }
+ break;
+ default:
+ break;
+ }
+}
+
//========================================================================
//========================================================================
//========================================================================
#ifdef MOZ_REFLOW_PERF
class ReflowCountMgr;
static const char kGrandTotalsStr[] = "Grand Totals";
@@ -8247,16 +8290,17 @@ PresShell::HandleEventInternal(WidgetEve
break;
}
}
if (Telemetry::CanRecordBase() &&
!aEvent->mTimeStamp.IsNull() &&
aEvent->mTimeStamp > mLastOSWake &&
aEvent->AsInputEvent()) {
+ RecordTimeSpentInHandlers(aEvent);
double millis = (TimeStamp::Now() - aEvent->mTimeStamp).ToMilliseconds();
Telemetry::Accumulate(Telemetry::INPUT_EVENT_RESPONSE_MS, millis);
if (mDocument && mDocument->GetReadyStateEnum() != nsIDocument::READYSTATE_COMPLETE) {
Telemetry::Accumulate(Telemetry::LOAD_INPUT_EVENT_RESPONSE_MS, millis);
}
}
return rv;
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -11391,10 +11391,64 @@
"TIME_TO_RESPONSE_START_MS": {
"alert_emails": ["wpan@mozilla.com"],
"expires_in_version": "60",
"kind": "exponential",
"high": 50000,
"n_buckets": 100,
"bug_numbers": [1344893],
"description": "Time in milliseconds from navigationStart to responseStart."
+ },
+ "INPUT_EVENT_HANDLED_MOUSE_DOWN_MS": {
+ "alert_emails": ["wpan@mozilla.com"],
+ "expires_in_version": "60",
+ "kind": "exponential",
+ "high": 5000,
+ "n_buckets": 100,
+ "bug_numbers": [1345540],
+ "description": "Time (ms) for the mouse down event spent in handlers."
+ },
+ "INPUT_EVENT_HANDLED_MOUSE_UP_MS": {
+ "alert_emails": ["wpan@mozilla.com"],
+ "expires_in_version": "60",
+ "kind": "exponential",
+ "high": 5000,
+ "n_buckets": 100,
+ "bug_numbers": [1345540],
+ "description": "Time (ms) for the mouse up event spent in handlers."
+ },
+ "INPUT_EVENT_HANDLED_KEYBOARD_MS": {
+ "alert_emails": ["wpan@mozilla.com"],
+ "expires_in_version": "60",
+ "kind": "exponential",
+ "high": 5000,
+ "n_buckets": 100,
+ "bug_numbers": [1345540],
+ "description": "Time (ms) for the keyboard event spent in handlers."
+ },
+ "INPUT_EVENT_HANDLED_APZ_TOUCH_MOVE_MS": {
+ "alert_emails": ["wpan@mozilla.com"],
+ "expires_in_version": "60",
+ "kind": "exponential",
+ "high": 5000,
+ "n_buckets": 100,
+ "bug_numbers": [1345540],
+ "description": "Time (ms) for the APZ handled touch move event spent in handlers."
+ },
+ "INPUT_EVENT_HANDLED_APZ_MOUSE_MOVE_MS": {
+ "alert_emails": ["wpan@mozilla.com"],
+ "expires_in_version": "60",
+ "kind": "exponential",
+ "high": 5000,
+ "n_buckets": 100,
+ "bug_numbers": [1345540],
+ "description": "Time (ms) for the APZ handled mouse move event spent in handlers."
+ },
+ "INPUT_EVENT_HANDLED_APZ_WHEEL_MS": {
+ "alert_emails": ["wpan@mozilla.com"],
+ "expires_in_version": "60",
+ "kind": "exponential",
+ "high": 5000,
+ "n_buckets": 100,
+ "bug_numbers": [1345540],
+ "description": "Time (ms) for the APZ handled wheel event spent in handlers."
}
}
--- a/widget/BasicEvents.h
+++ b/widget/BasicEvents.h
@@ -257,20 +257,23 @@ class WidgetEventTime
{
public:
// Elapsed time, in milliseconds, from a platform-specific zero time
// to the time the message was created
uint64_t mTime;
// Timestamp when the message was created. Set in parallel to 'time' until we
// determine if it is safe to drop 'time' (see bug 77992).
TimeStamp mTimeStamp;
+ // Measure time spent in event handlers.
+ TimeDuration mTimeSpentInHandlers;
WidgetEventTime()
: mTime(0)
, mTimeStamp(TimeStamp::Now())
+ , mTimeSpentInHandlers()
{
}
WidgetEventTime(uint64_t aTime,
TimeStamp aTimeStamp)
: mTime(aTime)
, mTimeStamp(aTimeStamp)
{