Change input latency result to depend on start of GPU swap

Use INPUT_EVENT_GPU_SWAP_BUFFER_COMPONENT instead of
INPUT_EVENT_LATENCY_TERMINATED_FRAME_SWAP_COMPONENT as the
final component to calculate input latency.

This will more accurately reflect latency regressions in the
code we have direct control of in Chrome.

Also make PassThroughImageTransportSurface::PostSubBuffer
add a INPUT_EVENT_GPU_SWAP_BUFFER_COMPONENT, which it
was missing before.

Followup patches will snap
INPUT_EVENT_LATENCY_TERMINATED_FRAME_SWAP_COMPONENT
to the next vsync to reflect the real display time.

The real display time can then be used for better
smoothness metrics and also to track latency regressions
at the OS/driver level for Ozone and potentially other
platforms where we can extract swap info.

BUG=360844

Review URL: https://codereview.chromium.org/918883002

Cr-Commit-Position: refs/heads/master@{#318812}

content/browser/compositor/software_browser_compositor_output_surface.cc

@@ -30,9 +30,13 @@ SoftwareBrowserCompositorOutputSurface::
 
 void SoftwareBrowserCompositorOutputSurface::SwapBuffers(
     cc::CompositorFrame* frame) {
-  for (size_t i = 0; i < frame->metadata.latency_info.size(); i++) {
-    frame->metadata.latency_info[i].AddLatencyNumber(
-        ui::INPUT_EVENT_LATENCY_TERMINATED_FRAME_SWAP_COMPONENT, 0, 0);
+  base::TimeTicks swap_time = base::TimeTicks::Now();
+  for (auto& latency : frame->metadata.latency_info) {
+    latency.AddLatencyNumberWithTimestamp(
+        ui::INPUT_EVENT_GPU_SWAP_BUFFER_COMPONENT, 0, 0, swap_time, 1);
+    latency.AddLatencyNumberWithTimestamp(
+        ui::INPUT_EVENT_LATENCY_TERMINATED_FRAME_SWAP_COMPONENT, 0, 0,
+        swap_time, 1);
   }
   base::MessageLoop::current()->PostTask(
       FROM_HERE,

content/browser/renderer_host/render_widget_host_latency_tracker.cc

@@ -150,10 +150,10 @@ void ComputeInputLatencyHistograms(WebInputEvent::Type type,
     1, 50000, 50)
 
 void ComputeScrollLatencyHistograms(
-    const LatencyInfo::LatencyComponent& swap_component,
+    const LatencyInfo::LatencyComponent& gpu_swap_component,
     int64 latency_component_id,
-    const ui::LatencyInfo& latency) {
-  DCHECK(!swap_component.event_time.is_null());
+    const LatencyInfo& latency) {
+  DCHECK(!gpu_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,
@@ -164,7 +164,7 @@ void ComputeScrollLatencyHistograms(
     for (size_t i = 0; i < first_original_component.event_count; i++) {
       UMA_HISTOGRAM_CUSTOM_COUNTS(
           "Event.Latency.TouchToFirstScrollUpdateSwap",
-          (swap_component.event_time - first_original_component.event_time)
+          (gpu_swap_component.event_time - first_original_component.event_time)
               .InMicroseconds(),
           1, 1000000, 100);
     }
@@ -181,7 +181,7 @@ void ComputeScrollLatencyHistograms(
   for (size_t i = 0; i < original_component.event_count; i++) {
     UMA_HISTOGRAM_CUSTOM_COUNTS(
         "Event.Latency.TouchToScrollUpdateSwap",
-        (swap_component.event_time - original_component.event_time)
+        (gpu_swap_component.event_time - original_component.event_time)
             .InMicroseconds(),
         1, 1000000, 100);
   }
@@ -235,17 +235,19 @@ void ComputeScrollLatencyHistograms(
       "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_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;
+
   UMA_HISTOGRAM_SCROLL_LATENCY_SHORT("Event.Latency.ScrollUpdate.GpuSwap",
-                                     gpu_swap_component, swap_component);
+                                     gpu_swap_component,
+                                     gpu_swap_ack_component);
 }
 
 // LatencyComponents generated in the renderer must have component IDs
@@ -389,11 +391,10 @@ void RenderWidgetHostLatencyTracker::OnSwapCompositorFrame(
 }
 
 void RenderWidgetHostLatencyTracker::OnFrameSwapped(
-    const ui::LatencyInfo& latency) {
-  LatencyInfo::LatencyComponent swap_component;
-  if (!latency.FindLatency(
-          ui::INPUT_EVENT_LATENCY_TERMINATED_FRAME_SWAP_COMPONENT, 0,
-          &swap_component)) {
+    const LatencyInfo& latency) {
+  LatencyInfo::LatencyComponent gpu_swap_component;
+  if (!latency.FindLatency(ui::INPUT_EVENT_GPU_SWAP_BUFFER_COMPONENT, 0,
+                           &gpu_swap_component)) {
     return;
   }
 
@@ -401,28 +402,21 @@ void RenderWidgetHostLatencyTracker::OnFrameSwapped(
   if (latency.FindLatency(ui::TAB_SHOW_COMPONENT, latency_component_id_,
                           &tab_switch_component)) {
     base::TimeDelta delta =
-        swap_component.event_time - tab_switch_component.event_time;
+        gpu_swap_component.event_time - tab_switch_component.event_time;
     for (size_t i = 0; i < tab_switch_component.event_count; i++) {
       UMA_HISTOGRAM_TIMES("MPArch.RWH_TabSwitchPaintDuration", delta);
     }
   }
 
-  LatencyInfo::LatencyComponent rwh_component;
   if (!latency.FindLatency(ui::INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT,
-                           latency_component_id_, &rwh_component)) {
+                           latency_component_id_, nullptr)) {
     return;
   }
 
-  ComputeScrollLatencyHistograms(swap_component, latency_component_id_,
+  ComputeScrollLatencyHistograms(gpu_swap_component, latency_component_id_,
                                  latency);
 
-  ui::LatencyInfo::LatencyComponent gpu_swap_component;
-  if (!latency.FindLatency(ui::INPUT_EVENT_GPU_SWAP_BUFFER_COMPONENT, 0,
-                           &gpu_swap_component)) {
-    return;
-  }
-
-  ui::LatencyInfo::LatencyComponent browser_swap_component;
+  LatencyInfo::LatencyComponent browser_swap_component;
   if (latency.FindLatency(
           ui::INPUT_EVENT_BROWSER_RECEIVED_RENDERER_SWAP_COMPONENT, 0,
           &browser_swap_component)) {

content/common/gpu/image_transport_surface.cc

@@ -191,8 +191,12 @@ bool PassThroughImageTransportSurface::SwapBuffers() {
   // GetVsyncValues before SwapBuffers to work around Mali driver bug:
   // crbug.com/223558.
   SendVSyncUpdateIfAvailable();
-  for (auto& latency : latency_info_)
-    latency.AddLatencyNumber(ui::INPUT_EVENT_GPU_SWAP_BUFFER_COMPONENT, 0, 0);
+
+  base::TimeTicks swap_time = base::TimeTicks::Now();
+  for (auto& latency : latency_info_) {
+    latency.AddLatencyNumberWithTimestamp(
+        ui::INPUT_EVENT_GPU_SWAP_BUFFER_COMPONENT, 0, 0, swap_time, 1);
+  }
 
   // We use WeakPtr here to avoid manual management of life time of an instance
   // of this class. Callback will not be called once the instance of this class
@@ -206,6 +210,13 @@ bool PassThroughImageTransportSurface::SwapBuffers() {
 bool PassThroughImageTransportSurface::PostSubBuffer(
     int x, int y, int width, int height) {
   SendVSyncUpdateIfAvailable();
+
+  base::TimeTicks swap_time = base::TimeTicks::Now();
+  for (auto& latency : latency_info_) {
+    latency.AddLatencyNumberWithTimestamp(
+        ui::INPUT_EVENT_GPU_SWAP_BUFFER_COMPONENT, 0, 0, swap_time, 1);
+  }
+
   // We use WeakPtr here to avoid manual management of life time of an instance
   // of this class. Callback will not be called once the instance of this class
   // is destroyed. However, this also means that the callback can be run on
@@ -216,9 +227,11 @@ bool PassThroughImageTransportSurface::PostSubBuffer(
 }
 
 void PassThroughImageTransportSurface::SwapBuffersCallBack() {
-  for (size_t i = 0; i < latency_info_.size(); i++) {
-    latency_info_[i].AddLatencyNumber(
-        ui::INPUT_EVENT_LATENCY_TERMINATED_FRAME_SWAP_COMPONENT, 0, 0);
+  base::TimeTicks swap_ack_time = base::TimeTicks::Now();
+  for (auto& latency : latency_info_) {
+    latency.AddLatencyNumberWithTimestamp(
+        ui::INPUT_EVENT_LATENCY_TERMINATED_FRAME_SWAP_COMPONENT, 0, 0,
+        swap_ack_time, 1);
   }
 
   helper_->stub()->SendSwapBuffersCompleted(latency_info_);

tools/telemetry/telemetry/web_perf/metrics/rendering_stats.py

@@ -20,7 +20,7 @@ BEGIN_SCROLL_UPDATE_COMP_NAME = (
 FORWARD_SCROLL_UPDATE_COMP_NAME = (
     'INPUT_EVENT_LATENCY_FORWARD_SCROLL_UPDATE_TO_MAIN_COMPONENT')
 # This is when the input event has reached swap buffer.
-END_COMP_NAME = 'INPUT_EVENT_LATENCY_TERMINATED_FRAME_SWAP_COMPONENT'
+END_COMP_NAME = 'INPUT_EVENT_GPU_SWAP_BUFFER_COMPONENT'
 
 # Name for a main thread scroll update latency event.
 SCROLL_UPDATE_EVENT_NAME = 'InputLatency:ScrollUpdate'