[Reland] Add DumpWithoutCrash for slow Mac KeyPress events

[Reland] - This is effectively a reland, first patchset is unchanged
https://crrev.com/74f12a609316ba81 so compare to that for changes. That
iteration provided some interesting data but used a triggering time of 5
seconds. I've since learned that there's a myriad of known edge-cases in
which events might have delays of 1-20 seconds (!). In our case, we're
specifically looking for issues at the upper end of the UMA metric (60+
seconds) so this caused some unrelated noise. This CL relands with a
higher threshold and some minor changes to the crash keys.

Add a DumpWithoutCrash to KeyPress events where the timestamp of the OS
differs from the current time by more than 60 seconds. We see in UMA
that we often see events in the 95% percentile reaching many seconds of
difference. Hopefully the crash stacks will reveal something about
what's causing this.

A previous iteration of this investigation in
https://crrev.com/c/2111782 showed that we sometimes redispatch events
that have been reinjected back from the renderer. This should never
happen. This CL adds crash keys to dump some of the related app state
to help explain how this happens.

However, not all such stack traces showed reinjection so that can't be
the cause of all these bad timestamps. This CL also adds some timing
information to the existing crash key in NSApp:sendEvent which might
reveal something.

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

chrome/browser/chrome_browser_application_mac.mm

@@ -21,6 +21,7 @@
 #include "content/public/browser/native_event_processor_mac.h"
 #include "content/public/browser/native_event_processor_observer_mac.h"
 #include "ui/base/cocoa/accessibility_focus_overrider.h"
+#include "ui/events/base_event_utils.h"
 
 namespace chrome_browser_application_mac {
 
@@ -94,6 +95,16 @@ std::string DescriptionForNSEvent(NSEvent* event) {
     default:
       break;
   }
+
+  // TODO(bokan): Added temporarily to debug https://crbug.com/1039833.
+  base::TimeTicks event_timestamp =
+      ui::EventTimeStampFromSeconds([event timestamp]);
+  base::TimeTicks now = ui::EventTimeForNow();
+  base::TimeDelta diff = now - event_timestamp;
+  desc += base::StringPrintf(" Now: %lld Diff: %lld",
+                             (now - base::TimeTicks()).InSeconds(),
+                             diff.InSeconds());
+
   return desc;
 }
 

content/app_shim_remote_cocoa/render_widget_host_view_cocoa.mm

@@ -119,6 +119,78 @@ SkColor SkColorFromNSColor(NSColor* color) {
          base::ClampToRange(static_cast<int>(lroundf(255.0f * b)), 0, 255);
 }
 
+// TODO(bokan): Added temporarily to debug https://crbug.com/1039833.
+// Needed only in temporary method below.
+CommandDispatcher* GetCommandDispatcher(NSWindow* theWindow) {
+  if ([theWindow conformsToProtocol:@protocol(CommandDispatchingWindow)]) {
+    return [static_cast<NSObject<CommandDispatchingWindow>*>(theWindow)
+        commandDispatcher];
+  }
+  return nil;
+}
+
+// TODO(bokan): Added temporarily to debug https://crbug.com/1039833.
+// Returns a string with class names of each ancestor view of this one
+// (inclusive).
+std::string GetViewHierarchyString(NSView* thisView) {
+  std::string ret = "";
+  NSView* view = thisView;
+  while (view) {
+    ret += base::SysNSStringToUTF8(NSStringFromClass([view class])) + "->";
+    view = [view superview];
+  }
+
+  return ret;
+}
+
+// TODO(bokan): Added temporarily to debug https://crbug.com/1039833.
+// Returns a string with information about all the app's windows and current
+// event redispatch state of this window and the event's window.
+std::string GetWindowInfoString(NSWindow* thisWindow, NSEvent* theEvent) {
+  std::string windowInfoStr = "[";
+  NSArray* windows = [NSApp windows];
+  bool foundEventWindow = false;
+  for (unsigned int i = 0; i < [windows count]; ++i) {
+    NSWindow* window = windows[i];
+    if (thisWindow == window)
+      windowInfoStr += "S-";
+    if ([NSApp keyWindow] == window)
+      windowInfoStr += "K-";
+    if ([NSApp mainWindow] == window)
+      windowInfoStr += "M-";
+    if ([theEvent windowNumber] == [window windowNumber]) {
+      foundEventWindow = true;
+      windowInfoStr += "E-";
+    }
+
+    std::string className =
+        base::SysNSStringToUTF8(NSStringFromClass([window class]));
+    NSRect rect = [window frame];
+    windowInfoStr += base::StringPrintf(
+        "%ld<%s - %dx%d>, ", static_cast<long>([window windowNumber]),
+        className.c_str(), static_cast<int>(NSWidth(rect)),
+        static_cast<int>(NSHeight(rect)));
+  }
+  windowInfoStr += "]";
+
+  if (!foundEventWindow)
+    windowInfoStr += base::StringPrintf(
+        " E: %ld", static_cast<long>([theEvent windowNumber]));
+
+  windowInfoStr += base::StringPrintf(
+      " R[t:%d e:%d]",
+      GetCommandDispatcher(thisWindow) == nil
+          ? -1
+          : static_cast<int>(
+                [GetCommandDispatcher(thisWindow) isRedispatchingKeyEvent]),
+      GetCommandDispatcher([theEvent window]) == nil
+          ? -1
+          : static_cast<int>([GetCommandDispatcher([theEvent window])
+                isRedispatchingKeyEvent]));
+
+  return windowInfoStr;
+}
+
 // Extract underline information from an attributed string. Mostly copied from
 // third_party/WebKit/Source/WebKit/mac/WebView/WebHTMLView.mm
 void ExtractUnderlines(NSAttributedString* string,
@@ -925,6 +997,16 @@ void ExtractUnderlines(NSAttributedString* string,
 - (void)keyEvent:(NSEvent*)theEvent wasKeyEquivalent:(BOOL)equiv {
   TRACE_EVENT1("browser", "RenderWidgetHostViewCocoa::keyEvent", "WindowNum",
                [[self window] windowNumber]);
+  // TODO(bokan): Added temporarily to debug https://crbug.com/1039833.
+  static auto* windowInfoKey = base::debug::AllocateCrashKeyString(
+      "window-info", base::debug::CrashKeySize::Size256);
+  static auto* viewInfoKey = base::debug::AllocateCrashKeyString(
+      "view-info", base::debug::CrashKeySize::Size256);
+  base::debug::ScopedCrashKeyString scopedKeyWindow(
+      windowInfoKey, GetWindowInfoString([self window], theEvent));
+  base::debug::ScopedCrashKeyString scopedKeyView(viewInfoKey,
+                                                  GetViewHierarchyString(self));
+
   NSEventType eventType = [theEvent type];
   NSEventModifierFlags modifierFlags = [theEvent modifierFlags];
   int keyCode = [theEvent keyCode];

content/browser/renderer_host/input/web_input_event_builders_mac.mm

@@ -35,6 +35,7 @@
 
 #include <stdint.h>
 
+#include "base/debug/dump_without_crashing.h"
 #include "base/metrics/histogram_macros.h"
 #include "base/strings/string_util.h"
 #include "base/time/time.h"
@@ -235,6 +236,12 @@ blink::WebMouseEvent::Button ButtonFromButtonNumber(NSEvent* event) {
 
 blink::WebKeyboardEvent WebKeyboardEventBuilder::Build(NSEvent* event,
                                                        bool record_debug_uma) {
+  // TODO(bokan) Temporary to debug crbug.com/1039833.
+  // It's assumed that some clients may fall into a bad state and produce these
+  // bad timestamps on lots of subsequent events. To prevent sending an
+  // overwhelming amount of crash reports stop after sending 5.
+  static int dump_without_crashing_throttle = 5;
+
   ui::ComputeEventLatencyOS(event);
   base::TimeTicks now = ui::EventTimeForNow();
   base::TimeTicks hardware_timestamp =
@@ -254,6 +261,16 @@ blink::WebKeyboardEvent WebKeyboardEventBuilder::Build(NSEvent* event,
             base::TimeDelta::FromMilliseconds(1),
             base::TimeDelta::FromSeconds(60), 50);
       }
+
+      // TODO(bokan) Temporary to debug crbug.com/1039833. We've seen in UMA
+      // that we often receive key press events with the OS timestamp differing
+      // from the current timestamp by 60+ seconds. Try to capture a few crash
+      // reports from the wild to see if we can find some pattern.
+      if (diff.magnitude() > base::TimeDelta::FromSeconds(60) &&
+          dump_without_crashing_throttle > 0) {
+        --dump_without_crashing_throttle;
+        base::debug::DumpWithoutCrashing();
+      }
     }
   }
   ui::DomCode dom_code = ui::DomCodeFromNSEvent(event);

ui/base/cocoa/command_dispatcher.h

@@ -58,6 +58,9 @@ UI_BASE_EXPORT
 - (void)dispatchUsingKeyModifiers:(id)sender
                        forHandler:(id<UserInterfaceItemCommandHandler>)handler;
 
+// TODO(bokan): Temporary to help debug https://crbug.com/1039833.
+- (BOOL)isRedispatchingKeyEvent;
+
 @end
 
 // If the NSWindow's firstResponder implements CommandDispatcherTarget, then

ui/base/cocoa/command_dispatcher.mm

@@ -226,6 +226,10 @@
     [[self bubbleParent] commandDispatchUsingKeyModifiers:sender];
 }
 
+- (BOOL)isRedispatchingKeyEvent {
+  return _isRedispatchingKeyEvent;
+}
+
 - (NSWindow<CommandDispatchingWindow>*)bubbleParent {
   NSWindow* parent = [_owner parentWindow];
   if (parent && [parent hasKeyAppearance] &&