Add Keyboard Latency UMA Metrics.

content/browser/renderer_host/input/render_widget_host_latency_tracker.cc

 // Copyright 2014 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "content/browser/renderer_host/input/render_widget_host_latency_tracker.h"

[mfomitchev, 2017/04/04 14:59:05]

General comment: I am wondering if we should split up this class into a
hierarchy of separate classes handling touch, mouse, and key events. ZI think
this could make the code cleaner. There's a lot of if's and some state that is
only specific to touch.

[tdresser, 2017/05/01 15:49:21]

I agree this is getting a bit unwieldy, but it isn't completely clear to me how
to slice this. There is a fair bit of overlap between logic for various sorts of
input, and there will be more as we improve coverage for different input types.

We could potentially split up scrolling vs non-scrolling?

 
 #include <stddef.h>
 
 #include "base/logging.h"
 #include "base/metrics/histogram_functions.h"
 #include "base/metrics/histogram_macros.h"
 #include "build/build_config.h"
 #include "components/rappor/public/rappor_utils.h"
 #include "content/browser/renderer_host/render_widget_host_delegate.h"
 #include "content/public/browser/content_browser_client.h"
@@ skipping 111 matching lines @@
                               base::HistogramBase::kUmaTargetedHistogramFlag) \
       ->Add((end.last_event_time - start.first_event_time).InMicroseconds());
 
 std::string LatencySourceEventTypeToInputModalityString(
     ui::SourceEventType type) {
   switch (type) {
     case ui::SourceEventType::WHEEL:
       return "Wheel";
     case ui::SourceEventType::TOUCH:
       return "Touch";
+    case ui::SourceEventType::KEY:
+      return "Key";
     default:
       return "";
   }
 }
 
 std::string WebInputEventTypeToInputModalityString(WebInputEvent::Type type) {
   if (type == blink::WebInputEvent::MouseWheel) {
     return "Wheel";
   } else if (WebInputEvent::isKeyboardEventType(type)) {
     return "Key";
@@ skipping 36 matching lines @@
 
   // This UMA metric tracks the time from when the original touch event is
   // created to when the scroll gesture results in final frame swap.
   for (size_t i = 0; i < original_component.event_count; i++) {
     UMA_HISTOGRAM_INPUT_LATENCY_HIGH_RESOLUTION_MICROSECONDS(
         "Event.Latency.TouchToScrollUpdateSwapBegin", original_component,
         gpu_swap_begin_component);
   }
 }
 
-void ComputeTouchAndWheelScrollLatencyHistograms(
+void ComputeEndToEndLatencyHistograms(
     RenderWidgetHostDelegate* render_widget_host_delegate,
     const ui::LatencyInfo::LatencyComponent& gpu_swap_begin_component,
     const ui::LatencyInfo::LatencyComponent& gpu_swap_end_component,
     int64_t latency_component_id,
     const ui::LatencyInfo& latency) {
   DCHECK(!latency.coalesced());
   if (latency.coalesced())
     return;
 
   LatencyInfo::LatencyComponent original_component;
@@ skipping 35 matching lines @@
     if (input_modality == "Touch") {
       UMA_HISTOGRAM_INPUT_LATENCY_HIGH_RESOLUTION_MICROSECONDS(
           "Event.Latency.ScrollUpdate.Touch.TimeToScrollUpdateSwapBegin2",
           original_component, gpu_swap_begin_component);
 
       RAPPOR_TOUCH_WHEEL_TO_SCROLL_LATENCY(
           render_widget_host_delegate,
           "Event.Latency.ScrollUpdate.Touch.TimeToScrollUpdateSwapBegin2",
           original_component, gpu_swap_begin_component);
     }
+  } else if (latency.FindLatency(ui::INPUT_EVENT_LATENCY_ORIGINAL_COMPONENT, 0,
+                                 &original_component)) {
+    if (input_modality == "Key") {
+      UMA_HISTOGRAM_INPUT_LATENCY_HIGH_RESOLUTION_MICROSECONDS(
+          "Event.Latency.EndToEnd.Key", original_component,
+          gpu_swap_begin_component);
+    }
   } else {
     // No original component found.
     return;
   }
 
   LatencyInfo::LatencyComponent rendering_scheduled_component;
   bool rendering_scheduled_on_main = latency.FindLatency(
       ui::INPUT_EVENT_LATENCY_RENDERING_SCHEDULED_MAIN_COMPONENT, 0,
       &rendering_scheduled_component);
   if (!rendering_scheduled_on_main) {
@@ skipping 96 matching lines @@
     WebInputEvent::Type type,
     int64_t latency_component_id,
     const LatencyInfo& latency,
     InputEventAckState ack_result) {
   // If this event was coalesced into another event, ignore it, as the event it
   // was coalesced into will reflect the full latency.
   if (latency.coalesced())
     return;
 
   if (type != blink::WebInputEvent::MouseWheel &&
-      !WebInputEvent::isTouchEventType(type)) {
+      !WebInputEvent::isTouchEventType(type) &&
+      !WebInputEvent::isKeyboardEventType(type)) {
     return;
   }
 
   LatencyInfo::LatencyComponent rwh_component;
   if (!latency.FindLatency(ui::INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT,
                            latency_component_id, &rwh_component)) {
     return;
   }
   DCHECK_EQ(rwh_component.event_count, 1u);
 
   LatencyInfo::LatencyComponent ui_component;
   if (latency.FindLatency(ui::INPUT_EVENT_LATENCY_UI_COMPONENT, 0,
                           &ui_component)) {
     DCHECK_EQ(ui_component.event_count, 1u);
     base::TimeDelta ui_delta =
         rwh_component.last_event_time - ui_component.first_event_time;
 
     if (type == blink::WebInputEvent::MouseWheel) {
       UMA_HISTOGRAM_CUSTOM_COUNTS("Event.Latency.Browser.WheelUI",
                                   ui_delta.InMicroseconds(), 1, 20000, 100);
-    } else {
-      DCHECK(WebInputEvent::isTouchEventType(type));
+    } else if (WebInputEvent::isTouchEventType(type)) {
       UMA_HISTOGRAM_CUSTOM_COUNTS("Event.Latency.Browser.TouchUI",
                                   ui_delta.InMicroseconds(), 1, 20000, 100);
+    } else if (WebInputEvent::isKeyboardEventType(type)) {

[mfomitchev, 2017/04/04 14:59:05]

Can we make this a DCHECK instead of an if?

[tdresser, 2017/05/01 15:49:21]

Added an else with NOTREACHED().

+      UMA_HISTOGRAM_CUSTOM_COUNTS("Event.Latency.Browser.KeyUI",
+                                  ui_delta.InMicroseconds(), 1, 20000, 50);
     }
   }
 
   // Both tap and scroll gestures depend on the disposition of the touch start
   // and the current touch. For touch start, touch_start_default_prevented_ ==

[mfomitchev, 2017/04/04 14:59:06]

Does the second sentence of this comment applies to key events as well? If so,
it would be good to update the comment. (I assume we don't need to cache
"prevented" value for key events, so touch_start_default_prevented_ would still
be touch-specific?)

[tdresser, 2017/05/01 15:49:21]

Sorry, a bit confused here. The second sentence starts "For touch start".

I've made this a bit more explicit in the first sentence. This is completely
touch specific.

   // (ack_result == INPUT_EVENT_ACK_STATE_CONSUMED).
   bool action_prevented = touch_start_default_prevented_ ||
                           ack_result == INPUT_EVENT_ACK_STATE_CONSUMED;

[tdresser, 2017/05/01 15:49:21]

Ack, this is still broken in the non-touch case. I'll fix this in a followup
patch. (crbug.com/717017)

 
   std::string event_name = WebInputEvent::GetName(type);
+  if (WebInputEvent::isKeyboardEventType(type))
+    event_name = "KeyEvent";
 
   std::string default_action_status =
       action_prevented ? "DefaultPrevented" : "DefaultAllowed";
 
   LatencyInfo::LatencyComponent main_component;
   if (latency.FindLatency(ui::INPUT_EVENT_LATENCY_RENDERER_MAIN_COMPONENT, 0,
                           &main_component)) {
     DCHECK_EQ(main_component.event_count, 1u);
     if (!multi_finger_gesture_) {

[mfomitchev, 2017/04/04 14:59:05]

Is it possible that a stale multi_finger_gesture_ is cached and subsequently
impacts key events and mouse wheel events? Even if not - it seems like it is
still possible an in-progress multitouch would impact key/mouse events that are
happening at the same time.

[tdresser, 2017/05/01 15:49:21]

Fixed in other patch, with follow up work here: crbug.com/717017.

       UMA_HISTOGRAM_INPUT_LATENCY_MILLISECONDS(
           "Event.Latency.QueueingTime." + event_name + default_action_status,
           rwh_component, main_component);
     }
   }
 
   LatencyInfo::LatencyComponent acked_component;
   if (latency.FindLatency(ui::INPUT_EVENT_LATENCY_ACK_RWH_COMPONENT, 0,
                           &acked_component)) {
     DCHECK_EQ(acked_component.event_count, 1u);
@@ skipping 42 matching lines @@
         0,
         0,
         timestamp_original,
         1);
   }
 
   latency->AddLatencyNumberWithTraceName(
       ui::INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT, latency_component_id_,
       ++last_event_id_, WebInputEvent::GetName(event.type()));
 
   UpdateLatencyCoordinates(event, device_scale_factor_, latency);

[mfomitchev, 2017/04/04 14:59:06]

Does this make sense for key events?

[tdresser, 2017/05/01 15:49:21]

Removed:
https://codereview.chromium.org/2804693002#

 
   if (event.type() == blink::WebInputEvent::GestureScrollBegin) {
     has_seen_first_gesture_scroll_update_ = false;
   } else if (event.type() == blink::WebInputEvent::GestureScrollUpdate) {
     // Make a copy of the INPUT_EVENT_LATENCY_ORIGINAL_COMPONENT with a
     // different name INPUT_EVENT_LATENCY_SCROLL_UPDATE_ORIGINAL_COMPONENT.
     // So we can track the latency specifically for scroll update events.
     LatencyInfo::LatencyComponent original_component;
     if (latency->FindLatency(ui::INPUT_EVENT_LATENCY_ORIGINAL_COMPONENT, 0,
                              &original_component)) {
@@ skipping 77 matching lines @@
       UMA_HISTOGRAM_TIMES("MPArch.RWH_TabSwitchPaintDuration", delta);
     }
   }
 
   if (!latency.FindLatency(ui::INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT,
                            latency_component_id_, nullptr)) {
     return;
   }
 
   ui::SourceEventType source_event_type = latency.source_event_type();
+
   if (source_event_type == ui::SourceEventType::WHEEL ||
-      source_event_type == ui::SourceEventType::TOUCH) {
-    ComputeTouchAndWheelScrollLatencyHistograms(
+      source_event_type == ui::SourceEventType::TOUCH ||
+      source_event_type == ui::SourceEventType::KEY) {
+    ComputeEndToEndLatencyHistograms(
         render_widget_host_delegate_, gpu_swap_begin_component,
         gpu_swap_end_component, latency_component_id_, latency);
   }
 
   // Compute the old scroll update latency metrics. They are exclusively
   // calculated for touch scrolls, and will be deprecated on M56.
   // (https://crbug.com/649754)
   LatencyInfo::LatencyComponent mouse_wheel_scroll_update_component;
   if (!latency.FindLatency(
           ui::INPUT_EVENT_LATENCY_GENERATE_SCROLL_UPDATE_FROM_MOUSE_WHEEL, 0,
           &mouse_wheel_scroll_update_component)) {
     ComputeScrollLatencyHistograms(gpu_swap_begin_component,
                                    gpu_swap_end_component,
                                    latency_component_id_, latency);
   }
 }
 
 void RenderWidgetHostLatencyTracker::SetDelegate(
     RenderWidgetHostDelegate* delegate) {
   render_widget_host_delegate_ = delegate;
 }
 
 }  // namespace content