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

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;
     }
   }
 }
 
+// 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,
     const ui::LatencyInfo& latency) {
   DCHECK(!swap_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(
+      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(
                  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(
+    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
 // 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 73 matching lines @@
   }
 }
 
 void RenderWidgetHostLatencyTracker::OnInputEventAck(
     const blink::WebInputEvent& event,
     LatencyInfo* latency) {
   DCHECK(latency);
 
   // 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) {
       latency->AddLatencyNumber(
           ui::INPUT_EVENT_LATENCY_TERMINATED_GESTURE_COMPONENT, 0, 0);
       // TODO(jdduke): Consider exposing histograms for gesture event types.
     }
     return;
   }
 
@@ skipping 83 matching lines @@
   // 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