Add latency measurement system

content/renderer/render_widget.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/renderer/render_widget.h"
 
 #include "base/bind.h"
 #include "base/command_line.h"
 #include "base/debug/trace_event.h"
 #include "base/logging.h"
@@ skipping 93 matching lines @@
       popup_type_(popup_type),
       pending_window_rect_count_(0),
       suppress_next_char_events_(false),
       is_accelerated_compositing_active_(false),
       animation_update_pending_(false),
       invalidation_task_posted_(false),
       screen_info_(screen_info),
       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());
   has_disable_gpu_vsync_switch_ = CommandLine::ForCurrentProcess()->HasSwitch(
       switches::kDisableGpuVsync);
   is_threaded_compositing_enabled_ =
       CommandLine::ForCurrentProcess()->HasSwitch(
           switches::kEnableThreadedCompositing);
 }
 
@@ skipping 106 matching lines @@
     IPC_MESSAGE_HANDLER(ViewMsg_Close, OnClose)
     IPC_MESSAGE_HANDLER(ViewMsg_CreatingNew_ACK, OnCreatingNewAck)
     IPC_MESSAGE_HANDLER(ViewMsg_Resize, OnResize)
     IPC_MESSAGE_HANDLER(ViewMsg_ChangeResizeRect, OnChangeResizeRect)
     IPC_MESSAGE_HANDLER(ViewMsg_WasHidden, OnWasHidden)
     IPC_MESSAGE_HANDLER(ViewMsg_WasShown, OnWasShown)
     IPC_MESSAGE_HANDLER(ViewMsg_WasSwappedOut, OnWasSwappedOut)
     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)
     IPC_MESSAGE_HANDLER(ViewMsg_ImeSetComposition, OnImeSetComposition)
     IPC_MESSAGE_HANDLER(ViewMsg_ImeConfirmComposition, OnImeConfirmComposition)
     IPC_MESSAGE_HANDLER(ViewMsg_PaintAtSize, OnMsgPaintAtSize)
     IPC_MESSAGE_HANDLER(ViewMsg_Repaint, OnMsgRepaint)
     IPC_MESSAGE_HANDLER(ViewMsg_SmoothScrollCompleted,
                         OnMsgSmoothScrollCompleted)
     IPC_MESSAGE_HANDLER(ViewMsg_SetTextDirection, OnSetTextDirection)
@@ skipping 288 matching lines @@
   // generated it.
   if (!animation_update_pending_ && !paint_aggregator_.HasPendingUpdate()) {
     TRACE_EVENT0("renderer", "EarlyOut_NoPendingUpdate");
     return;
   }
 
   // Continue painting if necessary...
   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");
 
   handling_input_event_ = true;
   if (!input_event) {
     handling_input_event_ = false;
     return;
   }
 
+  OnStartFrame(input_number);
+
   bool prevent_default = false;
   if (WebInputEvent::isMouseEventType(input_event->type)) {
     const WebMouseEvent& mouse_event =
         *static_cast<const WebMouseEvent*>(input_event);
     TRACE_EVENT2("renderer", "HandleMouseMove",
                  "x", mouse_event.x, "y", mouse_event.y);
     prevent_default = WillHandleMouseEvent(mouse_event);
   }
 
   if (WebInputEvent::isGestureEventType(input_event->type)) {
@@ skipping 63 matching lines @@
   if (!prevent_default) {
     if (WebInputEvent::isKeyboardEventType(input_event->type))
       DidHandleKeyEvent();
     if (WebInputEvent::isMouseEventType(input_event->type))
       DidHandleMouseEvent(*(static_cast<const WebMouseEvent*>(input_event)));
     if (WebInputEvent::isTouchEventType(input_event->type))
       DidHandleTouchEvent(*(static_cast<const WebTouchEvent*>(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);
+  }
+  webwidget_->setLatencyInfo(latency_info_);
+}
+
 void RenderWidget::OnMouseCaptureLost() {
   if (webwidget_)
     webwidget_->mouseCaptureLost();
 }
 
 void RenderWidget::OnSetFocus(bool enable) {
   has_focus_ = enable;
   if (webwidget_)
     webwidget_->setFocus(enable);
 }
@@ skipping 145 matching lines @@
   irect.set(rect.x(), rect.y(), rect.right() - 1, rect.bottom() - 1);
   canvas->drawIRect(irect, paint);
 }
 
 void RenderWidget::AnimationCallback() {
   TRACE_EVENT0("renderer", "RenderWidget::AnimationCallback");
   if (!animation_update_pending_) {
     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
     // skew is affecting animations.
     base::TimeDelta animation_callback_delay = base::Time::Now() -
         (animation_floor_time_ - base::TimeDelta::FromMilliseconds(16));
     UMA_HISTOGRAM_CUSTOM_TIMES("Renderer4.AnimationCallbackDelayTime",
                                animation_callback_delay,
                                base::TimeDelta::FromMilliseconds(0),
                                base::TimeDelta::FromMilliseconds(30),
@@ skipping 10 matching lines @@
   base::TimeDelta animationInterval = IsRenderingVSynced() ?
       base::TimeDelta::FromMilliseconds(16) : base::TimeDelta();
 
   base::Time now = base::Time::Now();
 
   // animation_floor_time_ is the earliest time that we should animate when
   // using the dead reckoning software scheduler. If we're using swapbuffers
   // 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
     // we'll be sure to run it at the proper time.
     animation_timer_.Stop();
     animation_timer_.Start(FROM_HERE, animationInterval, this,
                            &RenderWidget::AnimationCallback);
     animation_update_pending_ = false;
     webwidget_->animate(0.0);
     return;
@@ skipping 83 matching lines @@
   UpdateSelectionBounds();
 
   // Suppress painting if nothing is dirty.  This has to be done after updating
   // animations running layout as these may generate further invalidations.
   if (!paint_aggregator_.HasPendingUpdate()) {
     TRACE_EVENT0("renderer", "EarlyOut_NoPendingUpdate");
     webwidget_->instrumentCancelFrame();
     return;
   }
 
+  StartingFrame();
+
   if (!is_accelerated_compositing_active_ &&
       !is_threaded_compositing_enabled_ &&
       ForceCompositingModeEnabled()) {
     webwidget_->enterForceCompositingMode(true);
   }
 
   if (!last_do_deferred_update_time_.is_null()) {
     base::TimeDelta delay = frame_begin_ticks - last_do_deferred_update_time_;
     if (is_accelerated_compositing_active_) {
       UMA_HISTOGRAM_CUSTOM_TIMES("Renderer4.AccelDoDeferredUpdateDelay",
@@ skipping 49 matching lines @@
   DCHECK(!pending_update_params_.get());
   pending_update_params_.reset(new ViewHostMsg_UpdateRect_Params);
   pending_update_params_->scroll_delta = update.scroll_delta;
   pending_update_params_->scroll_rect = update.scroll_rect;
   pending_update_params_->view_size = size_;
   pending_update_params_->plugin_window_moves.swap(plugin_window_moves_);
   pending_update_params_->flags = next_paint_flags_;
   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;
 
   if (update.scroll_rect.IsEmpty() &&
       !is_accelerated_compositing_active_ &&
       GetBitmapForOptimizedPluginPaint(bounds, &dib, &optimized_copy_location,
                                        &optimized_copy_rect,
                                        &dib_scale_factor)) {
     // Only update the part of the plugin that actually changed.
     optimized_copy_rect.Intersect(bounds);
@@ skipping 61 matching lines @@
     Send(pending_input_event_ack_.release());
 
   // If composite() called SwapBuffers, pending_update_params_ will be reset (in
   // OnSwapBuffersPosted), meaning a message has been added to the
   // updates_pending_swap_ queue, that will be sent later. Otherwise, we send
   // the message now.
   if (pending_update_params_.get()) {
     // 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();
   }
 
   // If we're software rendering then we're done initiating the paint.
   if (!is_accelerated_compositing_active_)
     DidInitiatePaint();
 }
 
 ///////////////////////////////////////////////////////////////////////////////
 // WebWidgetClient
 
 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);
   if (damaged_rect.IsEmpty())
     return;
 
   paint_aggregator_.InvalidateRect(damaged_rect);
 
   // We may not need to schedule another call to DoDeferredUpdate.
   if (invalidation_task_posted_)
@@ skipping 27 matching lines @@
   // TODO(nduca): stop WebViewImpl from sending scrolls in the first place.
   if (is_accelerated_compositing_active_)
     return;
 
   // The scrolled rect might be outside the bounds of the view.
   gfx::Rect view_rect(size_);
   gfx::Rect damaged_rect = gfx::IntersectRects(view_rect, clip_rect);
   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.
   if (invalidation_task_posted_)
     return;
   if (!paint_aggregator_.HasPendingUpdate())
     return;
   if (update_reply_pending_ ||
       num_swapbuffers_complete_pending_ >= kMaxSwapBuffersPending)
     return;
@@ skipping 63 matching lines @@
   // In single-threaded mode, we exit force compositing mode and re-enter in
   // DoDeferredUpdate() if appropriate. In threaded compositing mode,
   // DoDeferredUpdate() is bypassed and WebKit is responsible for exiting and
   // entering force compositing mode at the appropriate times.
   if (!is_threaded_compositing_enabled_)
     webwidget_->enterForceCompositingMode(false);
 }
 
 void RenderWidget::willBeginCompositorFrame() {
   TRACE_EVENT0("gpu", "RenderWidget::willBeginCompositorFrame");
+  StartingFrame();
 
   DCHECK(RenderThreadImpl::current()->compositor_thread());
 
   // The following two can result in further layout and possibly
   // enable GPU acceleration so they need to be called before any painting
   // is done.
   UpdateTextInputState(DO_NOT_SHOW_IME);
   UpdateSelectionBounds();
+  WillInitiatePaint();
+}
 
-  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())
     Send(pending_input_event_ack_.release());
 }
 
 void RenderWidget::didCommitAndDrawCompositorFrame() {
   TRACE_EVENT0("gpu", "RenderWidget::didCommitAndDrawCompositorFrame");
@@ skipping 27 matching lines @@
   params.needs_ack = false;
   params.scale_factor = device_scale_factor_;
 
   Send(new ViewHostMsg_UpdateRect(routing_id_, params));
   next_paint_flags_ = 0;
   need_update_rect_for_auto_resize_ = false;
 }
 
 void RenderWidget::scheduleComposite() {
   TRACE_EVENT0("gpu", "RenderWidget::scheduleComposite");
+  StartingFrame();
   if (WebWidgetHandlesCompositorScheduling()) {
     webwidget_->composite(false);
   } else {
     // TODO(nduca): replace with something a little less hacky.  The reason this
     // hack is still used is because the Invalidate-DoDeferredUpdate loop
     // contains a lot of host-renderer synchronization logic that is still
     // important for the accelerated compositing case. The option of simply
     // duplicating all that code is less desirable than "faking out" the
     // invalidation path using a magical damage rect.
     didInvalidateRect(WebRect(0, 0, 1, 1));
@@ skipping 668 matching lines @@
 
 bool RenderWidget::WebWidgetHandlesCompositorScheduling() const {
   return false;
 }
 
 bool RenderWidget::HasTouchEventHandlersAt(const gfx::Point& point) const {
   return true;
 }
 
 }  // namespace content