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 2168 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& event,

[jdduke (slow), 2013/10/01 23:45:31]

See my comment below about making Report() const.  That will eliminate some of
the LatencyInfo copying.

[Yufeng Shen (Slow to review), 2013/10/04 00:29:51]

As to Nat's suggestion, removed the Report() function and move the logic into
AddLatencyNumber(component_type) that if the component_type is terminal
component, dump the latency info into trace buffer. AddLatencyNumber() is
non-const so I change the OnXXXEventAck() signature to be 
OnXXXEventAck(WebXXXEevet, ack_result, ui::LatencyInfo* latency)

so we can call latency->AddLatencyNumber().

Bundling const WebInputEvent with non-const latencyinfo into one const
XXXEventWithLatencyInfo is causing all the constness/copying problem. So
separate them.

     InputEventAckState ack_result) {
+  ui::LatencyInfo latency = event.latency;
+  latency.Report(ui::INPUT_EVENT_LATENCY_ACKED_MOUSE_COMPONENT);
   const bool processed = (INPUT_EVENT_ACK_STATE_CONSUMED == ack_result);
   if (overscroll_controller_)
-    overscroll_controller_->ReceivedEventACK(wheel_event, processed);
-
+    overscroll_controller_->ReceivedEventACK(event.event, processed);
   if (!processed && !is_hidden() && view_)
-    view_->UnhandledWheelEvent(wheel_event);
+    view_->UnhandledWheelEvent(event.event);
 }
 
 void RenderWidgetHostImpl::OnGestureEventAck(
-    const WebKit::WebGestureEvent& event,
+    const GestureEventWithLatencyInfo& event,
     InputEventAckState ack_result) {
+  ui::LatencyInfo latency = event.latency;
+  latency.Report(ui::INPUT_EVENT_LATENCY_ACKED_GESTURE_COMPONENT);
   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) {
+  ui::LatencyInfo* latency = const_cast<ui::LatencyInfo*>(&(event.latency));

[jdduke (slow), 2013/10/01 23:45:31]

Again, if Report() was const we could do away with the const_cast here.

[Yufeng Shen (Slow to review), 2013/10/04 00:29:51]

ditto

[jdduke (slow), 2013/10/04 02:22:19]

Sorry, I didn't mean to say we should start passing non-const ui::LatencyInfo
pointers around.  I was more so wondering why in
OnWheelEventAck/OnGestureEventAck you copied the ui::LatencyInfo, but in
OnGestureEventAck you were modifying it in-place?  I was fine with the copying
before, it was really just the const_cast'ing =/ 

[Yufeng Shen (Slow to review), 2013/10/04 18:03:02]

So in the new patch I switch to passing both const WebInputEvent& and
ui::LatencyInfo* for all onGesture/Wheel/TouchEventAck. 
The main problem is that we need to call a non-const method on LatencyInfo
but the XXXEventWithLatencyInfo is passed around as const&, so either
I do a copy of the LatencyInfo and call the non-const method on the copy
or I separate the LatencyInfo from the WebInputEvent and directly call
the non-const method on the ui::LatencyInfo*

Though either way is perfect :(

+  latency->Report(ui::INPUT_EVENT_LATENCY_ACKED_TOUCH_COMPONENT);
   ComputeTouchLatency(event.latency);
   if (view_)
     view_->ProcessAckedTouchEvent(event, ack_result);
 }
 
 void RenderWidgetHostImpl::OnUnexpectedEventAck(UnexpectedEventAckType type) {
   if (type == BAD_ACK_MESSAGE) {
     RecordAction(UserMetricsAction("BadMessageTerminate_RWH2"));
     process_->ReceivedBadMessage();
   } else if (type == UNEXPECTED_EVENT_TYPE) {
@@ skipping 283 matching lines @@
       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;

[jdduke (slow), 2013/10/01 23:45:31]

Hmm, I thought we had moved these calculations/updates
(ComputeTouchLatency/FrameSwapped) to the BrowserRenderingStats object? Maybe
that was a separate patch?

[Yufeng Shen (Slow to review), 2013/10/04 00:29:51]

Yeah, I wasn't able to land that. But eventually we will get rid of this
function entirely once we convert to the trace base approach: whenever we think
the latencyinfo is done we dump the latencyinfo into trace buffer and we can in
telemetry gather these latencyinfo and do analysis on them.

+  ui::LatencyInfo::LatencyComponent swap_component;
   if (!latency_info.FindLatency(ui::INPUT_EVENT_LATENCY_RWH_COMPONENT,
                                 GetLatencyComponentId(),
-                                &rwh_component))
+                                &rwh_component) ||
+      !latency_info.FindLatency(ui::INPUT_EVENT_LATENCY_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();
 }
@@ skipping 12 matching lines @@
     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