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..82e5de220e32e79b54d4c3985789940ea7300f71 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,20 @@ void ComputeInputLatencyHistograms(WebInputEvent::Type type,
   }
 }
 
+// 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& swap_component,
     int64 latency_component_id,
@@ -171,6 +185,77 @@ void ComputeScrollLatencyHistograms(
             .InMicroseconds(),
         1, 1000000, 100);
   }
+
+  LatencyInfo::LatencyComponent rendering_scheduled_component;
+  bool ret = false;
+  bool rendering_scheduled_on_main = latency.FindLatency(
+      ui::INPUT_EVENT_LATENCY_RENDERING_SCHEDULED_MAIN_COMPONENT,
+      0, &rendering_scheduled_component);
+
+  if (!rendering_scheduled_on_main) {
+    ret = latency.FindLatency(
+        ui::INPUT_EVENT_LATENCY_RENDERING_SCHEDULED_IMPL_COMPONENT,
+        0, &rendering_scheduled_component);
+    DCHECK(ret);
+    if (!ret) return;
+  }
+
+  DCHECK(rendering_scheduled_component.event_time >=
+         original_component.event_time);
+
+  if (rendering_scheduled_on_main) {
+    UMA_HISTOGRAM_SCROLL_LATENCY_LONG(
+        "Event.Latency.ScrollUpdate.TouchToHandled_Main",
+        original_component, rendering_scheduled_component);
+  } else {
+    UMA_HISTOGRAM_SCROLL_LATENCY_LONG(
+        "Event.Latency.ScrollUpdate.TouchToHandled_Impl",
+        original_component, rendering_scheduled_component);
+  }
+
+  LatencyInfo::LatencyComponent renderer_swap_component;
+  ret = latency.FindLatency(ui::INPUT_EVENT_LATENCY_RENDERER_SWAP_COMPONENT,
+                            0, &renderer_swap_component);
+  DCHECK(ret && renderer_swap_component.event_time >=
+         rendering_scheduled_component.event_time);
+  if (!ret) return;
+
+  if (rendering_scheduled_on_main) {
+    UMA_HISTOGRAM_SCROLL_LATENCY_LONG(
+        "Event.Latency.ScrollUpdate.HandledToRendererSwap_Main",
+        rendering_scheduled_component, renderer_swap_component);
+  } else {
+    UMA_HISTOGRAM_SCROLL_LATENCY_LONG(
+        "Event.Latency.ScrollUpdate.HandledToRendererSwap_Impl",
+        rendering_scheduled_component, renderer_swap_component);
+  }
+
+  LatencyInfo::LatencyComponent browser_received_swap_component;
+  ret = latency.FindLatency(
+          ui::INPUT_EVENT_BROWSER_RECEIVED_RENDERER_SWAP_COMPONENT,
+          0, &browser_received_swap_component);
+  DCHECK(ret && browser_received_swap_component.event_time >=
+         renderer_swap_component.event_time);
+  if (!ret) return;
+
+  UMA_HISTOGRAM_SCROLL_LATENCY_SHORT(
+      "Event.Latency.ScrollUpdate.RendererSwapToBrowserNotified",
+      renderer_swap_component, browser_received_swap_component);
+
+  LatencyInfo::LatencyComponent gpu_swap_component;
+  ret = latency.FindLatency(ui::INPUT_EVENT_GPU_SWAP_BUFFER_COMPONENT,
+                            0, &gpu_swap_component);
+  DCHECK(ret && gpu_swap_component.event_time >=

[jdduke (slow), 2015/02/18 00:00:16]

Hmm, these combined DCHECK conditions will be difficult to debug in practice.
Maybe let's leave them for a follow-up (back to patchset #6), just add a TODO?

Otherwise, I would use a NOTREACHED() + return for the find failure, and perhaps
add a DCHECK to the UMA macro. Regardless, let's add the validation in a
separate patch.

+         browser_received_swap_component.event_time &&
+         swap_component.event_time >= gpu_swap_component.event_time);
+  if (!ret) return;
+
+  UMA_HISTOGRAM_SCROLL_LATENCY_LONG(
+      "Event.Latency.ScrollUpdate.BrowserNotifiedToBeforeGpuSwap",
+      browser_received_swap_component, gpu_swap_component);
+
+  UMA_HISTOGRAM_SCROLL_LATENCY_SHORT("Event.Latency.ScrollUpdate.GpuSwap",
+                                     gpu_swap_component, swap_component);
 }
 
 // LatencyComponents generated in the renderer must have component IDs
@@ -264,7 +349,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) {