Add telemetry to track the time an event spent waiting for the main thread.

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 121 matching lines @@
     CASE_TYPE(TouchCancel);
     default:
       // Must include default to let WebKit::WebInputEvent add new event types
       // before they're added here.
       DLOG(WARNING) << "Unhandled WebInputEvent type in GetEventName.\n";
       break;
   }
 #undef CASE_TYPE
   return "";
 }
+
+void SendToImplThreadLatencyUma(int routing_id,
+                                const ui::LatencyInfo& latency_info,
+                                WebInputEvent::Type event_type) {
+  ui::LatencyInfo::LatencyComponent dispatch_component;
+  ui::LatencyInfo::LatencyComponent receive_component;
+  if (latency_info.FindLatency(
+          ui::INPUT_EVENT_LATENCY_SENT_FROM_IMPL_THREAD_COMPONENT,
+          routing_id, &dispatch_component) &&
+      latency_info.FindLatency(
+          ui::INPUT_EVENT_LATENCY_RECEIVED_ON_MAIN_THREAD_COMPONENT,
+          routing_id, &receive_component)) {
+    base::TimeDelta delta = receive_component.event_time -
+        dispatch_component.event_time;
+    switch (event_type) {
+      case WebInputEvent::GestureScrollBegin:
+      case WebInputEvent::GestureScrollUpdate:
+      case WebInputEvent::GestureScrollUpdateWithoutPropagation:
+        UMA_HISTOGRAM_TIMES(
+            "Event.Latency.ImplThreadToRendererThread.GestureScroll", delta);
+        break;
+      case WebInputEvent::TouchStart:
+      case WebInputEvent::TouchMove:
+        UMA_HISTOGRAM_TIMES(
+            "Event.Latency.ImplThreadToRendererThread.Touch", delta);
+        break;
+      default:
+        break;
+    }
+  }
+}
+
+void UpdateRenderingStatsForAverageImplThreadLatency(
+    int routing_id,
+    const ui::LatencyInfo& latency_info,
+    cc::RenderingStats& stats) {
+  ui::LatencyInfo::LatencyComponent dispatch_component;
+  ui::LatencyInfo::LatencyComponent receive_component;
+  if (latency_info.FindLatency(
+          ui::INPUT_EVENT_LATENCY_SENT_FROM_IMPL_THREAD_COMPONENT,
+          routing_id, &dispatch_component) &&
+      latency_info.FindLatency(
+          ui::INPUT_EVENT_LATENCY_RECEIVED_ON_MAIN_THREAD_COMPONENT,
+          routing_id, &receive_component)) {
+    stats.average_impl_thread_to_main_thread_time =
+        receive_component.event_time - dispatch_component.event_time;

[jbauman, 2013/07/03 20:00:15]

This won't calculate an average. You'd need to sum up the differences across
multiple events and keep a counter of events as well, and divide in the python
script.

[varunjain, 2013/07/04 16:49:46]

Done.

+  }
+}
+
 }
 namespace content {
 
 RenderWidget::RenderWidget(WebKit::WebPopupType popup_type,
                            const WebKit::WebScreenInfo& screen_info,
                            bool swapped_out)
     : routing_id_(MSG_ROUTING_NONE),
       surface_id_(0),
       webwidget_(NULL),
       opener_id_(MSG_ROUTING_NONE),
@@ skipping 579 matching lines @@
   }
 
   const char* const event_name = GetEventName(input_event->type);
   TRACE_EVENT1("renderer", "RenderWidget::OnHandleInputEvent",
                "event", event_name);
 
   if (compositor_)
     compositor_->SetLatencyInfo(latency_info);
   else
     latency_info_.MergeWith(latency_info);
+  SendToImplThreadLatencyUma(routing_id(), latency_info, input_event->type);
+  UpdateRenderingStatsForAverageImplThreadLatency(routing_id(), latency_info_,

[jbauman, 2013/07/03 20:00:15]

You probably don't want to use latency_info_ here. It won't be updated in the
accelerated compositing case.

[varunjain, 2013/07/04 16:49:46]

Done.

+                                                  software_stats_);
 
   base::TimeDelta now = base::TimeDelta::FromInternalValue(
       base::TimeTicks::Now().ToInternalValue());
 
   int64 delta = static_cast<int64>(
       (now.InSecondsF() - input_event->timeStampSeconds) *
           base::Time::kMicrosecondsPerSecond);
   UMA_HISTOGRAM_CUSTOM_COUNTS("Event.Latency.Renderer", delta, 0, 1000000, 100);
   base::HistogramBase* counter_for_type =
       base::Histogram::FactoryGet(
@@ skipping 1575 matching lines @@
     compositor_->GetRenderingStats(&stats.rendering_stats);
 
   stats.rendering_stats.animation_frame_count +=
       software_stats_.animation_frame_count;
   stats.rendering_stats.screen_frame_count +=
       software_stats_.screen_frame_count;
   stats.rendering_stats.total_paint_time +=
       software_stats_.total_paint_time;
   stats.rendering_stats.total_pixels_painted +=
       software_stats_.total_pixels_painted;
+  stats.rendering_stats.average_impl_thread_to_main_thread_time =
+      software_stats_.average_impl_thread_to_main_thread_time;
 }
 
 bool RenderWidget::GetGpuRenderingStats(GpuRenderingStats* stats) const {
   GpuChannelHost* gpu_channel = RenderThreadImpl::current()->GetGpuChannel();
   if (!gpu_channel)
     return false;
 
   return gpu_channel->CollectRenderingStatsForSurface(surface_id(), stats);
 }
 
@@ skipping 62 matching lines @@
 
   if (!context->InitializeWithDefaultBufferSizes(
           attributes,
           false /* bind generates resources */,
           CAUSE_FOR_GPU_LAUNCH_WEBGRAPHICSCONTEXT3DCOMMANDBUFFERIMPL_INITIALIZE))
     return NULL;
   return context.release();
 }
 
 }  // namespace content