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 132 matching lines @@
     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.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;
   } 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.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);
   }
 
   // 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);
@@ skipping 35 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;

[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);
     }
   }
 
   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;

[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);
   }
 }
 
 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