Add UMA/Telemetry stats for touch event latency

    
This CL adds following UMA stats for touch event latency
1. Event.Latency.Browser.TouchUI:
   touch event received by Chrome -> touch event sent to renderer
    
2. Event.Latency.Browser.TouchAcked
   touch event sent to renderer -> touch event acked from renderer
    
Corresponding telemetry stats are also added.
    
BUG=chromium:246034
TEST=1. Check UMA stats exist in chrome://histograms/Event.Latency.Browser
     2. Check the relevant stats are in telemetry smoothness test.

Review URL: https://chromiumcodereview.appspot.com/17757002

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@209255 0039d316-1c4b-4281-b951-d872f2087c98

11 files changed, 112 insertions, 28 deletions

diff --git a/content/browser/renderer_host/render_widget_host_impl.cc b/content/browser/renderer_host/render_widget_host_impl.cc
index 630bf70..8b30f4c 100644
--- a/content/browser/renderer_host/render_widget_host_impl.cc
+++ b/content/browser/renderer_host/render_widget_host_impl.cc
@@ -1114,8 +1114,9 @@ void RenderWidgetHostImpl::ForwardGestureEventWithLatencyInfo(
   // In Aura, gesture event will carry its original touch event's
   // INPUT_EVENT_LATENCY_RWH_COMPONENT. For non-aura platform, we add the
   // INPUT_EVENT_LATENCY_RWH_COMPONENT right here.
-  if (!ui_latency.HasLatencyComponent(ui::INPUT_EVENT_LATENCY_RWH_COMPONENT,
-                                      GetLatencyComponentId()))
+  if (!ui_latency.FindLatency(ui::INPUT_EVENT_LATENCY_RWH_COMPONENT,
+                              GetLatencyComponentId(),
+                              NULL))
     latency_info = NewInputLatencyInfo();
 
   latency_info.AddLatencyNumber(ui::INPUT_EVENT_LATENCY_INJECTED_RWH_COMPONENT,
@@ -1296,8 +1297,9 @@ void RenderWidgetHostImpl::SendInputEvent(const WebInputEvent& input_event,
                                           int event_size,
                                           const ui::LatencyInfo& latency_info,
                                           bool is_keyboard_shortcut) {
-  DCHECK(latency_info.HasLatencyComponent(ui::INPUT_EVENT_LATENCY_RWH_COMPONENT,
-                                          GetLatencyComponentId()));
+  DCHECK(latency_info.FindLatency(ui::INPUT_EVENT_LATENCY_RWH_COMPONENT,
+                                  GetLatencyComponentId(),
+                                  NULL));
   input_event_start_time_ = TimeTicks::Now();
   Send(new InputMsg_HandleInputEvent(
       routing_id_, &input_event, latency_info, is_keyboard_shortcut));
@@ -2584,6 +2586,55 @@ void RenderWidgetHostImpl::DetachDelegate() {
   delegate_ = NULL;
 }
 
+void RenderWidgetHostImpl::ComputeTouchLatency(
+    const ui::LatencyInfo& latency_info) {
+  ui::LatencyInfo::LatencyComponent ui_component;
+  ui::LatencyInfo::LatencyComponent rwh_component;
+  ui::LatencyInfo::LatencyComponent acked_component;
+
+  if (!latency_info.FindLatency(ui::INPUT_EVENT_LATENCY_UI_COMPONENT,
+                                0,
+                                &ui_component) ||
+      !latency_info.FindLatency(ui::INPUT_EVENT_LATENCY_RWH_COMPONENT,
+                                GetLatencyComponentId(),
+                                &rwh_component))
+    return;
+
+  DCHECK(ui_component.event_count == 1);
+  DCHECK(rwh_component.event_count == 1);
+
+  base::TimeDelta ui_delta =
+      rwh_component.event_time - ui_component.event_time;
+  rendering_stats_.touch_ui_count++;
+  rendering_stats_.total_touch_ui_latency += ui_delta;
+  UMA_HISTOGRAM_CUSTOM_COUNTS(
+      "Event.Latency.Browser.TouchUI",
+      ui_delta.InMicroseconds(),
+      0,
+      20000,
+      100);
+
+  if (latency_info.FindLatency(ui::INPUT_EVENT_LATENCY_ACKED_COMPONENT,
+                               0,
+                               &acked_component)) {
+    DCHECK(acked_component.event_count == 1);
+    base::TimeDelta acked_delta =
+        acked_component.event_time - rwh_component.event_time;
+    rendering_stats_.touch_acked_count++;
+    rendering_stats_.total_touch_acked_latency += acked_delta;
+    UMA_HISTOGRAM_CUSTOM_COUNTS(
+        "Event.Latency.Browser.TouchAcked",
+        acked_delta.InMicroseconds(),
+        0,
+        1000000,
+        100);
+  }
+
+  if (CommandLine::ForCurrentProcess()->HasSwitch(
+          switches::kEnableGpuBenchmarking))
+    Send(new ViewMsg_SetBrowserRenderingStats(routing_id_, rendering_stats_));
+}
+
 void RenderWidgetHostImpl::FrameSwapped(const ui::LatencyInfo& latency_info) {
   ui::LatencyInfo::LatencyMap::const_iterator l =
       latency_info.latency_components.find(std::make_pair(
diff --git a/content/browser/renderer_host/render_widget_host_impl.h b/content/browser/renderer_host/render_widget_host_impl.h
index 50851c9..5aa6a96 100644
--- a/content/browser/renderer_host/render_widget_host_impl.h
+++ b/content/browser/renderer_host/render_widget_host_impl.h
@@ -498,6 +498,7 @@ class CONTENT_EXPORT RenderWidgetHostImpl : virtual public RenderWidgetHost,
   // other way around.
   bool should_auto_resize() { return should_auto_resize_; }
 
+  void ComputeTouchLatency(const ui::LatencyInfo& latency_info);
   void FrameSwapped(const ui::LatencyInfo& latency_info);
 
   // Returns the ID that uniquely describes this component to the latency
diff --git a/content/browser/renderer_host/render_widget_host_view_aura.cc b/content/browser/renderer_host/render_widget_host_view_aura.cc
index f051aae..b72907b 100644
--- a/content/browser/renderer_host/render_widget_host_view_aura.cc
+++ b/content/browser/renderer_host/render_widget_host_view_aura.cc
@@ -1801,10 +1801,6 @@ void RenderWidgetHostViewAura::ProcessAckedTouchEvent(
       INPUT_EVENT_ACK_STATE_CONSUMED) ? ui::ER_HANDLED : ui::ER_UNHANDLED;
   for (ScopedVector<ui::TouchEvent>::iterator iter = events.begin(),
       end = events.end(); iter != end; ++iter) {
-    (*iter)->latency()->AddLatencyNumber(
-        ui::INPUT_EVENT_LATENCY_ACKED_COMPONENT,
-        static_cast<int64>(ack_result),
-        0);
     root->ProcessedTouchEvent((*iter), window_, result);
   }
 }
diff --git a/content/browser/renderer_host/render_widget_host_view_win.cc b/content/browser/renderer_host/render_widget_host_view_win.cc
index d19a1e8..7186313 100644
--- a/content/browser/renderer_host/render_widget_host_view_win.cc
+++ b/content/browser/renderer_host/render_widget_host_view_win.cc
@@ -935,10 +935,6 @@ void RenderWidgetHostViewWin::ProcessAckedTouchEvent(
       INPUT_EVENT_ACK_STATE_CONSUMED) ? ui::ER_HANDLED : ui::ER_UNHANDLED;
   for (ScopedVector<ui::TouchEvent>::iterator iter = events.begin(),
       end = events.end(); iter != end; ++iter)  {
-    (*iter)->latency()->AddLatencyNumber(
-        ui::INPUT_EVENT_LATENCY_ACKED_COMPONENT,
-        static_cast<int64>(ack_result),
-        0);
     scoped_ptr<ui::GestureRecognizer::Gestures> gestures;
     gestures.reset(gesture_recognizer_->ProcessTouchEventForGesture(
         *(*iter), result, this));
diff --git a/content/browser/renderer_host/touch_event_queue.cc b/content/browser/renderer_host/touch_event_queue.cc
index cdabd15..6878811 100644
--- a/content/browser/renderer_host/touch_event_queue.cc
+++ b/content/browser/renderer_host/touch_event_queue.cc
@@ -190,6 +190,10 @@ void TouchEventQueue::PopTouchEventToView(InputEventAckState ack_result) {
   for (WebTouchEventWithLatencyList::const_iterator iter = acked_event->begin(),
        end = acked_event->end();
        iter != end; ++iter) {
+    ui::LatencyInfo* latency = const_cast<ui::LatencyInfo*>(&(iter->latency));
+    latency->AddLatencyNumber(
+        ui::INPUT_EVENT_LATENCY_ACKED_COMPONENT, 0, 0);
+    render_widget_host_->ComputeTouchLatency(*latency);
     view->ProcessAckedTouchEvent((*iter), ack_result);
   }
 }
diff --git a/content/common/browser_rendering_stats.cc b/content/common/browser_rendering_stats.cc
index 87e3857..0ead3c7 100644
--- a/content/common/browser_rendering_stats.cc
+++ b/content/common/browser_rendering_stats.cc
@@ -6,7 +6,11 @@
 
 namespace content {
 
-BrowserRenderingStats::BrowserRenderingStats() : input_event_count(0) {}
+BrowserRenderingStats::BrowserRenderingStats() :
+    input_event_count(0),
+    touch_ui_count(0),
+    touch_acked_count(0) {
+}
 
 BrowserRenderingStats::~BrowserRenderingStats() {}
 
@@ -14,6 +18,14 @@ void BrowserRenderingStats::EnumerateFields(
     cc::RenderingStats::Enumerator* enumerator) const {
   enumerator->AddInt("inputEventCount", input_event_count);
   enumerator->AddTimeDeltaInSecondsF("totalInputLatency", total_input_latency);
+
+  enumerator->AddInt("touchUICount", touch_ui_count);
+  enumerator->AddTimeDeltaInSecondsF("totalTouchUILatency",
+                                     total_touch_ui_latency);
+
+  enumerator->AddInt("touchAckedCount", touch_acked_count);
+  enumerator->AddTimeDeltaInSecondsF("totalTouchAckedLatency",
+                                     total_touch_acked_latency);
 }
 
 }  // namespace content
diff --git a/content/common/browser_rendering_stats.h b/content/common/browser_rendering_stats.h
index ce20158..9760054 100644
--- a/content/common/browser_rendering_stats.h
+++ b/content/common/browser_rendering_stats.h
@@ -18,6 +18,10 @@ struct CONTENT_EXPORT BrowserRenderingStats {
   uint32 input_event_count;
   base::TimeDelta total_input_latency;
 
+  uint32 touch_ui_count;
+  base::TimeDelta total_touch_ui_latency;
+  uint32 touch_acked_count;
+  base::TimeDelta total_touch_acked_latency;
   // Note: when adding new members, please remember to update enumerateFields
   // in browser_rendering_stats.cc.
 
diff --git a/content/common/view_messages.h b/content/common/view_messages.h
index fc26803..b4074bf 100644
--- a/content/common/view_messages.h
+++ b/content/common/view_messages.h
@@ -303,6 +303,10 @@ IPC_STRUCT_TRAITS_END()
 IPC_STRUCT_TRAITS_BEGIN(content::BrowserRenderingStats)
   IPC_STRUCT_TRAITS_MEMBER(input_event_count)
   IPC_STRUCT_TRAITS_MEMBER(total_input_latency)
+  IPC_STRUCT_TRAITS_MEMBER(touch_ui_count)
+  IPC_STRUCT_TRAITS_MEMBER(total_touch_ui_latency)
+  IPC_STRUCT_TRAITS_MEMBER(touch_acked_count)
+  IPC_STRUCT_TRAITS_MEMBER(total_touch_acked_latency)
 IPC_STRUCT_TRAITS_END()
 
 IPC_STRUCT_BEGIN(ViewHostMsg_CreateWindow_Params)
diff --git a/tools/perf/measurements/smoothness.py b/tools/perf/measurements/smoothness.py
index 7ca8d69..80b7cd6 100644
--- a/tools/perf/measurements/smoothness.py
+++ b/tools/perf/measurements/smoothness.py
@@ -142,18 +142,23 @@ def CalcAnalysisResults(rendering_stats_deltas, results):
               averageAnalysisTimeMS,
               data_type='unimportant')
 
-def CalcLatencyResults(rendering_stats_deltas, results):
-  inputEventCount = rendering_stats_deltas.get(
-      'inputEventCount', 0)
-  totalInputLatencyInSeconds = rendering_stats_deltas.get(
-      'totalInputLatency', 0)
-
+def CalcLatency(rendering_stats_deltas, count_name, total_latency_name,
+                result_name, results):
+  eventCount = rendering_stats_deltas.get(count_name, 0)
+  totalLatencyInSeconds = rendering_stats_deltas.get(total_latency_name, 0)
   averageLatency = DivideIfPossibleOrZero(
-      (totalInputLatencyInSeconds * 1000), inputEventCount)
-
-  results.Add('average_latency', 'ms', averageLatency,
-              data_type='unimportant')
+      (totalLatencyInSeconds * 1000), eventCount)
+  results.Add(result_name, 'ms', averageLatency, data_type='unimportant')
 
+def CalcLatencyResults(rendering_stats_deltas, results):
+  CalcLatency(rendering_stats_deltas, 'inputEventCount', 'totalInputLatency',
+              'average_latency', results)
+  CalcLatency(rendering_stats_deltas, 'touchUICount', 'totalTouchUILatency',
+              'average_touch_ui_latency', results)
+  CalcLatency(rendering_stats_deltas, 'touchAckedCount',
+              'totalTouchAckedLatency',
+              'average_touch_acked_latency',
+              results)
 
 class Smoothness(page_measurement.PageMeasurement):
   def __init__(self):
diff --git a/ui/base/latency_info.cc b/ui/base/latency_info.cc
index f87f6df..459fc2a 100644
--- a/ui/base/latency_info.cc
+++ b/ui/base/latency_info.cc
@@ -58,10 +58,16 @@ void LatencyInfo::AddLatencyNumberWithTimestamp(LatencyComponentType component,
   }
 }
 
-bool LatencyInfo::HasLatencyComponent(LatencyComponentType type,
-                                      int64 id) const {
-  return latency_components.find(std::make_pair(type, id)) !=
-      latency_components.end();
+bool LatencyInfo::FindLatency(LatencyComponentType type,
+                              int64 id,
+                              LatencyComponent* output) const {
+  LatencyMap::const_iterator it = latency_components.find(
+      std::make_pair(type, id));
+  if (it == latency_components.end())
+    return false;
+  if (output)
+    *output = it->second;
+  return true;
 }
 
 void LatencyInfo::Clear() {
diff --git a/ui/base/latency_info.h b/ui/base/latency_info.h
index a5fe13b..423182a 100644
--- a/ui/base/latency_info.h
+++ b/ui/base/latency_info.h
@@ -72,7 +72,12 @@ struct UI_EXPORT LatencyInfo {
                                      base::TimeTicks time,
                                      uint32 event_count);
 
-  bool HasLatencyComponent(LatencyComponentType type, int64 id) const;
+  // Returns true if the a component with |type| and |id| is found in
+  // the latency_components and the component is stored to |output| if
+  // |output| is not NULL. Returns false if no such component is found.
+  bool FindLatency(LatencyComponentType type,
+                   int64 id,
+                   LatencyComponent* output) const;
 
   void Clear();