New scroll latency metrics added for touch and wheel.

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"
 
 #include <stddef.h>
 
 #include "base/logging.h"
 #include "base/metrics/histogram_macros.h"
@@ skipping 74 matching lines @@
     (end.event_time - start.event_time).InMicroseconds(),          \
     1000, 200000, 50)
 
 // Short scroll latency component that is mostly under 50ms.
 #define UMA_HISTOGRAM_SCROLL_LATENCY_SHORT(name, start, end)       \
   UMA_HISTOGRAM_CUSTOM_COUNTS(                                     \
     name,                                                          \
     (end.event_time - start.event_time).InMicroseconds(),          \
     1, 50000, 50)
 
+// Check valid timing for start and end latency components.
+#define CONFIRM_VALID_TIMING(start, end)     \
+  DCHECK(!start.first_event_time.is_null()); \
+  DCHECK(!end.last_event_time.is_null());    \
+  DCHECK_GE(end.last_event_time, start.first_event_time);
+
+// Touch/wheel to scroll latency that is mostly under 1 second.
+#define UMA_HISTOGRAM_TOUCH_WHEEL_TO_SCROLL_LATENCY(name, start, end)        \
+  CONFIRM_VALID_TIMING(start, end)                                           \
+  UMA_HISTOGRAM_CUSTOM_COUNTS(                                               \
+      name, (end.last_event_time - start.first_event_time).InMicroseconds(), \
+      1, 1000000, 100)
+
+// Long touch/wheel scroll latency component that is mostly under 200ms.
+#define UMA_HISTOGRAM_SCROLL_LATENCY_LONG_2(name, start, end)                \
+  CONFIRM_VALID_TIMING(start, end)                                           \
+  UMA_HISTOGRAM_CUSTOM_COUNTS(                                               \
+      name, (end.last_event_time - start.first_event_time).InMicroseconds(), \
+      1000, 200000, 50)
+
+// Short touch/wheel scroll latency component that is mostly under 50ms.
+#define UMA_HISTOGRAM_SCROLL_LATENCY_SHORT_2(name, start, end)               \
+  CONFIRM_VALID_TIMING(start, end)                                           \
+  UMA_HISTOGRAM_CUSTOM_COUNTS(                                               \
+      name, (end.last_event_time - start.first_event_time).InMicroseconds(), \
+      1, 50000, 50)
+
 void ComputeScrollLatencyHistograms(
     const LatencyInfo::LatencyComponent& gpu_swap_begin_component,
     const LatencyInfo::LatencyComponent& gpu_swap_end_component,
     int64_t latency_component_id,
     const LatencyInfo& latency,
     bool is_running_navigation_hint_task) {
   DCHECK(!latency.coalesced());
   if (latency.coalesced())
     return;
 
@@ skipping 98 matching lines @@
 
   UMA_HISTOGRAM_SCROLL_LATENCY_LONG(
       "Event.Latency.ScrollUpdate.BrowserNotifiedToBeforeGpuSwap",
       browser_received_swap_component, gpu_swap_begin_component);
 
   UMA_HISTOGRAM_SCROLL_LATENCY_SHORT("Event.Latency.ScrollUpdate.GpuSwap",
                                      gpu_swap_begin_component,
                                      gpu_swap_end_component);
 }
 
+void ComputeTouchAndWheelScrollLatencyHistograms(
+    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,
+    const std::string event_type_name) {
+  DCHECK(!latency.coalesced());
+  if (latency.coalesced())
+    return;
+
+  LatencyInfo::LatencyComponent original_component;
+  if (latency.FindLatency(
+          ui::INPUT_EVENT_LATENCY_FIRST_SCROLL_UPDATE_ORIGINAL_COMPONENT,
+          latency_component_id, &original_component)) {
+    // This UMA metric tracks the time between the final frame swap for the
+    // first scroll event in a sequence and the original timestamp of that
+    // scroll event's underlying touch/wheel event.
+    UMA_HISTOGRAM_TOUCH_WHEEL_TO_SCROLL_LATENCY(
+        "Event.Latency." + event_type_name +
+            ".TimeToFirstScrollUpdateSwapBegin2",
+        original_component, gpu_swap_begin_component);
+  } else if (latency.FindLatency(
+                 ui::INPUT_EVENT_LATENCY_SCROLL_UPDATE_ORIGINAL_COMPONENT,
+                 latency_component_id, &original_component)) {
+    // This UMA metric tracks the time from when the original touch event is
+    // created to when the scroll gesture results in final frame swap.

[tdresser, 2016/09/30 17:16:38]

Clarify that this excludes the first scroll.

[sahel, 2016/10/04 14:22:25]

Done.

+    if (event_type_name == "Touch") {
+      UMA_HISTOGRAM_TOUCH_WHEEL_TO_SCROLL_LATENCY(
+          "Event.Latency." + event_type_name + ".TimeToScrollUpdateSwapBegin2",
+          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) {
+    if (!latency.FindLatency(
+            ui::INPUT_EVENT_LATENCY_RENDERING_SCHEDULED_IMPL_COMPONENT, 0,
+            &rendering_scheduled_component))
+      return;
+  }
+
+  if (rendering_scheduled_on_main) {
+    UMA_HISTOGRAM_SCROLL_LATENCY_LONG_2(
+        "Event.Latency.ScrollUpdate." + event_type_name +
+            ".TimeToHandled2_Main",
+        original_component, rendering_scheduled_component);
+  } else {
+    UMA_HISTOGRAM_SCROLL_LATENCY_LONG_2(
+        "Event.Latency.ScrollUpdate." + event_type_name +
+            ".TimeToHandled2_Impl",
+        original_component, rendering_scheduled_component);
+  }
+
+  LatencyInfo::LatencyComponent renderer_swap_component;
+  if (!latency.FindLatency(ui::INPUT_EVENT_LATENCY_RENDERER_SWAP_COMPONENT, 0,
+                           &renderer_swap_component))
+    return;
+
+  if (rendering_scheduled_on_main) {
+    UMA_HISTOGRAM_SCROLL_LATENCY_LONG_2(
+        "Event.Latency.ScrollUpdate." + event_type_name +

[Steven Holte, 2016/09/30 22:10:05]

Computing names like this doesn't work when using UMA_HISTOGRAM_CUSTOM_COUNTS
macro.
This macro uses a static variable to keep a pointer to the Histogram object,
which won't get recomputed when you hit this with different names.

You need to either have a separate macro invocation for each name you are using,
or use FactoryGet(args)->Add(sample) directly.

[sahel, 2016/10/04 14:22:26]

Done.

+            ".HandledToRendererSwap2_Main",
+        rendering_scheduled_component, renderer_swap_component);
+  } else {
+    UMA_HISTOGRAM_SCROLL_LATENCY_LONG_2(
+        "Event.Latency.ScrollUpdate." + event_type_name +
+            ".HandledToRendererSwap2_Impl",
+        rendering_scheduled_component, renderer_swap_component);
+  }
+
+  LatencyInfo::LatencyComponent browser_received_swap_component;
+  if (!latency.FindLatency(
+          ui::INPUT_EVENT_BROWSER_RECEIVED_RENDERER_SWAP_COMPONENT, 0,
+          &browser_received_swap_component))
+    return;
+
+  UMA_HISTOGRAM_SCROLL_LATENCY_SHORT_2(
+      "Event.Latency.ScrollUpdate." + event_type_name +
+          ".RendererSwapToBrowserNotified2",
+      renderer_swap_component, browser_received_swap_component);
+
+  UMA_HISTOGRAM_SCROLL_LATENCY_LONG_2(
+      "Event.Latency.ScrollUpdate." + event_type_name +
+          ".BrowserNotifiedToBeforeGpuSwap2",
+      browser_received_swap_component, gpu_swap_begin_component);
+
+  UMA_HISTOGRAM_SCROLL_LATENCY_SHORT_2(
+      "Event.Latency.ScrollUpdate." + event_type_name + ".GpuSwap2",
+      gpu_swap_begin_component, gpu_swap_end_component);
+}
 // LatencyComponents generated in the renderer must have component IDs
 // provided to them by the browser process. This function adds the correct
 // component ID where necessary.
 void AddLatencyInfoComponentIds(LatencyInfo* latency,
                                 int64_t latency_component_id) {
   std::vector<std::pair<ui::LatencyComponentType, int64_t>> new_components_key;
   std::vector<LatencyInfo::LatencyComponent> new_components_value;
   for (const auto& lc : latency->latency_components()) {
     ui::LatencyComponentType component_type = lc.first.first;
     if (component_type == ui::WINDOW_SNAPSHOT_FRAME_NUMBER_COMPONENT) {
@@ skipping 325 matching lines @@
   for (LatencyInfo& latency : *latencies) {
     AddLatencyInfoComponentIds(&latency, latency_component_id_);
     latency.AddLatencyNumber(
         ui::INPUT_EVENT_BROWSER_RECEIVED_RENDERER_SWAP_COMPONENT, 0, 0);
   }
 }
 
 void RenderWidgetHostLatencyTracker::OnFrameSwapped(
     const LatencyInfo& latency,
     bool is_running_navigation_hint_task) {
-  // Don't report frame latency on wheel events. Previously they were only
-  // reported on touch metrics and we need to be consistent across reporting
-  // metrics.
-  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)) {
-    return;
-  }
 
   LatencyInfo::LatencyComponent gpu_swap_end_component;
   if (!latency.FindLatency(
           ui::INPUT_EVENT_LATENCY_TERMINATED_FRAME_SWAP_COMPONENT, 0,
           &gpu_swap_end_component)) {
     return;
   }
 
   LatencyInfo::LatencyComponent gpu_swap_begin_component;
   if (!latency.FindLatency(ui::INPUT_EVENT_GPU_SWAP_BUFFER_COMPONENT, 0,
                            &gpu_swap_begin_component)) {
     return;
   }
 
   LatencyInfo::LatencyComponent tab_switch_component;
   if (latency.FindLatency(ui::TAB_SHOW_COMPONENT, latency_component_id_,
                           &tab_switch_component)) {
     base::TimeDelta delta =
         gpu_swap_end_component.event_time - tab_switch_component.event_time;
     for (size_t i = 0; i < tab_switch_component.event_count; i++) {
       UMA_HISTOGRAM_TIMES("MPArch.RWH_TabSwitchPaintDuration", delta);
     }
   }
 
   if (!latency.FindLatency(ui::INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT,
                            latency_component_id_, nullptr)) {
     return;
   }
 
-  ComputeScrollLatencyHistograms(gpu_swap_begin_component,
-                                 gpu_swap_end_component, latency_component_id_,
-                                 latency, is_running_navigation_hint_task);
+  // 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, is_running_navigation_hint_task);
+  }

[tdresser, 2016/09/30 17:16:38]

Let's move the deprecated metrics after the more current metrics.

I think that'll just make the scope of the above comment a bit clearer.

[sahel, 2016/10/04 14:22:26]

Done.

+
+  ui::SourceEventType source_event_type = latency.source_event_type();
+  if (source_event_type != ui::SourceEventType::WHEEL &&
+      source_event_type != ui::SourceEventType::TOUCH) {
+    return;
+  }
+
+  ComputeTouchAndWheelScrollLatencyHistograms(
+      gpu_swap_begin_component, gpu_swap_end_component, latency_component_id_,
+      latency,
+      source_event_type == ui::SourceEventType::WHEEL ? "Wheel" : "Touch");
 }
 
 }  // namespace content