Report LatencyInfo through trace buffer

content/browser/renderer_host/render_widget_host_impl.cc

 // Copyright (c) 2012 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_impl.h"
 
 #include <math.h>
 #include <utility>
 
 #include "base/auto_reset.h"
@@ skipping 1146 matching lines @@
   g_check_for_pending_resize_ack = false;
 }
 
 ui::LatencyInfo RenderWidgetHostImpl::CreateRWHLatencyInfoIfNotExist(
     const ui::LatencyInfo* original) {
   ui::LatencyInfo info;
   if (original)
     info = *original;
   // In Aura, gesture event will already carry its original touch event's
   // INPUT_EVENT_LATENCY_RWH_COMPONENT.
-  if (!info.FindLatency(ui::INPUT_EVENT_LATENCY_RWH_COMPONENT,
+  if (!info.FindLatency(ui::INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT,
                         GetLatencyComponentId(),
                         NULL)) {
-    info.AddLatencyNumber(ui::INPUT_EVENT_LATENCY_RWH_COMPONENT,
+    info.AddLatencyNumber(ui::INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT,
                           GetLatencyComponentId(),
                           ++last_input_number_);
   }
   return info;
 }
 
 
 void RenderWidgetHostImpl::AddKeyPressEventCallback(
     const KeyPressEventCallback& callback) {
   key_press_event_callbacks_.push_back(callback);
@@ skipping 999 matching lines @@
   if (delegate_ && !processed && !is_hidden() && !event.skip_in_browser) {
     delegate_->HandleKeyboardEvent(event);
 
     // WARNING: This RenderWidgetHostImpl can be deallocated at this point
     // (i.e.  in the case of Ctrl+W, where the call to
     // HandleKeyboardEvent destroys this RenderWidgetHostImpl).
   }
 }
 
 void RenderWidgetHostImpl::OnWheelEventAck(
-    const WebKit::WebMouseWheelEvent& wheel_event,
+    const MouseWheelEventWithLatencyInfo& wheel_event,
     InputEventAckState ack_result) {
+  if (!wheel_event.latency.FindLatency(

[jdduke (slow), 2013/10/08 20:58:50]

In the future, we might consider an additional
ui::LatencyInfo::ReportTerminalComponent(...) that reports with the provided
terminal component and doesn't mutate the latency.  This would be for occasions
like this method where we're done with the latency and just want to report it. 
That can come later, and may not even be needed when these OnFooEventAck()
methods start taking scoped_ptrs. 

+          ui::INPUT_EVENT_LATENCY_RENDERING_SCHEDULED_COMPONENT, 0, NULL)) {
+    // MouseWheelEvent latency ends when it is acked but does not cause any
+    // rendering scheduled.
+    ui::LatencyInfo latency = wheel_event.latency;
+    latency.AddLatencyNumber(
+        ui::INPUT_EVENT_LATENCY_TERMINATED_MOUSE_COMPONENT, 0, 0);
+  }
   const bool processed = (INPUT_EVENT_ACK_STATE_CONSUMED == ack_result);
   if (overscroll_controller_)
-    overscroll_controller_->ReceivedEventACK(wheel_event, processed);
-
+    overscroll_controller_->ReceivedEventACK(wheel_event.event, processed);
   if (!processed && !is_hidden() && view_)
-    view_->UnhandledWheelEvent(wheel_event);
+    view_->UnhandledWheelEvent(wheel_event.event);
 }
 
 void RenderWidgetHostImpl::OnGestureEventAck(
-    const WebKit::WebGestureEvent& event,
+    const GestureEventWithLatencyInfo& event,
     InputEventAckState ack_result) {
+  if (!event.latency.FindLatency(
+          ui::INPUT_EVENT_LATENCY_RENDERING_SCHEDULED_COMPONENT, 0, NULL)) {
+    // GestureEvent latency ends when it is acked but does not cause any
+    // rendering scheduled.
+    ui::LatencyInfo latency = event.latency;
+    latency.AddLatencyNumber(
+        ui::INPUT_EVENT_LATENCY_TERMINATED_GESTURE_COMPONENT, 0 ,0);
+  }
   const bool processed = (INPUT_EVENT_ACK_STATE_CONSUMED == ack_result);
   if (overscroll_controller_)
-    overscroll_controller_->ReceivedEventACK(event, processed);
+    overscroll_controller_->ReceivedEventACK(event.event, processed);
 
   if (view_)
-    view_->GestureEventAck(event.type, ack_result);
+    view_->GestureEventAck(event.event.type, ack_result);
 }
 
 void RenderWidgetHostImpl::OnTouchEventAck(
     const TouchEventWithLatencyInfo& event,
     InputEventAckState ack_result) {
-  ComputeTouchLatency(event.latency);
+  // TouchEvent latency does not end when acked since it could later on

[jdduke (slow), 2013/10/08 20:58:50]

Nit: You might as well copy |event| into a new TouchEventWithLatencyInfo,
operate on that latency, then pass it to the view, rather than copying the
latency, then copying it and the event to a new TouchEventWithLatencyInfo below.

[Yufeng Shen (Slow to review), 2013/10/08 21:35:18]

Done.

+  // become gesture events.
+  ui::LatencyInfo latency = event.latency;
+  latency.AddLatencyNumber(ui::INPUT_EVENT_LATENCY_ACKED_TOUCH_COMPONENT,
+                           0, 0);
+  ComputeTouchLatency(latency);
   if (view_)
-    view_->ProcessAckedTouchEvent(event, ack_result);
+    view_->ProcessAckedTouchEvent(
+        TouchEventWithLatencyInfo(event.event, latency), ack_result);
 }
 
 void RenderWidgetHostImpl::OnUnexpectedEventAck(UnexpectedEventAckType type) {
   if (type == BAD_ACK_MESSAGE) {
     RecordAction(UserMetricsAction("BadMessageTerminate_RWH2"));
     process_->ReceivedBadMessage();
   } else if (type == UNEXPECTED_EVENT_TYPE) {
     suppress_next_char_events_ = false;
   }
 }
@@ skipping 250 matching lines @@
 
 void RenderWidgetHostImpl::ComputeTouchLatency(
     const ui::LatencyInfo& latency_info) {
   ui::LatencyInfo::LatencyComponent ui_component;
   ui::LatencyInfo::LatencyComponent rwh_component;
   ui::LatencyInfo::LatencyComponent acked_component;
 
   if (!latency_info.FindLatency(ui::INPUT_EVENT_LATENCY_UI_COMPONENT,
                                 0,
                                 &ui_component) ||
-      !latency_info.FindLatency(ui::INPUT_EVENT_LATENCY_RWH_COMPONENT,
+      !latency_info.FindLatency(ui::INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT,
                                 GetLatencyComponentId(),
                                 &rwh_component))
     return;
 
   DCHECK(ui_component.event_count == 1);
   DCHECK(rwh_component.event_count == 1);
 
   base::TimeDelta ui_delta =
       rwh_component.event_time - ui_component.event_time;
   rendering_stats_.touch_ui_count++;
   rendering_stats_.total_touch_ui_latency += ui_delta;
   UMA_HISTOGRAM_CUSTOM_COUNTS(
       "Event.Latency.Browser.TouchUI",
       ui_delta.InMicroseconds(),
       0,
       20000,
       100);
 
-  if (latency_info.FindLatency(ui::INPUT_EVENT_LATENCY_ACKED_COMPONENT,
+  if (latency_info.FindLatency(ui::INPUT_EVENT_LATENCY_ACKED_TOUCH_COMPONENT,
                                0,
                                &acked_component)) {
     DCHECK(acked_component.event_count == 1);
     base::TimeDelta acked_delta =
         acked_component.event_time - rwh_component.event_time;
     rendering_stats_.touch_acked_count++;
     rendering_stats_.total_touch_acked_latency += acked_delta;
     UMA_HISTOGRAM_CUSTOM_COUNTS(
         "Event.Latency.Browser.TouchAcked",
         acked_delta.InMicroseconds(),
         0,
         1000000,
         100);
   }
 
   if (CommandLine::ForCurrentProcess()->HasSwitch(
           switches::kEnableGpuBenchmarking))
     Send(new ViewMsg_SetBrowserRenderingStats(routing_id_, rendering_stats_));
 }
 
 void RenderWidgetHostImpl::FrameSwapped(const ui::LatencyInfo& latency_info) {
   ui::LatencyInfo::LatencyComponent rwh_component;
-  if (!latency_info.FindLatency(ui::INPUT_EVENT_LATENCY_RWH_COMPONENT,
+  ui::LatencyInfo::LatencyComponent swap_component;
+  if (!latency_info.FindLatency(ui::INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT,
                                 GetLatencyComponentId(),
-                                &rwh_component))
+                                &rwh_component) ||
+      !latency_info.FindLatency(
+          ui::INPUT_EVENT_LATENCY_TERMINATED_FRAME_SWAP_COMPONENT,
+          0, &swap_component)) {
     return;
+  }
 
   rendering_stats_.input_event_count += rwh_component.event_count;
   rendering_stats_.total_input_latency +=
       rwh_component.event_count *
-      (latency_info.swap_timestamp - rwh_component.event_time);
+      (swap_component.event_time - rwh_component.event_time);
 
   ui::LatencyInfo::LatencyComponent original_component;
   if (latency_info.FindLatency(
           ui::INPUT_EVENT_LATENCY_SCROLL_UPDATE_ORIGINAL_COMPONENT,
           GetLatencyComponentId(),
           &original_component)) {
     // 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.
     base::TimeDelta delta =
-        latency_info.swap_timestamp - original_component.event_time;
+        swap_component.event_time - original_component.event_time;
     for (size_t i = 0; i < original_component.event_count; i++) {
       UMA_HISTOGRAM_CUSTOM_COUNTS(
           "Event.Latency.TouchToScrollUpdateSwap",
           delta.InMicroseconds(),
           0,
           1000000,
           100);
     }
     rendering_stats_.scroll_update_count += original_component.event_count;
     rendering_stats_.total_scroll_update_latency +=
         original_component.event_count *
-        (latency_info.swap_timestamp - original_component.event_time);
+        (swap_component.event_time - original_component.event_time);
   }
 
   if (CommandLine::ForCurrentProcess()->HasSwitch(
           switches::kEnableGpuBenchmarking))
     Send(new ViewMsg_SetBrowserRenderingStats(routing_id_, rendering_stats_));
 }
 
 void RenderWidgetHostImpl::DidReceiveRendererFrame() {
   view_->DidReceiveRendererFrame();
 }
 
 // static
 void RenderWidgetHostImpl::CompositorFrameDrawn(
     const ui::LatencyInfo& latency_info) {
   for (ui::LatencyInfo::LatencyMap::const_iterator b =
            latency_info.latency_components.begin();
        b != latency_info.latency_components.end();
        ++b) {
-    if (b->first.first != ui::INPUT_EVENT_LATENCY_RWH_COMPONENT)
+    if (b->first.first != ui::INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT)
       continue;
     // Matches with GetLatencyComponentId
     int routing_id = b->first.second & 0xffffffff;
     int process_id = (b->first.second >> 32) & 0xffffffff;
     RenderWidgetHost* rwh =
         RenderWidgetHost::FromID(process_id, routing_id);
     if (!rwh)
       continue;
     RenderWidgetHostImpl::From(rwh)->FrameSwapped(latency_info);
   }
 }
 
 }  // namespace content