Record debug UMA only when event sent to renderer

Mac key event handling works by first sending a key to the renderer.
When the renderer ACKs the event as unconsumed, the browser re-injects
the NSEvent back into the app. This is done so that the browser can
perform commands if the renderer didn't consume them (e.g. Command-T).

The Event.Latency.OS_NO_VALIDATION metric was temporarily added to
investigate the cause of long instances in the InputDelay metric. It
measures the delta between the event's OS-provided timestamp and the
current time when a WebKeyboardEvent is built from an NSEvent. This
metric is meant to narrow down where these long InputDelay values are
coming from.

OS_NO_VALIDATION assumes that the call to it happens close to where the
OS event is received by Chrome.  However, the reinjection mechanism
mentioned at the top breaks this assumption. When the event is
reinjected, there are cases where it must be passed to the content/
layer (e.g. when being passed to the Views FocusManager[1]) and a
WebKeyboardEvent is reconstructed.  Hence we record this metric multiple
times for such events, the second time causing the metric to depend on
delays in the jank.

This can reproduced by visiting a page with a very busy main thread
(e.g.  https://rbyers.github.io/scroll-latency.html and set a high
periodic jank) and performing "key equivalents" (i.e. browser commands
like Command-C) while the main thread is blocked. You'll notice very
high values reported in [2].

This CL adds a temporary constructor to NativeWebKeyboardEvent on Mac
that causes us to record this metric only on the code path that will
eventually send the event to the renderer (i.e.  avoid reinjected
events). This is temporary to prove this hypothesis and determine how
much of the problematic reports are due to other causes. It will be
reverted after a few days of data is collected.

Note: In https://crrev.com/4a7404eceeb I added a DumpWithoutCrash in
cases where we saw a big discrepancy in the Now() and event timestamp.
The issue addressed in this CL shows up in these stacks but there are
other cases that have a big discrepancy and are captured from
RenderWidgetHostViewCocoa::keyEvent. This CL will help cut down on the
noise so we can keep diagnosing the root cause.

[1] https://cs.chromium.org/chromium/src/chrome/browser/ui/cocoa/chrome_command_dispatcher_delegate.mm?l=44&rcl=fb1021a791d9141b4df6d639f0d50bfe0c0ce944
[2] chrome://histograms/Event.Latency.OS_NO_VALIDATION.POSITIVE.KEY_PRESSED


Bug: 1039833
Change-Id: I17af7f76db0f69024ec75b45822d69178a4cd565
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2129238
Commit-Queue: David Bokan <bokan@chromium.org>
Reviewed-by: Avi Drissman <avi@chromium.org>
Cr-Commit-Position: refs/heads/master@{#755118}

content/app_shim_remote_cocoa/render_widget_host_view_cocoa.mm

@@ -949,8 +949,8 @@ void ExtractUnderlines(NSAttributedString* string,
   // Don't cancel child popups; the key events are probably what's triggering
   // the popup in the first place.
 
-
-  NativeWebKeyboardEvent event(theEvent);
+  NativeWebKeyboardEvent event =
+      NativeWebKeyboardEvent::CreateForRenderer(theEvent);
   ui::LatencyInfo latency_info;
   if (event.GetType() == blink::WebInputEvent::kRawKeyDown ||
       event.GetType() == blink::WebInputEvent::kChar) {

content/browser/renderer_host/input/web_input_event_builders_mac.h

@@ -19,7 +19,15 @@ namespace content {
 
 class CONTENT_EXPORT WebKeyboardEventBuilder {
  public:
-  static blink::WebKeyboardEvent Build(NSEvent* event);
+  // TODO(bokan): Temporarily added the |record_debug_uma| param to help debug
+  // https://crbug.com/1039833. This parameter controls whether
+  // Event.Latency.OS_NO_VALIDATION metrics are collected for the key event.
+  // The purpose is to limit this to only those events that are being handled
+  // synchronously from the OS message loop since we can reinject the same
+  // NSEvent back into the app multiple times; we want to record this stat only
+  // the first time the event was received.
+  static blink::WebKeyboardEvent Build(NSEvent* event,
+                                       bool record_debug_uma = false);
 };
 
 class CONTENT_EXPORT WebMouseEventBuilder {

content/browser/renderer_host/input/web_input_event_builders_mac.mm

@@ -233,19 +233,22 @@ blink::WebMouseEvent::Button ButtonFromButtonNumber(NSEvent* event) {
 
 }  // namespace
 
-blink::WebKeyboardEvent WebKeyboardEventBuilder::Build(NSEvent* event) {
+blink::WebKeyboardEvent WebKeyboardEventBuilder::Build(NSEvent* event,
+                                                       bool record_debug_uma) {
   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);
+  if (record_debug_uma) {
+    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 =

content/browser/renderer_host/native_web_keyboard_event_mac.mm

@@ -96,8 +96,23 @@ NativeWebKeyboardEvent::NativeWebKeyboardEvent(
   [os_event eventRef];
 }
 
+// static
+NativeWebKeyboardEvent NativeWebKeyboardEvent::CreateForRenderer(
+    gfx::NativeEvent native_event) {
+  return NativeWebKeyboardEvent(native_event, true);
+}
+
+NativeWebKeyboardEvent::NativeWebKeyboardEvent(gfx::NativeEvent native_event,
+                                               bool record_debug_uma)
+    : WebKeyboardEvent(
+          WebKeyboardEventBuilder::Build(native_event, record_debug_uma)),
+      os_event([native_event retain]),
+      skip_in_browser(false) {}
+
 NativeWebKeyboardEvent::NativeWebKeyboardEvent(gfx::NativeEvent native_event)
-    : WebKeyboardEvent(WebKeyboardEventBuilder::Build(native_event)),
+    : WebKeyboardEvent(
+          WebKeyboardEventBuilder::Build(native_event,
+                                         /*record_debug_uma=*/false)),
       os_event([native_event retain]),
       skip_in_browser(false) {}
 

content/public/browser/native_web_keyboard_event.h

@@ -56,6 +56,17 @@ struct CONTENT_EXPORT NativeWebKeyboardEvent : public blink::WebKeyboardEvent {
 #endif
 #endif
 
+#if defined(OS_MACOSX)
+  // TODO(bokan): Temporarily added to debug https://crbug.com/1039833. This is
+  // used to allow collecting Event.Latency.OS_NO_VALIDATION only in contexts
+  // where the key event will be sent to the renderer.  The purpose is to avoid
+  // recording it for reinjected events after the renderer has already
+  // processed the event.
+  static NativeWebKeyboardEvent CreateForRenderer(
+      gfx::NativeEvent native_event);
+  NativeWebKeyboardEvent(gfx::NativeEvent native_event, bool record_debug_uma);
+#endif
+
   NativeWebKeyboardEvent(const NativeWebKeyboardEvent& event);
   ~NativeWebKeyboardEvent() override;