WIP: Plumbing input event latency reporting through Mus GPU.

components/latency_tracker/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 "components/latency_tracker/latency_tracker.h"
+
+#include "base/metrics/histogram_functions.h"
+#include "base/metrics/histogram_macros.h"
+
+using ui::LatencyInfo;
+
+// TODO: SHould we have separate classes with state for browser and GPU
+// callbacks? Or perhaps stateless?
+
+namespace latency_tracker {
+namespace {
+
+// 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);
+
+// Event latency that is mostly under 1 second. We should only use 100 buckets
+// when needed.
+#define UMA_HISTOGRAM_INPUT_LATENCY_HIGH_RESOLUTION_MICROSECONDS(name, start, \
+                                                                 end)         \
+  CONFIRM_VALID_TIMING(start, end)                                            \
+  base::UmaHistogramCustomCounts(                                             \
+      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)                                            \
+  base::Histogram::FactoryGet(name, 1000, 200000, 50,                         \
+                              base::HistogramBase::kUmaTargetedHistogramFlag) \
+      ->Add((end.last_event_time - start.first_event_time).InMicroseconds());
+
+// 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)                                            \
+  base::Histogram::FactoryGet(name, 1, 50000, 50,                             \
+                              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";
+    default:
+      return "";
+  }
+}
+
+void ComputeScrollLatencyHistograms(
+    const LatencyInfo::LatencyComponent& gpu_swap_begin_component,
+    const LatencyInfo::LatencyComponent& gpu_swap_end_component,
+    const LatencyInfo& latency,
+    bool is_running_navigation_hint_task) {
+  DCHECK(!latency.coalesced());
+  if (latency.coalesced())
+    return;
+
+  DCHECK(!gpu_swap_begin_component.event_time.is_null());
+  DCHECK(!gpu_swap_end_component.event_time.is_null());
+  LatencyInfo::LatencyComponent original_component;
+  if (latency.FindLatency(
+          ui::INPUT_EVENT_LATENCY_FIRST_SCROLL_UPDATE_ORIGINAL_COMPONENT,
+          &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 event.
+    for (size_t i = 0; i < original_component.event_count; i++) {
+      UMA_HISTOGRAM_INPUT_LATENCY_HIGH_RESOLUTION_MICROSECONDS(
+          "Event.Latency.TouchToFirstScrollUpdateSwapBegin",
+          original_component, gpu_swap_begin_component);
+    }
+    // TODO(horo): IsRunningNavigationHintTask UMAs are only for
+    // SpeculativeLaunchServiceWorker experimentation. So remove this UMA when
+    // the experimentation finished (crbug.com/638827).
+    if (is_running_navigation_hint_task) {
+      for (size_t i = 0; i < original_component.event_count; i++) {
+        UMA_HISTOGRAM_INPUT_LATENCY_HIGH_RESOLUTION_MICROSECONDS(
+            "Event.Latency.TouchToFirstScrollUpdateSwapBegin_"
+            "IsRunningNavigationHintTask",
+            original_component, gpu_swap_begin_component);
+      }
+    }
+  } else if (!latency.FindLatency(
+                 ui::INPUT_EVENT_LATENCY_SCROLL_UPDATE_ORIGINAL_COMPONENT,
+                 &original_component)) {
+    return;
+  }
+
+  // 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);
+  }
+  // TODO(horo): IsRunningNavigationHintTask UMAs are only for
+  // SpeculativeLaunchServiceWorker experimentation. So remove this UMA when
+  // the experimentation finished (crbug.com/638827).
+  if (is_running_navigation_hint_task) {
+    for (size_t i = 0; i < original_component.event_count; i++) {
+      UMA_HISTOGRAM_INPUT_LATENCY_HIGH_RESOLUTION_MICROSECONDS(
+          "Event.Latency.TouchToScrollUpdateSwapBegin_"
+          "IsRunningNavigationHintTask",
+          original_component, gpu_swap_begin_component);
+    }
+  }
+}
+
+}  // namespace
+
+void LatencyTracker::OnGpuSwapBufersCompleted(

[Fady Samuel, 2017/03/23 17:24:37]

This should probably be on CompositorFrameActivated, and this should be called
AFTER activation.

+    const LatencyInfo& latency,
+    bool is_running_navigation_hint_task) {
+  LOG(ERROR) << "LatencyTracker::OnGpuSwapBufersCompleted";
+  int i = 0;
+  for (const auto& lc : latency.latency_components()) {
+    ++i;
+    LOG(ERROR) << "Component " << i << ": "
+        << ui::GetComponentName(lc.first.first);
+  }
+
+  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, &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,
+                           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(
+        gpu_swap_begin_component,
+        gpu_swap_end_component, 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, is_running_navigation_hint_task);
+  }
+}
+
+void LatencyTracker::ReportRapporScrollLatency(
+    const std::string& name,
+    const LatencyInfo::LatencyComponent& start_component,
+    const LatencyInfo::LatencyComponent& end_component) {}
+
+void LatencyTracker::ComputeTouchAndWheelScrollLatencyHistograms(
+    const ui::LatencyInfo::LatencyComponent& gpu_swap_begin_component,
+    const ui::LatencyInfo::LatencyComponent& gpu_swap_end_component,
+    const ui::LatencyInfo& latency) {
+  DCHECK(!latency.coalesced());
+  if (latency.coalesced())
+    return;
+
+  LatencyInfo::LatencyComponent original_component;
+  std::string scroll_name = "ScrollUpdate";
+
+  const std::string input_modality =
+      LatencySourceEventTypeToInputModalityString(latency.source_event_type());
+
+  if (latency.FindLatency(
+          ui::INPUT_EVENT_LATENCY_FIRST_SCROLL_UPDATE_ORIGINAL_COMPONENT,
+          &original_component)) {
+    scroll_name = "ScrollBegin";
+    // 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_INPUT_LATENCY_HIGH_RESOLUTION_MICROSECONDS(
+        "Event.Latency.ScrollBegin." + input_modality +
+            ".TimeToScrollUpdateSwapBegin2",
+        original_component, gpu_swap_begin_component);
+
+    ReportRapporScrollLatency(
+        "Event.Latency.ScrollBegin." + input_modality +
+            ".TimeToScrollUpdateSwapBegin2",
+        original_component, gpu_swap_begin_component);
+
+    // TODO(lanwei): Will remove them when M56 is stable, see
+    // https://crbug.com/669618.
+    UMA_HISTOGRAM_INPUT_LATENCY_HIGH_RESOLUTION_MICROSECONDS(
+        "Event.Latency.ScrollUpdate." + input_modality +
+            ".TimeToFirstScrollUpdateSwapBegin2",
+        original_component, gpu_swap_begin_component);
+  } else if (latency.FindLatency(
+                 ui::INPUT_EVENT_LATENCY_SCROLL_UPDATE_ORIGINAL_COMPONENT,
+                 &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.
+    // First scroll events are excluded from this metric.
+    if (input_modality == "Touch") {
+      UMA_HISTOGRAM_INPUT_LATENCY_HIGH_RESOLUTION_MICROSECONDS(
+          "Event.Latency.ScrollUpdate.Touch.TimeToScrollUpdateSwapBegin2",
+          original_component, gpu_swap_begin_component);
+
+      ReportRapporScrollLatency(
+          "Event.Latency.ScrollUpdate.Touch.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;
+  }
+
+  const std::string thread_name = rendering_scheduled_on_main ? "Main" : "Impl";
+
+  UMA_HISTOGRAM_SCROLL_LATENCY_LONG_2(
+      "Event.Latency." + scroll_name + "." + input_modality +
+          ".TimeToHandled2_" + thread_name,
+      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;
+
+  UMA_HISTOGRAM_SCROLL_LATENCY_LONG_2(
+      "Event.Latency." + scroll_name + "." + input_modality +
+          ".HandledToRendererSwap2_" + thread_name,
+      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." + scroll_name + "." + input_modality +
+          ".RendererSwapToBrowserNotified2",
+      renderer_swap_component, browser_received_swap_component);
+
+  UMA_HISTOGRAM_SCROLL_LATENCY_LONG_2(
+      "Event.Latency." + scroll_name + "." + input_modality +
+          ".BrowserNotifiedToBeforeGpuSwap2",
+      browser_received_swap_component, gpu_swap_begin_component);
+
+  UMA_HISTOGRAM_SCROLL_LATENCY_SHORT_2(
+      "Event.Latency." + scroll_name + "." + input_modality + ".GpuSwap2",
+      gpu_swap_begin_component, gpu_swap_end_component);
+}
+}  // namespace content