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

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 bb06cfe956eaafc0f7e210d0a5f394ea25c9ea6a..c31b4c4bbb9fc1f27b0087760272174d7c0e90d2 100644
--- a/content/renderer/render_widget.cc
+++ b/content/renderer/render_widget.cc
@@ -139,6 +139,55 @@ const char* GetEventName(WebInputEvent::Type type) {
 #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 {
 
@@ -738,6 +787,9 @@ void RenderWidget::OnHandleInputEvent(const WebKit::WebInputEvent* input_event,
     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());
@@ -2333,6 +2385,8 @@ void RenderWidget::GetRenderingStats(
       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 {