Bug 1345540 - Measure input event handling latency. r?smaug, data-review?bsmedberg draft
authorWei-Cheng Pan <wpan@mozilla.com>
Tue, 18 Apr 2017 11:25:21 +0800
changeset 567033 945ce629f02bd550406b8f248b92e3f9b1d42fb8
parent 566881 73752931e273091185e1e4b5231c28beed657cc8
child 625504 a4e26a5de8f48e4a8a94fc314ebcfadabd847fee
push id55422
push userbmo:wpan@mozilla.com
push dateMon, 24 Apr 2017 10:18:14 +0000
reviewerssmaug
bugs1345540
milestone55.0a1
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
dom/events/EventListenerManager.cpp
layout/base/PresShell.cpp
toolkit/components/telemetry/Histograms.json
widget/BasicEvents.h
--- 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)
   {