Calculate latency metric timestamps on windows based on GetTickCount

On Windows, EventTimeFromNative just returns the current time as the event timestamp, to smooth over the difference between touch events (timestamps based on the high-resolution timer) and other events (timestamps based on the low-resolution GetTickCount). This makes it impossible to measure the time between the event being generated by the OS and handled by Chrome for latency measurements. This patch continues to set timestamps in event objects from the current time, but calculates new Latency.OS_WIN.* metrics for certain events using the OS event timestamp. BUG=1189656 R=gab Change-Id: Ic152833c7e544499b785be4d3a758de1911c4cbc Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2769418 Reviewed-by: Jesse Doherty <jwd@chromium.org> Reviewed-by: Sadrul Chowdhury <sadrul@chromium.org> Reviewed-by: Gabriel Charette <gab@chromium.org> Commit-Queue: Joe Mason <joenotcharles@chromium.org> Cr-Commit-Position: refs/heads/master@{#866633}
FairyWorld · Mar 25, 2021 · 0c64eba · 0c64eba
1 parent 016588d
commit 0c64eba
Show file tree

Hide file tree

Showing 7 changed files with 350 additions and 5 deletions.
diff --git a/tools/metrics/histograms/histograms_xml/event/histograms.xml b/tools/metrics/histograms/histograms_xml/event/histograms.xml
@@ -410,6 +410,62 @@ reviews. Googlers can read more about this at go/gwsq-gerrit.
   </summary>
 </histogram>
 
+<histogram name="Event.Latency.OS_WIN.HIGH_RES" units="ms"
+    expires_after="2021-12-01">
+  <owner>joenotcharles@chromium.org</owner>
+  <owner>catan-team@chromium.org</owner>
+  <summary>
+    Experimental Windows-only histogram similar to Event.Latency.OS, but
+    recorded only for MOUSE_PRESSED and KEY_PRESSED events and including the
+    true time between when the event is generated by the OS and when it is
+    received by Chrome.
+
+    On Windows, ui::Event structures include a timestamp based on the time the
+    event is received, not when it is generated, so the cross-platform
+    Event.Latency.OS histograms which are based on this timestamp are wrong.
+
+    This metric is only reported from clients with high-resolution clocks.
+    Clients with low-resolution clocks record Event.Latency.OS_WIN.LOW_RES
+    instead. Once we validate that there is no difference between the two
+    metrics and all is working as expected we will combine them into a single
+    cross-platform event latency metric.
+  </summary>
+</histogram>
+
+<histogram name="Event.Latency.OS_WIN.LOW_RES" units="ms"
+    expires_after="2021-12-01">
+  <owner>joenotcharles@chromium.org</owner>
+  <owner>catan-team@chromium.org</owner>
+  <summary>
+    Experimental Windows-only histogram similar to Event.Latency.OS, but
+    recorded only for MOUSE_PRESSED and KEY_PRESSED events and including the
+    true time between when the event is generated by the OS and when it is
+    received by Chrome.
+
+    On Windows, ui::Event structures include a timestamp based on the time the
+    event is received, not when it is generated, so the cross-platform
+    Event.Latency.OS histograms which are based on this timestamp are wrong.
+
+    This metric is only reported from clients with low-resolution clocks.
+    Clients with high-resolution clocks record Event.Latency.OS_WIN.HIGH_RES
+    instead. Once we validate that there is no difference between the two
+    metrics and all is working as expected we will combine them into a single
+    cross-platform event latency metric.
+  </summary>
+</histogram>
+
+<histogram name="Event.Latency.OS_WIN_IS_VALID" enum="Boolean"
+    expires_after="2021-12-01">
+  <owner>joenotcharles@chromium.org</owner>
+  <owner>catan-team@chromium.org</owner>
+  <summary>
+    Windows-only boolean that records whether an input event has a valid OS
+    timestamp, recorded for MOUSE_PRESSED and KEY_PRESSED events when they are
+    received by Chrome. This is used to estimate the bias caused by skipping
+    events with invalid timestamps in Event.Latency.OS_WIN.*.
+  </summary>
+</histogram>
+
 <histogram name="Event.Latency.Scroll.Wheel.TimeToHandled2"
     units="microseconds" expires_after="2021-08-15">
   <owner>flackr@chromium.org</owner>

diff --git a/tools/metrics/histograms/histograms_xml/histogram_suffixes_list.xml b/tools/metrics/histograms/histograms_xml/histogram_suffixes_list.xml
@@ -6292,6 +6292,9 @@ reviews. Googlers can read more about this at go/gwsq-gerrit.
   <affected-histogram name="Event.Latency.OS"/>
   <affected-histogram name="Event.Latency.OS_NO_VALIDATION.NEGATIVE"/>
   <affected-histogram name="Event.Latency.OS_NO_VALIDATION.POSITIVE"/>
+  <affected-histogram name="Event.Latency.OS_WIN.HIGH_RES"/>
+  <affected-histogram name="Event.Latency.OS_WIN.LOW_RES"/>
+  <affected-histogram name="Event.Latency.OS_WIN_IS_VALID"/>
 </histogram_suffixes>
 
 <histogram_suffixes name="EventLatencyPinchTypes" separator=".">

diff --git a/ui/events/base_event_utils.cc b/ui/events/base_event_utils.cc
@@ -27,11 +27,6 @@ const int kSystemKeyModifierMask = EF_COMMAND_DOWN;
 const int kSystemKeyModifierMask = EF_ALT_DOWN;
 #endif  // !BUILDFLAG(IS_CHROMEOS_ASH) && !defined(OS_APPLE)
 
-bool IsValidTimebase(base::TimeTicks now, base::TimeTicks timestamp) {
-  int64_t delta = (now - timestamp).InMilliseconds();
-  return delta >= 0 && delta <= 60 * 1000;
-}
-
 }  // namespace
 
 base::AtomicSequenceNumber g_next_event_id;
@@ -73,6 +68,11 @@ base::TimeTicks EventTimeStampFromSeconds(double time_stamp_seconds) {
   return base::TimeTicks() + base::TimeDelta::FromSecondsD(time_stamp_seconds);
 }
 
+bool IsValidTimebase(base::TimeTicks now, base::TimeTicks timestamp) {
+  int64_t delta = (now - timestamp).InMilliseconds();
+  return delta >= 0 && delta <= 60 * 1000;
+}
+
 void ValidateEventTimeClock(base::TimeTicks* timestamp) {
   // Some fraction of devices, across all platforms provide bogus event
   // timestamps. See https://crbug.com/650338#c1. Correct timestamps which are

diff --git a/ui/events/base_event_utils.h b/ui/events/base_event_utils.h
@@ -43,6 +43,13 @@ EVENTS_BASE_EXPORT double EventTimeStampToSeconds(base::TimeTicks time_stamp);
 EVENTS_BASE_EXPORT base::TimeTicks EventTimeStampFromSeconds(
     double time_stamp_seconds);
 
+// Returns false if an event timestamp is clearly bogus given that the event
+// was generated a short time before |now|. Some fraction of devices, across
+// all platforms provide bogus event timestamps. See
+// https://crbug.com/650338#c1.
+EVENTS_BASE_EXPORT bool IsValidTimebase(base::TimeTicks now,
+                                        base::TimeTicks timestamp);
+
 // Ensures that the event timestamp values are coming from the same underlying
 // monotonic clock as base::TimeTicks::Now() and if it is not then falls
 // back to using the current ticks for event timestamp.

diff --git a/ui/events/event_unittest.cc b/ui/events/event_unittest.cc
@@ -7,10 +7,14 @@
 #include <stddef.h>
 #include <stdint.h>
 
+#include <limits>
 #include <memory>
+#include <string>
 
 #include "base/stl_util.h"
+#include "base/strings/strcat.h"
 #include "base/test/metrics/histogram_tester.h"
+#include "base/test/simple_test_tick_clock.h"
 #include "build/build_config.h"
 #include "testing/gtest/include/gtest/gtest.h"
 #include "ui/base/ui_base_features.h"
@@ -654,6 +658,12 @@ TEST(EventTest, EventLatencyOSMouseWheelHistogram) {
   MSG event = {nullptr, WM_MOUSEWHEEL, 0, 0};
   MouseWheelEvent mouseWheelEvent(event);
   histogram_tester.ExpectTotalCount("Event.Latency.OS.MOUSE_WHEEL", 1);
+  histogram_tester.ExpectTotalCount("Event.Latency.OS_WIN.HIGH_RES.MOUSE_WHEEL",
+                                    0);
+  histogram_tester.ExpectTotalCount("Event.Latency.OS_WIN.LOW_RES.MOUSE_WHEEL",
+                                    0);
+  histogram_tester.ExpectTotalCount("Event.Latency.OS_WIN_IS_VALID.MOUSE_WHEEL",
+                                    0);
 #endif
 }
 
@@ -830,6 +840,120 @@ INSTANTIATE_TEST_SUITE_P(
     ::testing::Combine(::testing::Values(WM_CHAR),
                        ::testing::ValuesIn(kAltGraphEventTestCases)));
 
+constexpr struct EventLatencyOSWinTestCase {
+  EventType event_type;
+  UINT win_event;
+  const char* histogram_suffix;
+} kEventLatencyOSWinTestCases[] = {
+    {
+        ET_KEY_PRESSED,
+        WM_KEYDOWN,
+        "KEY_PRESSED",
+    },
+    {
+        ET_MOUSE_PRESSED,
+        WM_LBUTTONDOWN,
+        "MOUSE_PRESSED",
+    },
+};
+
+class EventLatencyOSWinTest
+    : public ::testing::TestWithParam<EventLatencyOSWinTestCase> {
+ public:
+  EventLatencyOSWinTest() { SetEventLatencyTickClockForTesting(&tick_clock_); }
+
+  ~EventLatencyOSWinTest() { SetEventLatencyTickClockForTesting(nullptr); }
+
+ protected:
+  static constexpr char kHighResHistogram[] = "Event.Latency.OS_WIN.HIGH_RES";
+  static constexpr char kLowResHistogram[] = "Event.Latency.OS_WIN.LOW_RES";
+  static constexpr char kIsValidHistogram[] = "Event.Latency.OS_WIN_IS_VALID";
+
+  void UpdateTickClock(DWORD timestamp) {
+    tick_clock_.SetNowTicks(base::TimeTicks() +
+                            base::TimeDelta::FromMilliseconds(timestamp));
+  }
+
+  std::string HighResEventHistogram() const {
+    return base::StrCat({kHighResHistogram, ".", GetParam().histogram_suffix});
+  }
+
+  std::string LowResEventHistogram() const {
+    return base::StrCat({kLowResHistogram, ".", GetParam().histogram_suffix});
+  }
+
+  std::string IsValidEventHistogram() const {
+    return base::StrCat({kIsValidHistogram, ".", GetParam().histogram_suffix});
+  }
+
+  void ExpectValidHistograms(const base::HistogramTester& histogram_tester,
+                             base::TimeDelta delta) {
+    // Expect both general and per-event histograms to be set.
+    histogram_tester.ExpectUniqueSample(kIsValidHistogram, true, 1);
+    histogram_tester.ExpectUniqueSample(IsValidEventHistogram(), true, 1);
+    if (base::TimeTicks::IsHighResolution()) {
+      histogram_tester.ExpectUniqueTimeSample(kHighResHistogram, delta, 1);
+      histogram_tester.ExpectUniqueTimeSample(HighResEventHistogram(), delta,
+                                              1);
+      histogram_tester.ExpectTotalCount(kLowResHistogram, 0);
+      histogram_tester.ExpectTotalCount(LowResEventHistogram(), 0);
+    } else {
+      histogram_tester.ExpectUniqueTimeSample(kLowResHistogram, delta, 1);
+      histogram_tester.ExpectUniqueTimeSample(LowResEventHistogram(), delta, 1);
+      histogram_tester.ExpectTotalCount(kHighResHistogram, 0);
+      histogram_tester.ExpectTotalCount(HighResEventHistogram(), 0);
+    }
+  }
+
+  base::SimpleTestTickClock tick_clock_;
+};
+
+TEST_P(EventLatencyOSWinTest, ComputeEventLatencyOS) {
+  // Create an event whose timestamp is very close to the max range of
+  // ::GetTickCount.
+  constexpr DWORD timestamp_msec = std::numeric_limits<DWORD>::max() - 10;
+  const MSG event = {nullptr, GetParam().win_event, 0, 0, timestamp_msec};
+
+  // Measure the latency of an event that's processed not long after the OS
+  // timestamp.
+  UpdateTickClock(timestamp_msec + 5);
+  {
+    base::HistogramTester histogram_tester;
+    ComputeEventLatencyOS(event);
+    ExpectValidHistograms(histogram_tester,
+                          base::TimeDelta::FromMilliseconds(5));
+  }
+
+  // Simulate ::GetTickCount advancing 15 msec, which wraps around past 0.
+  constexpr DWORD wrapped_timestamp_msec = timestamp_msec + 15;
+  static_assert(wrapped_timestamp_msec == 4,
+                "timestamp should have wrapped around");
+  UpdateTickClock(wrapped_timestamp_msec);
+  {
+    base::HistogramTester histogram_tester;
+    ComputeEventLatencyOS(event);
+    ExpectValidHistograms(histogram_tester,
+                          base::TimeDelta::FromMilliseconds(15));
+  }
+
+  // Simulate an event with a bogus timestamp.
+  UpdateTickClock(timestamp_msec - 1000);
+  {
+    base::HistogramTester histogram_tester;
+    ComputeEventLatencyOS(event);
+    histogram_tester.ExpectUniqueSample(kIsValidHistogram, false, 1);
+    histogram_tester.ExpectUniqueSample(IsValidEventHistogram(), false, 1);
+    histogram_tester.ExpectTotalCount(kHighResHistogram, 0);
+    histogram_tester.ExpectTotalCount(HighResEventHistogram(), 0);
+    histogram_tester.ExpectTotalCount(kLowResHistogram, 0);
+    histogram_tester.ExpectTotalCount(LowResEventHistogram(), 0);
+  }
+}
+
+INSTANTIATE_TEST_SUITE_P(All,
+                         EventLatencyOSWinTest,
+                         ::testing::ValuesIn(kEventLatencyOSWinTestCases));
+
 #endif  // defined(OS_WIN)
 
 }  // namespace ui