bug 1357457 - Report non-overlapping Input Responses to Telemetry. r?masayuki data-r=bsmedberg draft
authorChris H-C <chutten@mozilla.com>
Wed, 19 Apr 2017 15:53:30 -0400
changeset 568101 e90779ca57f548ef5b5d4bccee71c1ca94225d3e
parent 565752 27311156637f9b5d4504373967e01c4241902ae7
child 625819 47eccc089f4eff46781fcde7cbb253f247684b5f
push id55757
push userbmo:chutten@mozilla.com
push dateTue, 25 Apr 2017 19:02:10 +0000
reviewersmasayuki
bugs1357457
milestone55.0a1
bug 1357457 - Report non-overlapping Input Responses to Telemetry. r?masayuki data-r=bsmedberg Say there's a single lag event, a GC or a busy loop, during which the user types several characters. Is this one (lag) event? Several (input) events? We have INPUT_EVENT_RESPONSE_MS which will accumulate several lagged events in this case. However, that is more of an indication of how users use Firefox than how good we've been at eliminating sources of lag. INPUT_EVENT_RESPONSE_COALESCED_MS records the coalesced time spend waiting for responses to input events. So in this case it will record one value for the entire duration of the lag. MozReview-Commit-ID: H5rYnhwF0q3
layout/base/PresShell.cpp
layout/base/PresShell.h
toolkit/components/telemetry/Histograms.json
--- a/layout/base/PresShell.cpp
+++ b/layout/base/PresShell.cpp
@@ -29,16 +29,17 @@
 #include "mozilla/IMEStateManager.h"
 #include "mozilla/MemoryReporting.h"
 #include "mozilla/dom/TabChild.h"
 #include "mozilla/Likely.h"
 #include "mozilla/Logging.h"
 #include "mozilla/MouseEvents.h"
 #include "mozilla/Sprintf.h"
 #include "mozilla/TextEvents.h"
+#include "mozilla/TimeStamp.h"
 #include "mozilla/TouchEvents.h"
 #include "mozilla/UniquePtr.h"
 #include "mozilla/Unused.h"
 #include "mozilla/StyleBackendType.h"
 #include <algorithm>
 
 #ifdef XP_WIN
 #include "winuser.h"
@@ -565,16 +566,19 @@ public:
 private:
   nsCOMPtr<nsIDocument> mDocument;
 };
 
 bool PresShell::sDisableNonTestMouseEvents = false;
 
 mozilla::LazyLogModule PresShell::gLog("PresShell");
 
+mozilla::TimeStamp PresShell::sLastInputCreated;
+mozilla::TimeStamp PresShell::sLastInputProcessed;
+
 #ifdef DEBUG
 static void
 VerifyStyleTree(nsPresContext* aPresContext, nsFrameManager* aFrameManager)
 {
   if (nsFrame::GetVerifyStyleTreeEnable()) {
     if (aPresContext->RestyleManager()->IsServo()) {
       NS_ERROR("stylo: cannot verify style tree with a ServoRestyleManager");
       return;
@@ -8252,21 +8256,34 @@ PresShell::HandleEventInternal(WidgetEve
       break;
     }
   }
 
   if (Telemetry::CanRecordBase() &&
       !aEvent->mTimeStamp.IsNull() &&
       aEvent->mTimeStamp > mLastOSWake &&
       aEvent->AsInputEvent()) {
-    double millis = (TimeStamp::Now() - aEvent->mTimeStamp).ToMilliseconds();
+    TimeStamp now = TimeStamp::Now();
+    double millis = (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);
     }
+
+    if (!sLastInputProcessed || sLastInputProcessed < aEvent->mTimeStamp) {
+      if (sLastInputProcessed) {
+        // This input event was created after we handled the last one.
+        // Accumulate the previous events' coalesced duration.
+        double lastMillis = (sLastInputProcessed - sLastInputCreated).ToMilliseconds();
+        Telemetry::Accumulate(Telemetry::INPUT_EVENT_RESPONSE_COALESCED_MS,
+                              lastMillis);
+      }
+      sLastInputCreated = aEvent->mTimeStamp;
+    }
+    sLastInputProcessed = now;
   }
 
   return rv;
 }
 
 /* static */ void
 nsIPresShell::DispatchGotOrLostPointerCaptureEvent(
                 bool aIsGotCapture,
--- a/layout/base/PresShell.h
+++ b/layout/base/PresShell.h
@@ -903,13 +903,16 @@ protected:
   // Whether the widget has received a paint message yet.
   bool                      mHasReceivedPaintMessage : 1;
 
   bool                      mIsLastKeyDownCanceled : 1;
 
   static bool               sDisableNonTestMouseEvents;
 
   mozilla::TimeStamp        mLastOSWake;
+
+  static mozilla::TimeStamp sLastInputCreated;
+  static mozilla::TimeStamp sLastInputProcessed;
 };
 
 } // namespace mozilla
 
 #endif // mozilla_PresShell_h
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -5664,16 +5664,25 @@
     "alert_emails": ["perf-telemetry-alerts@mozilla.com"],
     "bug_numbers": [1235908],
     "expires_in_version": "never",
     "kind": "exponential",
     "high": 10000,
     "n_buckets": 50,
     "description": "Time (ms) from the Input event being created to the end of it being handled"
   },
+  "INPUT_EVENT_RESPONSE_COALESCED_MS": {
+    "alert_emails": ["perf-telemetry-alerts@mozilla.com"],
+    "bug_numbers": [1357457],
+    "expires_in_version": "61",
+    "kind": "exponential",
+    "high": 10000,
+    "n_buckets": 50,
+    "description": "Time (ms) from the Input event being created to the end of it being handled, but with overlapping events coalesced."
+  },
   "LOAD_INPUT_EVENT_RESPONSE_MS": {
     "alert_emails": ["perf-telemetry-alerts@mozilla.com"],
     "bug_numbers": [1298101],
     "expires_in_version": "never",
     "kind": "exponential",
     "high": 10000,
     "n_buckets": 50,
     "description": "Time (ms) from the Input event being created to the end of it being handled for events handling during page load only"