Add latency measurement system

content/renderer/render_widget.cc

Index: content/renderer/render_widget.cc
diff --git a/content/renderer/render_widget.cc b/content/renderer/render_widget.cc
index 6e38df8a0b6014a1ff1af08e59e25169cdc0b91d..0f91183347fd3e8439e41471a01bc500509e7189 100644
--- a/content/renderer/render_widget.cc
+++ b/content/renderer/render_widget.cc
@@ -111,7 +111,9 @@ RenderWidget::RenderWidget(WebKit::WebPopupType popup_type,
       device_scale_factor_(screen_info_.deviceScaleFactor),
       throttle_input_events_(true),
       next_smooth_scroll_gesture_id_(0),
-      is_threaded_compositing_enabled_(false) {
+      is_threaded_compositing_enabled_(false),
+      started_frame_(false),
+      got_input_(false) {
   if (!swapped_out)
     RenderProcess::current()->AddRefProcess();
   DCHECK(RenderThread::Get());
@@ -238,6 +240,7 @@ bool RenderWidget::OnMessageReceived(const IPC::Message& message) {
     IPC_MESSAGE_HANDLER(ViewMsg_UpdateRect_ACK, OnUpdateRectAck)
     IPC_MESSAGE_HANDLER(ViewMsg_SwapBuffers_ACK, OnSwapBuffersComplete)
     IPC_MESSAGE_HANDLER(ViewMsg_HandleInputEvent, OnHandleInputEvent)
+    IPC_MESSAGE_HANDLER(ViewMsg_StartFrame, OnStartFrame)
     IPC_MESSAGE_HANDLER(ViewMsg_MouseCaptureLost, OnMouseCaptureLost)
     IPC_MESSAGE_HANDLER(ViewMsg_SetFocus, OnSetFocus)
     IPC_MESSAGE_HANDLER(ViewMsg_SetInputMethodActive, OnSetInputMethodActive)
@@ -545,7 +548,8 @@ void RenderWidget::OnSwapBuffersComplete() {
   DoDeferredUpdateAndSendInputAck();
 }
 
-void RenderWidget::OnHandleInputEvent(const WebKit::WebInputEvent* input_event,
+void RenderWidget::OnHandleInputEvent(int64 input_number,
+                                      const WebKit::WebInputEvent* input_event,
                                       bool is_keyboard_shortcut) {
   TRACE_EVENT0("renderer", "RenderWidget::OnHandleInputEvent");
 
@@ -555,6 +559,8 @@ void RenderWidget::OnHandleInputEvent(const WebKit::WebInputEvent* input_event,
     return;
   }
 
+  OnStartFrame(input_number);
+
   bool prevent_default = false;
   if (WebInputEvent::isMouseEventType(input_event->type)) {
     const WebMouseEvent& mouse_event =
@@ -638,6 +644,35 @@ void RenderWidget::OnHandleInputEvent(const WebKit::WebInputEvent* input_event,
   }
 }
 
+void RenderWidget::OnStartFrame(int64 input_number) {
+  latency_info_.inputNumber = std::max(input_number, latency_info_.inputNumber);
+  if (!got_input_) {
+    TRACE_EVENT_ASYNC_BEGIN1("frame", "Input handling", this,
+                             "input_number", input_number);
+    got_input_ = true;
+  }
+}
+
+void RenderWidget::StartingFrame() {
+  if (got_input_) {
+    TRACE_EVENT_ASYNC_END1("frame", "Input handling", this,
+                           "input_number", latency_info_.inputNumber);
+    got_input_ = false;
+  }
+
+  if (!started_frame_) {
+    started_frame_ = true;
+    latency_info_.rendererMainFrameNumber++;
+    TRACE_EVENT_ASYNC_BEGIN2("frame", "Frame", this,
+                             "frame_number",
+                                 latency_info_.rendererMainFrameNumber,
+                             "input_number", latency_info_.inputNumber);
+  }
+  WebKit::WebLatencyInfoImpl latency_info;
+  latency_info.latency_info = latency_info_;
+  webwidget_->setLatencyInfo(latency_info);
+}
+
 void RenderWidget::OnMouseCaptureLost() {
   if (webwidget_)
     webwidget_->mouseCaptureLost();
@@ -803,6 +838,7 @@ void RenderWidget::AnimationCallback() {
     TRACE_EVENT0("renderer", "EarlyOut_NoAnimationUpdatePending");
     return;
   }
+  StartingFrame();
   if (!animation_floor_time_.is_null() && IsRenderingVSynced()) {
     // Record when we fired (according to base::Time::Now()) relative to when
     // we posted the task to quantify how much the base::Time/base::TimeTicks
@@ -833,6 +869,7 @@ void RenderWidget::AnimateIfNeeded() {
   // complete callbacks to rate limit, we can ignore this floor.
   if (now >= animation_floor_time_ || num_swapbuffers_complete_pending_ > 0) {
     TRACE_EVENT0("renderer", "RenderWidget::AnimateIfNeeded")
+    StartingFrame();
     animation_floor_time_ = now + animationInterval;
     // Set a timer to call us back after animationInterval before
     // running animation callbacks so that if a callback requests another
@@ -936,6 +973,8 @@ void RenderWidget::DoDeferredUpdate() {
     return;
   }
 
+  StartingFrame();
+
   if (!is_accelerated_compositing_active_ &&
       !is_threaded_compositing_enabled_ &&
       ForceCompositingModeEnabled()) {
@@ -1005,6 +1044,7 @@ void RenderWidget::DoDeferredUpdate() {
   pending_update_params_->scroll_offset = GetScrollOffset();
   pending_update_params_->needs_ack = true;
   pending_update_params_->scale_factor = device_scale_factor_;
+  pending_update_params_->latency_info = latency_info_;
   next_paint_flags_ = 0;
   need_update_rect_for_auto_resize_ = false;
 
@@ -1086,6 +1126,7 @@ void RenderWidget::DoDeferredUpdate() {
     // sending an ack to browser process that the paint is complete...
     update_reply_pending_ = pending_update_params_->needs_ack;
     Send(new ViewHostMsg_UpdateRect(routing_id_, *pending_update_params_));
+    didBeginCompositorFrame();
     pending_update_params_.reset();
   }
 
@@ -1100,6 +1141,7 @@ void RenderWidget::DoDeferredUpdate() {
 void RenderWidget::didInvalidateRect(const WebRect& rect) {
   TRACE_EVENT2("renderer", "RenderWidget::didInvalidateRect",
                "width", rect.width, "height", rect.height);
+  StartingFrame();
   // The invalidated rect might be outside the bounds of the view.
   gfx::Rect view_rect(size_);
   gfx::Rect damaged_rect = gfx::IntersectRects(view_rect, rect);
@@ -1147,6 +1189,7 @@ void RenderWidget::didScrollRect(int dx, int dy,
   if (damaged_rect.IsEmpty())
     return;
 
+  StartingFrame();
   paint_aggregator_.ScrollRect(gfx::Vector2d(dx, dy), damaged_rect);
 
   // We may not need to schedule another call to DoDeferredUpdate.
@@ -1230,6 +1273,7 @@ void RenderWidget::didDeactivateCompositor() {
 
 void RenderWidget::willBeginCompositorFrame() {
   TRACE_EVENT0("gpu", "RenderWidget::willBeginCompositorFrame");
+  StartingFrame();
 
   DCHECK(RenderThreadImpl::current()->compositor_thread());
 
@@ -1238,10 +1282,18 @@ void RenderWidget::willBeginCompositorFrame() {
   // is done.
   UpdateTextInputState(DO_NOT_SHOW_IME);
   UpdateSelectionBounds();
-
   WillInitiatePaint();
 }
 
+void RenderWidget::didBeginCompositorFrame() {
+  if (started_frame_) {
+    TRACE_EVENT_ASYNC_END2("frame", "Frame", this,
+                           "frameNumber", latency_info_.rendererMainFrameNumber,
+                           "inputNumber", latency_info_.inputNumber);
+    started_frame_ = false;
+  }
+}
+
 void RenderWidget::didBecomeReadyForAdditionalInput() {
   TRACE_EVENT0("renderer", "RenderWidget::didBecomeReadyForAdditionalInput");
   if (pending_input_event_ack_.get())
@@ -1287,6 +1339,7 @@ void RenderWidget::didCompleteSwapBuffers() {
 
 void RenderWidget::scheduleComposite() {
   TRACE_EVENT0("gpu", "RenderWidget::scheduleComposite");
+  StartingFrame();
   if (WebWidgetHandlesCompositorScheduling()) {
     webwidget_->composite(false);
   } else {