Break down end-to-end scroll update latency UMA metrics

content/browser/renderer_host/render_widget_host_latency_tracker.cc

Index: content/browser/renderer_host/render_widget_host_latency_tracker.cc
diff --git a/content/browser/renderer_host/render_widget_host_latency_tracker.cc b/content/browser/renderer_host/render_widget_host_latency_tracker.cc
index 2d738c491910c4d429709da26d4ecd6193f9105b..f5bdd390e7662b3508171ba15e34427a32956016 100644
--- a/content/browser/renderer_host/render_widget_host_latency_tracker.cc
+++ b/content/browser/renderer_host/render_widget_host_latency_tracker.cc
@@ -135,6 +135,13 @@ void ComputeInputLatencyHistograms(WebInputEvent::Type type,
   }
 }
 
+// Scroll latency is mostly under 1000ms.

[Alexei Svitkine (slow), 2015/02/13 16:16:33]

I'm not convinced that these macro params are the best.

When I look at an existing histogram using these:

https://uma.googleplex.com/histograms/?dayCount=1&endDate=02-12-2015&version=...

It looks like most of the interesting data happens around 5ms - 200ms range.

At which point, most of the bucket sizes are several ms in size.

Which doesn't seem any better than what you get with just a
UMA_HISTOGRAM_TIMES() macro, e.g.:

https://uma.googleplex.com/histograms/?dayCount=1&endDate=02-12-2015&version=...

But you can probably do even better by just customizing UMA_HISTOGRAM_TIMES()
and logging in ms.

For example, you can set it's max to be 1s like you do here, which will give you
smaller bucket sizes. Or increase the number of buckets (default is 50) -
although I'm hoping you actually don't need the full 100 buckets. The more
buckets there are, the more space is used in logs and bandwidth to transmit - so
it should only be increased if there's a real benefit.

So the question is, what kind of granularity you're looking for? Perhaps the
default UMA_HISTOGRAM_TIMES buckets are sufficient?

[Yufeng Shen (Slow to review), 2015/02/17 20:37:21]

Thanks Alexei for the suggestions.

Here is what's in the new patchset:
1) The UMA range/bucket size for the existing metrics remain the same so we
don't lose the history data.
2) For the new metrics added, we have some to be collected with the long range
that's between under 200ms and 50 buckets. And the others collected with the
short range that's under 50ms and 50 buckets. This should improve
the granularity and collecting overhead.

PTAL, thanks. 

+#define UMA_HISTOGRAM_SCROLL_LATENCY(name, start, end)        \
+  UMA_HISTOGRAM_CUSTOM_COUNTS(                                \
+    name,                                                     \
+    (end.event_time - start.event_time).InMicroseconds(),     \
+    1, 1000000, 100)
+
 void ComputeScrollLatencyHistograms(
     const LatencyInfo::LatencyComponent& swap_component,
     int64 latency_component_id,
@@ -148,11 +155,9 @@ void ComputeScrollLatencyHistograms(
     // 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(
+      UMA_HISTOGRAM_SCROLL_LATENCY(
           "Event.Latency.TouchToFirstScrollUpdateSwap",
-          (swap_component.event_time - first_original_component.event_time)
-              .InMicroseconds(),
-          1, 1000000, 100);
+          first_original_component, swap_component);
     }
     original_component = first_original_component;
   } else if (!latency.FindLatency(
@@ -165,12 +170,69 @@ void ComputeScrollLatencyHistograms(
   // 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(
+    UMA_HISTOGRAM_SCROLL_LATENCY(
         "Event.Latency.TouchToScrollUpdateSwap",
-        (swap_component.event_time - original_component.event_time)
-            .InMicroseconds(),
-        1, 1000000, 100);
+        original_component, swap_component);
+  }
+
+  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(
+        "Event.Latency.ScrollUpdate.TouchToHandled_Main",
+        original_component, rendering_scheduled_component);
+  } else {
+    UMA_HISTOGRAM_SCROLL_LATENCY(
+        "Event.Latency.ScrollUpdate.TouchToHandled_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(
+        "Event.Latency.ScrollUpdate.HandledToRendererSwap_Main",
+        rendering_scheduled_component, renderer_swap_component);
+  } else {
+    UMA_HISTOGRAM_SCROLL_LATENCY(
+        "Event.Latency.ScrollUpdate.HandledToRendererSwap_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(
+      "Event.Latency.ScrollUpdate.RendererSwapToBrowserNotified",
+      renderer_swap_component, browser_received_swap_component);
+
+  LatencyInfo::LatencyComponent gpu_swap_component;
+  if (!latency.FindLatency(ui::INPUT_EVENT_GPU_SWAP_BUFFER_COMPONENT,
+                           0, &gpu_swap_component))
+    return;
+
+  UMA_HISTOGRAM_SCROLL_LATENCY(
+      "Event.Latency.ScrollUpdate.BrowserNotifiedToBeforeGpuSwap",
+      browser_received_swap_component, gpu_swap_component);
+
+  UMA_HISTOGRAM_SCROLL_LATENCY("Event.Latency.ScrollUpdate.GpuSwap",
+                               gpu_swap_component, swap_component);
 }
 
 // LatencyComponents generated in the renderer must have component IDs
@@ -264,7 +326,9 @@ void RenderWidgetHostLatencyTracker::OnInputEventAck(
 
   // Latency ends when it is acked but does not cause render scheduling.
   bool rendering_scheduled = latency->FindLatency(
-      ui::INPUT_EVENT_LATENCY_RENDERING_SCHEDULED_COMPONENT, 0, NULL);
+      ui::INPUT_EVENT_LATENCY_RENDERING_SCHEDULED_MAIN_COMPONENT, 0, nullptr);
+  rendering_scheduled |= latency->FindLatency(
+      ui::INPUT_EVENT_LATENCY_RENDERING_SCHEDULED_IMPL_COMPONENT, 0, nullptr);
 
   if (WebInputEvent::isGestureEventType(event.type)) {
     if (!rendering_scheduled) {