Add UMA/Telemetry stats for touch event latency

content/browser/renderer_host/render_widget_host_impl.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/browser/renderer_host/render_widget_host_impl.h"
 
 #include <math.h>
 #include <utility>
 
 #include "base/auto_reset.h"
@@ skipping 2547 matching lines @@
   if (!should_auto_resize_)
     return;
 
   OnRenderAutoResized(new_size);
 }
 
 void RenderWidgetHostImpl::DetachDelegate() {
   delegate_ = NULL;
 }
 
+void RenderWidgetHostImpl::ComputeTouchLatency(
+    const ui::LatencyInfo& latency_info) {
+  typedef ui::LatencyInfo::LatencyMap::const_iterator LatencyIter;
+  const ui::LatencyInfo::LatencyMap& latency_map =
+      latency_info.latency_components;
+
+  LatencyIter original_it = latency_map.find(std::make_pair(

[Rick Byers, 2013/06/26 16:34:55]

I think it would be a little cleaner to add a LatencyInfo::Lookup API that
returns a reference to the entry with the given component+id.

[Yufeng Shen (Slow to review), 2013/06/26 20:44:05]

Done.

+      ui::INPUT_EVENT_LATENCY_ORIGINAL_COMPONENT, 0));

[Rick Byers, 2013/06/26 16:34:55]

Are we guaranteed to have this (eg. for synthetic events)?  I'd prefer to skip
reporting metrics when we don't have reliable data, then to try to ensure we've
always got values even when that means putting some fake value in (i.e. the
timestamp the event was created in software).

[Yufeng Shen (Slow to review), 2013/06/26 20:44:05]

Done.

+
+  LatencyIter ui_it = latency_map.find(std::make_pair(

[jbauman, 2013/06/26 08:52:53]

Is it guaranteed that there will be at most one
INPUT_EVENT_LATENCY_UI_COMPONENT, INPUT_EVENT_LATENCY_RWH_COMPONENT, and
INPUT_EVENT_LATENCY_ACKED_COMPONENT that contributes to a LatencyInfo? E.g.
we'll never coalesce two LatencyInfos that each contain one of these? If so, you
should add a DCHECK that the event_count == 1 for these. If not, this logic is
likely to be wrong, because the latency calculations won't make sense.

[Yufeng Shen (Slow to review), 2013/06/26 20:44:05]

This should be true. This function, ComputeTouchLatency(), is called on
TouchEvent that are not coalesced. So the the latency info for the touch event
should have exactly 1 INPUT_EVENT_LATENCY_UI_COMPONENT,
INPUT_EVENT_LATENCY_RWH_COMPONENT and INPUT_EVENT_LATENCY_ACKED_COMPONENT.
A DCHECK() is added.

+      ui::INPUT_EVENT_LATENCY_UI_COMPONENT, 0));
+
+  LatencyIter rwh_it = latency_map.find(std::make_pair(
+      ui::INPUT_EVENT_LATENCY_RWH_COMPONENT,
+      GetLatencyComponentId()));
+
+  LatencyIter acked_consumed_it = latency_map.find(std::make_pair(
+      ui::INPUT_EVENT_LATENCY_ACKED_COMPONENT,
+      INPUT_EVENT_ACK_STATE_CONSUMED));
+
+  LatencyIter acked_not_consumed_it = latency_map.find(std::make_pair(
+      ui::INPUT_EVENT_LATENCY_ACKED_COMPONENT,
+      INPUT_EVENT_ACK_STATE_NOT_CONSUMED));
+
+  LatencyIter acked_no_consumer_it = latency_map.find(std::make_pair(
+      ui::INPUT_EVENT_LATENCY_ACKED_COMPONENT,
+      INPUT_EVENT_ACK_STATE_NO_CONSUMER_EXISTS));
+
+  base::TimeDelta system_delta =
+      ui_it->second.event_time - original_it->second.event_time;
+  rendering_stats_.touch_system_count++;
+  rendering_stats_.total_touch_system_latency += system_delta;
+  UMA_HISTOGRAM_CUSTOM_COUNTS(
+      "Event.Latency.Touch.System",

[jbauman, 2013/06/26 08:52:53]

This is kind of weird, because we're making a histogram from the averaged
latency between all the input events that contributed to this. But I guess it
might work for you.

[Rick Byers, 2013/06/26 16:34:55]

Yeah, I'm very worried about relying on these averaged timestamps.  One option
is to report the histogram only when the event_count is 1, but then I'd also
want some assurance that that is representative (eg. another histogram showing
that >50% of the time we have only 1 event).

Alternately we could always report histograms for pairs of time points that
don't have coalescing between them (i.e. send the UMA when the 2nd element in
the pair is added to the LatencyInfo).

[Rick Byers, 2013/06/26 16:34:55]

Isn't Event.Latency.Touch.System basically the same as our existing
Event.Latency.Browser.ET_TOUCH_MOVED?  I'm not opposed to having some redundancy
(eg. to validate that LatencyInfo agrees with our existing measures), but I
don't see much additional value.

[Yufeng Shen (Slow to review), 2013/06/26 20:44:05]

removed.

[Yufeng Shen (Slow to review), 2013/06/26 20:44:05]

As comment above, there is no coalesce or latency info merge happening when
this function is called, so the histogram should be truly from individual
samples.

[Yufeng Shen (Slow to review), 2013/06/26 20:44:05]

I think it is already taking the alternative approach you suggested.
This function is called right after the ACKED_XXX_COMPONENT is added to
the latency info, and as comments to John's question that there is no
average for UI/RWH_COMPONENT 

[Rick Byers, 2013/06/26 21:42:10]

Ah, sorry - perfect, thanks!

+      system_delta.InMicroseconds(),
+      0,
+      20000,
+      100);
+
+  base::TimeDelta ui_delta =
+      rwh_it->second.event_time - ui_it->second.event_time;
+  rendering_stats_.touch_ui_count++;
+  rendering_stats_.total_touch_ui_latency += ui_delta;
+  UMA_HISTOGRAM_CUSTOM_COUNTS(

[Rick Byers, 2013/06/26 16:34:55]

It would be cleaner to use a common macro for all of these.  I think Varun had a
CL up that added UMA_HISTOGRAM_SHORT_TIMES.

[Yufeng Shen (Slow to review), 2013/06/26 20:44:05]

As the reviewer for his CL points out that there is resolution issue with
UMA_HISTOGRAM_SHORT_TIMES, particularly when you adding sample using TimeDelta,
only the milliseconds are extracted from TimeDelta. That's why
I am using  UMA_HISTOGRAM_CUSTOM_COUNTS() to take out the microseconds from
sample instead of UMA_HISTOGRAM_CUSTOM_TIMES().

We will see. If varun can resolve the issue before this CL passed review, I will
change to his macro.

+      "Event.Latency.Touch.UI",
+      ui_delta.InMicroseconds(),
+      0,
+      20000,
+      100);
+
+  if (acked_consumed_it != latency_map.end()) {
+    base::TimeDelta acked_delta =
+        acked_consumed_it->second.event_time - rwh_it->second.event_time;
+    rendering_stats_.touch_acked_consumed_count++;
+    rendering_stats_.total_touch_acked_consumed_latency += acked_delta;
+    UMA_HISTOGRAM_CUSTOM_COUNTS(
+        "Event.Latency.Touch.Acked_Consumed",
+        acked_delta.InMicroseconds(),
+        0,
+        100000,
+        100);
+  } else if (acked_not_consumed_it != latency_map.end()) {
+    base::TimeDelta acked_delta =
+        acked_not_consumed_it->second.event_time - rwh_it->second.event_time;
+    rendering_stats_.touch_acked_not_consumed_count++;
+    rendering_stats_.total_touch_acked_not_consumed_latency += acked_delta;
+    UMA_HISTOGRAM_CUSTOM_COUNTS(
+        "Event.Latency.Touch.Acked_Not_Consumed",
+        acked_delta.InMicroseconds(),
+        0,
+        100000,
+        100);
+  } else if (acked_no_consumer_it != latency_map.end()) {
+    base::TimeDelta acked_delta =
+        acked_no_consumer_it->second.event_time - rwh_it->second.event_time;
+    rendering_stats_.touch_acked_no_consumer_count++;
+    rendering_stats_.total_touch_acked_no_consumer_latency += acked_delta;
+    UMA_HISTOGRAM_CUSTOM_COUNTS(
+        "Event.Latency.Touch.Acked_No_Consumer_Exists",

[Rick Byers, 2013/06/26 16:34:55]

Separating out the metrics into the 3 ACK states is an interesting idea.  I'm
not convinced we'll learn something interesting, but we can give it a shot and
see what we learn.  Perhaps update the touch scroll latency doc with your ideas
here?

[Yufeng Shen (Slow to review), 2013/06/26 20:44:05]

will do

+        acked_delta.InMicroseconds(),
+        0,
+        100000,
+        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(
           ui::INPUT_EVENT_LATENCY_RWH_COMPONENT, GetLatencyComponentId()));
   if (l == latency_info.latency_components.end())
     return;
 
   rendering_stats_.input_event_count += l->second.event_count;
   rendering_stats_.total_input_latency +=
       l->second.event_count *
@@ skipping 18 matching lines @@
     int process_id = (b->first.second >> 32) & 0xffffffff;
     RenderWidgetHost* rwh =
         RenderWidgetHost::FromID(process_id, routing_id);
     if (!rwh)
       continue;
     RenderWidgetHostImpl::From(rwh)->FrameSwapped(latency_info);
   }
 }
 
 }  // namespace content