Add DumpWithoutCrash for slow Mac KeyPress events

Add a DumpWithoutCrash to KeyPress events where the timestamp of the OS
differs from the current time by more than 5 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: I90a8bb210debc8e9f0fcfba23a566200de72e9c2
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2144627
Reviewed-by: Avi Drissman <avi@chromium.org>
Commit-Queue: David Bokan <bokan@chromium.org>
Cr-Commit-Position: refs/heads/master@{#758871}

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 @@ void CancelTerminate() {
     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

@@ -120,6 +120,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 += "SELF-";
+    if ([NSApp keyWindow] == window)
+      windowInfoStr += "KEY-";
+    if ([NSApp mainWindow] == window)
+      windowInfoStr += "MAIN-";
+    if ([theEvent windowNumber] == [window windowNumber]) {
+      foundEventWindow = true;
+      windowInfoStr += "EVENT-";
+    }
+
+    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(
+        " Event: %ld", static_cast<long>([theEvent windowNumber]));
+
+  windowInfoStr += base::StringPrintf(
+      " isRedispatch[this:%d event:%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,
@@ -921,6 +993,16 @@ - (EventHandled)keyEvent:(NSEvent*)theEvent {
 
 - (void)keyEvent:(NSEvent*)theEvent wasKeyEquivalent:(BOOL)equiv {
   TRACE_EVENT0("browser", "RenderWidgetHostViewCocoa::keyEvent");
+  // 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,19 +236,35 @@ bool IsSystemKeyEvent(const blink::WebKeyboardEvent& 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 =
       ui::EventTimeStampFromSeconds([event timestamp]);
   if (record_debug_uma) {
     if (ui::EventTypeFromNative(event) == ui::ET_KEY_PRESSED) {
+      base::TimeDelta diff = now - hardware_timestamp;
       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),
+          diff.magnitude(), 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 many 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(5) &&
+          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

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