Collecting LatencyInfo in telemetry

tools/perf/metrics/rendering_stats.py

 # Copyright 2013 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.
 
 from operator import attrgetter
 
 
 class RenderingStats(object):
-  def __init__(self, renderer_process, timeline_ranges):
+  def __init__(self, renderer_process, browser_main_thread, timeline_ranges):
     """
     Utility class for extracting rendering statistics from the timeline (or
     other loggin facilities), and providing them in a common format to classes
     that compute benchmark metrics from this data.
 
     Stats can either be numbers, or lists of numbers. Classes that calculate
     metrics from the stats must be able to handle both cases. The length of
     different list stats may vary.
 
     All *_time values are measured in milliseconds.
     """
     assert(len(timeline_ranges) > 0)
     self.renderer_process = renderer_process
+    self.browser_main_thread = browser_main_thread
 
     self.frame_timestamps = []
     self.frame_times = []
     self.paint_time = []
     self.painted_pixel_count = []
     self.record_time = []
     self.recorded_pixel_count = []
     self.rasterize_time = []
     self.rasterized_pixel_count = []
+    self.mouse_wheel_latency = []
+    self.gesture_scroll_latency = []
+    self.touch_scroll_latency = []
 
     for timeline_range in timeline_ranges:
       if timeline_range.is_empty:
         continue
       self.initMainThreadStatsFromTimeline(timeline_range)
       self.initImplThreadStatsFromTimeline(timeline_range)
+      if self.browser_main_thread:
+        self.initInputLatencyFromTimeline(timeline_range)
+
+  def initInputLatencyFromTimeline(self, timeline_range):
+    event_name = "InputLatency"
+    ui_comp_name = 'INPUT_EVENT_LATENCY_UI_COMPONENT'

[nduca, 2014/01/23 18:34:45]

this code is incredibly dense and hard to read and the variable names are hard
to understand. what is a comp_name? remember, your job is not just to make this
work, but to make it so that other people can read this and understand what is
going on.

[Yufeng Shen (Slow to review), 2014/01/30 01:16:05]

I refactored this into a few helper functions, hopefully making this easier to
understand.

+    original_comp_name = 'INPUT_EVENT_LATENCY_ORIGINAL_COMPONENT'
+    begin_comp_name = 'INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT'
+    end_comp_name = 'INPUT_EVENT_LATENCY_TERMINATED_FRAME_SWAP_COMPONENT'
+    mouse_wheel_events = []
+    scroll_events = []
+    for event in self.browser_main_thread.IterAllAsyncSlicesOfName(event_name):

[nduca, 2014/01/23 18:34:45]

i dont get the point of event_name as a variable here, its actually quite
misleading

[nduca, 2014/01/23 18:34:45]

this function should really be split into a few functions so that you can unit
test its pieces. there's one piece that takes a browser_main_thread and gets
produces a class with the different events of interest in different arrays. 

then you might use a
@property
def mouse_wheel_latency_times(self):
  if self._mouse_wheel_latency_times:
     return self._mouse_wheel_latency_times
  .. build _mouse_wheel_latency_times

so that the three loops below are 

then, once you have this, you'll realize that you can write  a unit test for
this entire function without having to create a RenderStats object --- all you
need to do is test the object in isolation. You'll still need a basic test that
the renderstats integration with your new objct works but it'll be better
isolated.

+      if event.start >= timeline_range.min and event.end <= timeline_range.max:
+        for ss in event.sub_slices:
+          if 'step' not in ss.args:
+            continue
+          if 'data' not in ss.args:
+            continue
+          if ss.args['step'] == 'MouseWheel':
+            mouse_wheel_events.append(ss)
+          elif ss.args['step'] == 'GestureScrollUpdate':
+            scroll_events.append(ss)
+
+    # mouse_wheel_latency is the time from when mouse wheel event reaches RWH
+    # to buffer swapped.
+    for event in mouse_wheel_events:
+      data = event.args['data']
+      if begin_comp_name in data and end_comp_name in data:
+        latency = data[end_comp_name]['time'] - data[begin_comp_name]['time']
+        self.mouse_wheel_latency.append(latency / 1000.0)
+
+    # gesture_scroll_latency is the time from when gesture scroll event reaches
+    # RWH to buffer swapped. It is available on all platforms.
+    # touch_scroll_latency is the time from when the touch event is created
+    # to when the buffer swapped due to the scroll generated from the original
+    # touch event. On Aura, the starting timestamp is kept in UI_COMPONENT, and
+    # on Android, the starting timestamp is kept in ORIGINAL_COMPONENT.
+    for event in scroll_events:
+      data = event.args['data']
+      if end_comp_name in data:
+        end_time = data[end_comp_name]['time']
+        if begin_comp_name in data:

[nduca, 2014/01/23 18:34:45]

this huge set of branches shold be broken into a set of helper functions. I
can't understand what is going on here. It looks like you've got a
GetGestureScrollLatencyFromEvent() and a GetTouchScrollLatencyFromEvent() maybe?

+          latency = end_time - data[begin_comp_name]['time']
+          self.gesture_scroll_latency.append(latency / 1000.0)
+        if ui_comp_name in data and original_comp_name in data:
+          raise ValueError, 'LatencyInfo has both UI and ORIGINAL component'
+        if ui_comp_name in data:
+          latency = end_time - data[ui_comp_name]['time']
+          self.touch_scroll_latency.append(latency / 1000.0)
+        elif original_comp_name in data:
+          latency = end_time - data[original_comp_name]['time']
+          self.touch_scroll_latency.append(latency / 1000.0)
 
   def initMainThreadStatsFromTimeline(self, timeline_range):
     event_name = 'BenchmarkInstrumentation::MainThreadRenderingStats'
     events = []
     for event in self.renderer_process.IterAllSlicesOfName(event_name):
       if event.start >= timeline_range.min and event.end <= timeline_range.max:
         if 'data' not in event.args:
           continue
         events.append(event)
     events.sort(key=attrgetter('start'))
@@ skipping 38 matching lines @@
         self.frame_timestamps.append(
             event.start)
         if not first_frame:
           self.frame_times.append(round(self.frame_timestamps[-1] -
                                         self.frame_timestamps[-2], 2))
         first_frame = False
       self.rasterize_time.append(1000.0 *
           event.args['data']['rasterize_time'])
       self.rasterized_pixel_count.append(
           event.args['data']['rasterized_pixel_count'])