Track input latency for both begin and end of GPU swap in UMAs

content/browser/renderer_host/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/render_widget_host_latency_tracker.h"
 
 #include "base/logging.h"
 #include "base/metrics/histogram.h"
 #include "content/browser/renderer_host/render_widget_host_impl.h"
 
@@ skipping 117 matching lines @@
             "Event.Latency.Browser.TouchAcked",
             acked_delta.InMicroseconds(), 1, 1000000, 100);
         break;
       default:
         NOTREACHED();
         break;
     }
   }
 }
 
+// Touch to scroll latency than is mostly under 1 second.
+#define UMA_HISTOGRAM_TOUCH_TO_SCROLL_LATENCY(name, start, end)               \
+  UMA_HISTOGRAM_CUSTOM_COUNTS(                                                \
+      name, (start.event_time - end.event_time).InMicroseconds(), 1, 1000000, \
+      100)

[Yufeng Shen (Slow to review), 2015/04/17 22:06:22]

please use (end - start) to make it less confusing.

[brianderson, 2015/04/17 22:21:25]

D'oh. Done.

+
 // Long scroll latency component that is mostly under 200ms.
 #define UMA_HISTOGRAM_SCROLL_LATENCY_LONG(name, start, end)        \
   UMA_HISTOGRAM_CUSTOM_COUNTS(                                     \
     name,                                                          \
     (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)
 
 void ComputeScrollLatencyHistograms(
-    const LatencyInfo::LatencyComponent& gpu_swap_component,
+    const LatencyInfo::LatencyComponent& gpu_swap_begin_component,
+    const LatencyInfo::LatencyComponent& gpu_swap_end_component,
     int64 latency_component_id,
     const LatencyInfo& latency) {
-  DCHECK(!gpu_swap_component.event_time.is_null());
+  DCHECK(!gpu_swap_begin_component.event_time.is_null());
+  DCHECK(!gpu_swap_end_component.event_time.is_null());
   LatencyInfo::LatencyComponent first_original_component, original_component;
   if (latency.FindLatency(
           ui::INPUT_EVENT_LATENCY_FIRST_SCROLL_UPDATE_ORIGINAL_COMPONENT,
           latency_component_id, &first_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 < first_original_component.event_count; i++) {
-      UMA_HISTOGRAM_CUSTOM_COUNTS(
-          "Event.Latency.TouchToFirstScrollUpdateSwap",
-          (gpu_swap_component.event_time - first_original_component.event_time)
-              .InMicroseconds(),
-          1, 1000000, 100);
+      UMA_HISTOGRAM_TOUCH_TO_SCROLL_LATENCY(
+          "Event.Latency.TouchToFirstScrollUpdateSwapBegin",
+          gpu_swap_begin_component, first_original_component);
+      // TODO(brianderson): Remove this version once we have enough overlapping
+      // data with the metric above.
+      UMA_HISTOGRAM_TOUCH_TO_SCROLL_LATENCY(
+          "Event.Latency.TouchToFirstScrollUpdateSwap", gpu_swap_end_component,
+          first_original_component);
     }
     original_component = first_original_component;
   } else if (!latency.FindLatency(
                  ui::INPUT_EVENT_LATENCY_SCROLL_UPDATE_ORIGINAL_COMPONENT,
                  latency_component_id, &original_component)) {
     return;
   }
 
   // This UMA metric tracks the time from when the original touch event is
   // created (averaged if there are multiple) to when the scroll gesture
   // results in final frame swap.
   for (size_t i = 0; i < original_component.event_count; i++) {
-    UMA_HISTOGRAM_CUSTOM_COUNTS(
-        "Event.Latency.TouchToScrollUpdateSwap",
-        (gpu_swap_component.event_time - original_component.event_time)
-            .InMicroseconds(),
-        1, 1000000, 100);
+    UMA_HISTOGRAM_TOUCH_TO_SCROLL_LATENCY(
+        "Event.Latency.TouchToScrollUpdateSwapBegin", gpu_swap_begin_component,
+        original_component);
+    // TODO(brianderson): Remove this version once we have enough overlapping
+    // data with the metric above.
+    UMA_HISTOGRAM_TOUCH_TO_SCROLL_LATENCY(
+        "Event.Latency.TouchToScrollUpdateSwap", gpu_swap_end_component,
+        original_component);
   }
 
   // TODO(miletus): Add validation for making sure the following components
   // are present and their event times are legit.
   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 33 matching lines @@
           ui::INPUT_EVENT_BROWSER_RECEIVED_RENDERER_SWAP_COMPONENT,
           0, &browser_received_swap_component))
     return;
 
   UMA_HISTOGRAM_SCROLL_LATENCY_SHORT(
       "Event.Latency.ScrollUpdate.RendererSwapToBrowserNotified",
       renderer_swap_component, browser_received_swap_component);
 
   UMA_HISTOGRAM_SCROLL_LATENCY_LONG(
       "Event.Latency.ScrollUpdate.BrowserNotifiedToBeforeGpuSwap",
-      browser_received_swap_component, gpu_swap_component);
-
-  LatencyInfo::LatencyComponent gpu_swap_ack_component;
-  if (!latency.FindLatency(
-          ui::INPUT_EVENT_LATENCY_TERMINATED_FRAME_SWAP_COMPONENT, 0,
-          &gpu_swap_ack_component))
-    return;
+      browser_received_swap_component, gpu_swap_begin_component);
 
   UMA_HISTOGRAM_SCROLL_LATENCY_SHORT("Event.Latency.ScrollUpdate.GpuSwap",
-                                     gpu_swap_component,
-                                     gpu_swap_ack_component);
+                                     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 latency_component_id) {
   LatencyInfo::LatencyMap new_components;
   auto lc = latency->latency_components.begin();
   while (lc != latency->latency_components.end()) {
@@ skipping 135 matching lines @@
   DCHECK(latencies);
   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) {
-  LatencyInfo::LatencyComponent gpu_swap_component;
-  if (!latency.FindLatency(ui::INPUT_EVENT_GPU_SWAP_BUFFER_COMPONENT, 0,
-                           &gpu_swap_component)) {
+  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_component.event_time - tab_switch_component.event_time;
+        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_component, latency_component_id_,
+  ComputeScrollLatencyHistograms(gpu_swap_begin_component,
+                                 gpu_swap_end_component, latency_component_id_,
                                  latency);
 
   LatencyInfo::LatencyComponent browser_swap_component;
   if (latency.FindLatency(
           ui::INPUT_EVENT_BROWSER_RECEIVED_RENDERER_SWAP_COMPONENT, 0,
           &browser_swap_component)) {
     base::TimeDelta delta =
-        gpu_swap_component.event_time - browser_swap_component.event_time;
+        gpu_swap_begin_component.event_time - browser_swap_component.event_time;
     browser_composite_latency_history_.InsertSample(delta);
   }
 }
 
 base::TimeDelta
 RenderWidgetHostLatencyTracker::GetEstimatedBrowserCompositeTime() const {
   // TODO(brianderson): Remove lower bound on estimate once we're sure it won't
   // cause regressions.
   return std::max(
       browser_composite_latency_history_.Percentile(
           kBrowserCompositeLatencyEstimationPercentile) *
           kBrowserCompositeLatencyEstimationSlack,
       base::TimeDelta::FromMicroseconds(
           (1.0f * base::Time::kMicrosecondsPerSecond) / (3.0f * 60)));
 }
 
 }  // namespace content