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,

[nduca, 2013/07/08 20:58:32]

see you're just using the latency info struct but you'er still doing the probe
here.

your uma should be up in the browser process where you're tracking things about
the input events as they're acked by the host process. the renderer really
shouldn't be doing anything.

[varunjain, 2013/07/10 19:32:37]

Hi Nat, while I am looking into how to plumb the latency info back into the
browser, I wanted to ask why is it wrong to do this in the renderer? Especially
because this metric measures latency that exists entirely in the renderer. We
are recording other UMA stats in render_widget, so why is this one not allowed?

+                                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.total_impl_thread_to_main_thread_time +=
+        (receive_component.event_time - dispatch_component.event_time);
+    stats.total_impl_thread_to_main_thread_count++;
+  }
+}
+
 }
 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,
+                                                  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.total_impl_thread_to_main_thread_count +=
+      software_stats_.total_impl_thread_to_main_thread_count;
+  stats.rendering_stats.total_impl_thread_to_main_thread_time +=
+      software_stats_.total_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