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 1000 matching lines @@
     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,
-    InputEventAckState ack_result) {
+    InputEventAckState ack_result,
+    ui::LatencyInfo* latency) {
+  if (!latency->FindLatency(
+          ui::INPUT_EVENT_LATENCY_RENDERING_SCHEDULED_COMPONENT, 0, NULL)) {
+    // MouseWheelEvent latency ends when it is acked but does not cause any
+    // rendering scheduled.
+    latency->AddLatencyNumber(

[jdduke (slow), 2013/10/08 16:28:08]

Please revert the arg changes and just copy the ui::LatencyInfo if necessary
here (within the if).

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

Done.

+        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);
-
   if (!processed && !is_hidden() && view_)
     view_->UnhandledWheelEvent(wheel_event);
 }
 
 void RenderWidgetHostImpl::OnGestureEventAck(
     const WebKit::WebGestureEvent& event,
-    InputEventAckState ack_result) {
+    InputEventAckState ack_result,
+    ui::LatencyInfo* latency) {

[jdduke (slow), 2013/10/08 16:28:08]

Same as above.

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

Done.

+  if (!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.
+    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);
 
   if (view_)
     view_->GestureEventAck(event.type, ack_result);
 }
 
 void RenderWidgetHostImpl::OnTouchEventAck(
-    const TouchEventWithLatencyInfo& event,
-    InputEventAckState ack_result) {
-  ComputeTouchLatency(event.latency);
+    const WebKit::WebTouchEvent& event,
+    InputEventAckState ack_result,
+    ui::LatencyInfo* latency) {
+  // TouchEvent latency does not end when acked since it could later on
+  // become gesture events.
+  latency->AddLatencyNumber(ui::INPUT_EVENT_LATENCY_ACKED_TOUCH_COMPONENT,

[jdduke (slow), 2013/10/08 16:28:08]

Ditto.

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

Done.

+                            0, 0);
+  ComputeTouchLatency(*latency);
   if (view_)
-    view_->ProcessAckedTouchEvent(event, ack_result);
+    view_->ProcessAckedTouchEvent(TouchEventWithLatencyInfo(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