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

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 07df66014ca774bff338542cc42c710f66e4e507..652892e04b81d120d320b99f03e9c755eaa0eadc 100644
--- a/content/browser/renderer_host/render_widget_host_latency_tracker.cc
+++ b/content/browser/renderer_host/render_widget_host_latency_tracker.cc
@@ -150,10 +150,12 @@ void ComputeInputLatencyHistograms(WebInputEvent::Type type,
     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,
@@ -163,9 +165,18 @@ void ComputeScrollLatencyHistograms(
     // scroll event's underlying touch event.
     for (size_t i = 0; i < first_original_component.event_count; i++) {
       UMA_HISTOGRAM_CUSTOM_COUNTS(
+          "Event.Latency.TouchToFirstScrollUpdateSwapBegin",
+          (gpu_swap_begin_component.event_time -
+           first_original_component.event_time).InMicroseconds(),
+          1, 1000000, 100);

[Yufeng Shen (Slow to review), 2015/04/17 21:49:58]

a UMA_HISTOGRAM_TOUCH_TO_SCROLL_LATENCY macro for this similar to 
UMA_HISTOGRAM_SCROLL_LATENCY_LONG/SHORT above ?

[brianderson, 2015/04/17 22:01:41]

Done.

+    }
+    // TODO(brianderson): Remove this version once we have enough overlapping
+    // data with the metric above.
+    for (size_t i = 0; i < first_original_component.event_count; i++) {
+      UMA_HISTOGRAM_CUSTOM_COUNTS(

[Yufeng Shen (Slow to review), 2015/04/17 21:49:58]

you can do this in the same loop above.

[brianderson, 2015/04/17 22:01:41]

Done.

           "Event.Latency.TouchToFirstScrollUpdateSwap",
-          (gpu_swap_component.event_time - first_original_component.event_time)
-              .InMicroseconds(),
+          (gpu_swap_end_component.event_time -
+           first_original_component.event_time).InMicroseconds(),
           1, 1000000, 100);
     }
     original_component = first_original_component;
@@ -180,8 +191,15 @@ void ComputeScrollLatencyHistograms(
   // results in final frame swap.
   for (size_t i = 0; i < original_component.event_count; i++) {
     UMA_HISTOGRAM_CUSTOM_COUNTS(
+        "Event.Latency.TouchToScrollUpdateSwapBegin",
+        (gpu_swap_begin_component.event_time - original_component.event_time)
+            .InMicroseconds(),
+        1, 1000000, 100);
+    // TODO(brianderson): Remove this version once we have enough overlapping
+    // data with the metric above.
+    UMA_HISTOGRAM_CUSTOM_COUNTS(
         "Event.Latency.TouchToScrollUpdateSwap",
-        (gpu_swap_component.event_time - original_component.event_time)
+        (gpu_swap_end_component.event_time - original_component.event_time)
             .InMicroseconds(),
         1, 1000000, 100);
   }
@@ -237,17 +255,11 @@ void ComputeScrollLatencyHistograms(
 
   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
@@ -403,9 +415,16 @@ void RenderWidgetHostLatencyTracker::OnSwapCompositorFrame(
 
 void RenderWidgetHostLatencyTracker::OnFrameSwapped(
     const LatencyInfo& latency) {
-  LatencyInfo::LatencyComponent 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_component)) {
+                           &gpu_swap_begin_component)) {
     return;
   }
 
@@ -413,7 +432,7 @@ void RenderWidgetHostLatencyTracker::OnFrameSwapped(
   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;

[brianderson, 2015/04/17 21:21:52]

jbauman: Heads up that this will change MPArch.RWH_TabSwitchPaintDuration to use
the end of swap, which is what it was using before.

     for (size_t i = 0; i < tab_switch_component.event_count; i++) {
       UMA_HISTOGRAM_TIMES("MPArch.RWH_TabSwitchPaintDuration", delta);
     }
@@ -424,7 +443,8 @@ void RenderWidgetHostLatencyTracker::OnFrameSwapped(
     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;
@@ -432,7 +452,7 @@ void RenderWidgetHostLatencyTracker::OnFrameSwapped(
           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;

[jdduke (slow), 2015/04/17 21:26:40]

Hmm, I'm wondering if it makes sense to use the "end" component here.

[brianderson, 2015/04/17 21:51:29]

For this one I'd prefer to keep the begin component since the end will have more
variance in the blocking behavior depending on the platform and GPU state.

If we need to be more conservative in the deadline estimation, I would prefer to
play with the percentile + fudge factor of the
browser_composite_latency_hitory_.

If the swap starts to block longer (pushing out the end component), it likely
means the Browser is in a high latency mode. Using the end component in that
case will increase the estimated Browser composite costs and make the Renderer's
deadline earlier, which will likely put the Renderer in a high latency mode too.

We really need OS feedback to avoid heuristics like this...

[jdduke (slow), 2015/04/17 22:03:22]

I see. By "renderer" do you mean Blink? Or the renderer compositor? I was under
the impression that a shorter deadline would make it less likely for the
compositor to enter high latency mode (trading off Blink latency), which is the
critical path for most gestures.

     browser_composite_latency_history_.InsertSample(delta);
   }
 }