Add additional histograms for OS event latency on Mac.

These will be used to debug extreme outlier values of the
PageLoad.InputDelay3 histogram.

First, add all event types used to calculate PageLoad.InputDelay3 to
Event.Latency.OS. Move the calls to generate the histogram into the
functions that build the events, because the calling functions for the
new event types have much more complex logic.

Second, add new versions of Event.Latency.OS without the call to
ValidateEventTimeClock(). This call fixes some potential causes of
extreme values, so adding histograms which do not include it can help
determine if it masks the problem.

Bug: 1039833
Change-Id: I48cfa3613dd7c6a1d15b75e7a91f53b3f46a90c8
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2022346
Reviewed-by: Avi Drissman <avi@chromium.org>
Reviewed-by: Jesse Doherty <jwd@chromium.org>
Reviewed-by: Navid Zolghadr <nzolghadr@chromium.org>
Commit-Queue: Annie Sullivan <sullivan@chromium.org>
Cr-Commit-Position: refs/heads/master@{#737475}

content/app_shim_remote_cocoa/render_widget_host_view_cocoa.mm

@@ -1315,9 +1315,6 @@ void ExtractUnderlines(NSAttributedString* string,
       return;
   }
 
-  // Compute Event.Latency.OS.MOUSE_WHEEL histogram.
-  ui::ComputeEventLatencyOS(event);
-
   // Use an NSEvent monitor to listen for the wheel-end end. This ensures that
   // the event is received even when the mouse cursor is no longer over the view
   // when the scrolling ends (e.g. if the tab was switched). This is necessary

content/browser/renderer_host/input/web_input_event_builders_mac.mm

@@ -35,6 +35,7 @@
 
 #include <stdint.h>
 
+#include "base/metrics/histogram_macros.h"
 #include "base/strings/string_util.h"
 #include "base/time/time.h"
 #include "third_party/blink/public/common/input/web_input_event.h"
@@ -42,6 +43,7 @@
 #include "ui/events/base_event_utils.h"
 #include "ui/events/blink/blink_event_util.h"
 #import "ui/events/cocoa/cocoa_event_utils.h"
+#include "ui/events/event_utils.h"
 #include "ui/events/keycodes/keyboard_code_conversion.h"
 #include "ui/events/keycodes/keyboard_code_conversion_mac.h"
 
@@ -232,6 +234,19 @@ blink::WebMouseEvent::Button ButtonFromButtonNumber(NSEvent* event) {
 }  // namespace
 
 blink::WebKeyboardEvent WebKeyboardEventBuilder::Build(NSEvent* event) {
+  ui::ComputeEventLatencyOS(event);
+  base::TimeTicks now = ui::EventTimeForNow();
+  base::TimeTicks hardware_timestamp =
+      ui::EventTimeStampFromSeconds([event timestamp]);
+  if (ui::EventTypeFromNative(event) == ui::ET_KEY_PRESSED) {
+    UMA_HISTOGRAM_CUSTOM_TIMES(
+        now > hardware_timestamp
+            ? "Event.Latency.OS_NO_VALIDATION.POSITIVE.KEY_PRESSED"
+            : "Event.Latency.OS_NO_VALIDATION.NEGATIVE.KEY_PRESSED",
+        (now - hardware_timestamp).magnitude(),
+        base::TimeDelta::FromMilliseconds(1), base::TimeDelta::FromSeconds(60),
+        50);
+  }
   ui::DomCode dom_code = ui::DomCodeFromNSEvent(event);
   int modifiers =
       ModifiersFromEvent(event) | ui::DomCodeToWebInputEventModifiers(dom_code);
@@ -287,6 +302,19 @@ blink::WebMouseEvent WebMouseEventBuilder::Build(
     NSEvent* event,
     NSView* view,
     blink::WebPointerProperties::PointerType pointerType) {
+  ui::ComputeEventLatencyOS(event);
+  base::TimeTicks now = ui::EventTimeForNow();
+  base::TimeTicks hardware_timestamp =
+      ui::EventTimeStampFromSeconds([event timestamp]);
+  if (ui::EventTypeFromNative(event) == ui::ET_MOUSE_PRESSED) {
+    UMA_HISTOGRAM_CUSTOM_TIMES(
+        now > hardware_timestamp
+            ? "Event.Latency.OS_NO_VALIDATION.POSITIVE.MOUSE_PRESSED"
+            : "Event.Latency.OS_NO_VALIDATION.NEGATIVE.MOUSE_PRESSED",
+        (now - hardware_timestamp).magnitude(),
+        base::TimeDelta::FromMilliseconds(1), base::TimeDelta::FromSeconds(60),
+        50);
+  }
   blink::WebInputEvent::Type event_type =
       blink::WebInputEvent::Type::kUndefined;
   int click_count = 0;
@@ -395,6 +423,17 @@ blink::WebMouseEvent WebMouseEventBuilder::Build(
 blink::WebMouseWheelEvent WebMouseWheelEventBuilder::Build(
     NSEvent* event,
     NSView* view) {
+  ui::ComputeEventLatencyOS(event);
+  base::TimeTicks now = ui::EventTimeForNow();
+  base::TimeTicks hardware_timestamp =
+      ui::EventTimeStampFromSeconds([event timestamp]);
+  UMA_HISTOGRAM_CUSTOM_TIMES(
+      now > hardware_timestamp
+          ? "Event.Latency.OS_NO_VALIDATION.POSITIVE.MOUSE_WHEEL"
+          : "Event.Latency.OS_NO_VALIDATION.NEGATIVE.MOUSE_WHEEL",
+      (now - hardware_timestamp).magnitude(),
+      base::TimeDelta::FromMilliseconds(1), base::TimeDelta::FromSeconds(60),
+      50);
   blink::WebMouseWheelEvent result(
       blink::WebInputEvent::kMouseWheel, ModifiersFromEvent(event),
       ui::EventTimeStampFromSeconds([event timestamp]));
@@ -626,6 +665,19 @@ blink::WebTouchEvent WebTouchEventBuilder::Build(NSEvent* event, NSView* view) {
 
   blink::WebTouchEvent result(event_type, ModifiersFromEvent(event),
                               ui::EventTimeStampFromSeconds([event timestamp]));
+  if (ui::EventTypeFromNative(event) == ui::ET_TOUCH_PRESSED) {
+    base::TimeTicks now = ui::EventTimeForNow();
+    base::TimeTicks hardware_timestamp =
+        ui::EventTimeStampFromSeconds([event timestamp]);
+    UMA_HISTOGRAM_CUSTOM_TIMES(
+        now > hardware_timestamp
+            ? "Event.Latency.OS.NO_VALIDATION.POSITIVE.TOUCH_PRESSED"
+            : "Event.Latency.OS.NO_VALIDATION.NEGATIVE.TOUCH_PRESSED",
+        (now - hardware_timestamp).magnitude(),
+        base::TimeDelta::FromMilliseconds(1), base::TimeDelta::FromSeconds(60),
+        50);
+  }
+  ui::ComputeEventLatencyOS(event);
   result.hovering = event_type == blink::WebInputEvent::kTouchEnd;
   result.unique_touch_event_id = ui::GetNextTouchEventId();
   result.touches_length = 1;

tools/metrics/histograms/histograms.xml

@@ -44811,6 +44811,34 @@ uploading your change for review.
   </summary>
 </histogram>
 
+<histogram name="Event.Latency.OS_NO_VALIDATION.NEGATIVE" units="ms"
+    expires_after="2020-06-28">
+  <owner>sullivan@chromium.org</owner>
+  <owner>input-dev@chromium.org</owner>
+  <summary>
+    For Mac, a version of Event.Latency.OS that has the negative values it would
+    contain if ValidateEventTimeClock() were not called on the timestamps.
+
+    This metric is intended to debug http://crbug.com/1039833, where very high
+    numbers are seen for PageLoad.InputDelay3. The units of this metric are the
+    same as PageLoad.InputDelay3 for consistency while debugging.
+  </summary>
+</histogram>
+
+<histogram name="Event.Latency.OS_NO_VALIDATION.POSITIVE" units="ms"
+    expires_after="2020-06-28">
+  <owner>sullivan@chromium.org</owner>
+  <owner>input-dev@chromium.org</owner>
+  <summary>
+    For Mac, a version of Event.Latency.OS that has the positive values it would
+    contain if ValidateEventTimeClock() were not called on the timestamps.
+
+    This metric is intended to debug http://crbug.com/1039833, where very high
+    numbers are seen for PageLoad.InputDelay3. The units of this metric are the
+    same as PageLoad.InputDelay3 for consistency while debugging.
+  </summary>
+</histogram>
+
 <histogram name="Event.Latency.QueueingTime.KeyPressDefaultAllowed" units="ms"
     expires_after="2020-03-29">
   <owner>tdresser@chromium.org</owner>
@@ -181295,11 +181323,15 @@ regressions. -->
 </histogram_suffixes>
 
 <histogram_suffixes name="EventLatencyOS" separator=".">
+  <suffix name="KEY_PRESSED" label=""/>
+  <suffix name="MOUSE_PRESSED" label=""/>
   <suffix name="MOUSE_WHEEL" label=""/>
   <suffix name="TOUCH_MOVED" label=""/>
   <suffix name="TOUCH_PRESSED" label=""/>
   <suffix name="TOUCH_RELEASED" label=""/>
   <affected-histogram name="Event.Latency.OS"/>
+  <affected-histogram name="Event.Latency.OS_NO_VALIDATION.NEGATIVE"/>
+  <affected-histogram name="Event.Latency.OS_NO_VALIDATION.POSITIVE"/>
 </histogram_suffixes>
 
 <histogram_suffixes name="ExitFunnels" separator=".">

ui/events/event_utils.cc

@@ -127,6 +127,16 @@ void ComputeEventLatencyOS(const PlatformEvent& native_event) {
           "Event.Latency.OS.TOUCH_RELEASED",
           base::saturated_cast<int>(delta.InMicroseconds()), 1, 1000000, 50);
       return;
+    case ET_KEY_PRESSED:
+      UMA_HISTOGRAM_CUSTOM_COUNTS(
+          "Event.Latency.OS.KEY_PRESSED",
+          base::saturated_cast<int>(delta.InMicroseconds()), 1, 1000000, 50);
+      return;
+    case ET_MOUSE_PRESSED:
+      UMA_HISTOGRAM_CUSTOM_COUNTS(
+          "Event.Latency.OS.MOUSE_PRESSED",
+          base::saturated_cast<int>(delta.InMicroseconds()), 1, 1000000, 50);
+      return;
     default:
       return;
   }