Android: start upstreaming some of our perf tests.

build/android/pylib/surface_stats_collector.py

+# 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.
+
+import Queue
+import datetime
+import logging
+import re
+import threading
+
+from pylib import perf_tests_helper
+
+
+# Log marker containing SurfaceTexture timestamps.
+_SURFACE_TEXTURE_TIMESTAMPS_MESSAGE = 'SurfaceTexture update timestamps'
+_SURFACE_TEXTURE_TIMESTAMP_RE = '\d+'
+
+
+class SurfaceStatsCollector(object):
+  """Collects surface stats for a window from the output of SurfaceFlinger.
+
+  Args:
+    adb: the adb coonection to use.
+    window_package: Package name of the window.
+    window_activity: Activity name of the window.
+  """
+  def __init__(self, adb, window_package, window_activity):
+    self._adb = adb
+    self._window_package = window_package
+    self._window_activity = window_activity
+    self._collector_thread = None
+    self._use_legacy_method = False
+    self._surface_before = None
+    self._get_data_event = None
+    self._data_queue = None
+    self._stop_event = None
+
+  def Start(self):
+    assert not self._collector_thread
+
+    if self._ClearSurfaceFlingerLatencyData():
+      self._get_data_event = threading.Event()
+      self._stop_event = threading.Event()
+      self._data_queue = Queue.Queue()
+      self._collector_thread = threading.Thread(target=self._CollectorThread)
+      self._collector_thread.start()
+      self._adb.StartRecordingLogcat(clear=False)
+    else:
+      self._use_legacy_method = True
+      self._surface_before = self._GetSurfaceStatsLegacy()
+
+  def Stop(self):
+    if self._collector_thread:
+      self._stop_event.set()
+      self._collector_thread.join()
+      self._collector_thread = None
+
+  def PrintPerfResults(self, trace_tag):
+    if self._use_legacy_method:
+      surface_after = self._GetSurfaceStatsLegacy()
+      td = surface_after['timestamp'] - self._surface_before['timestamp']
+      seconds = td.seconds + td.microseconds / 1e6
+      frame_count = (surface_after['page_flip_count'] -
+                     self._surface_before['page_flip_count'])
+    else:
+      assert self._collector_thread
+      (seconds, latencies, app_timestamps) = self._GetDataFromThread()
+      if not seconds or not len(latencies):
+        logging.warning('Surface stat data is empty')
+        return
+
+      renderer_timestamps = self._CollectSurfaceTextureTimestamps()

[Sami, 2012/10/18 11:35:57]

This bit depends on the browser sending us timestamps from the SurfaceTexture.
Since it seems like we're moving away from the SurfaceTexture architecture, I'd
drop this part.

That's not to say the data it collects isn't useful. I think we should have a
way to measure various internal compositor latencies once we dust settles on the
architecture front.

[bulach, 2012/10/18 12:33:56]

thanks for the clarification sami! it simplifies this class a lot!

+      if not renderer_timestamps:
+        logging.warning('No renderer timestamp data')
+      elif app_timestamps:
+        dropped_frames, repeated_frames, use_count = \
+            self._CalculateDroppedAndRepeatedFrames(app_timestamps,
+                                                    renderer_timestamps)
+        perf_tests_helper.PrintPerfResult(
+            'dropped_frames', 'dropped_frames' + trace_tag,
+            [100.0 * dropped_frames / len(use_count)], 'percent')
+        perf_tests_helper.PrintPerfResult(
+            'repeated_frames', 'repeated_frames' + trace_tag,
+            [100.0 * repeated_frames / len(use_count)], 'percent')
+        perf_tests_helper.PrintPerfResult(
+            'frame_use_count', 'frame_use_count' + trace_tag, use_count, '')
+
+      frame_count = len(latencies)
+      jitter_count = 0
+      last_latency = latencies[0]
+      for latency in latencies[1:]:
+        if latency > last_latency:
+          jitter_count = jitter_count + 1
+        last_latency = latency
+
+      perf_tests_helper.PrintPerfResult(
+          'surface_latencies', 'surface_latencies' + trace_tag, latencies, '')
+      perf_tests_helper.PrintPerfResult(
+          'peak_jitter', 'peak_jitter' + trace_tag, [max(latencies)], '')
+      perf_tests_helper.PrintPerfResult(
+          'jitter_percent', 'jitter_percent' + trace_tag,
+          [jitter_count * 100.0 / frame_count], 'percent')
+
+    print 'SurfaceMonitorTime: %fsecs' % seconds
+    perf_tests_helper.PrintPerfResult(
+        'avg_surface_fps', 'avg_surface_fps' + trace_tag,
+        [int(round(frame_count / seconds))], 'fps')
+
+  def _CollectSurfaceTextureTimestamps(self):
+    """Extracts Surface Texture timestamps from logcat messages as generated by
+       --log-fps.
+
+    Returns:
+      A list of integer time stamps sorted in ascending order.
+    """
+    record = self._adb.StopRecordingLogcat()
+    timestamp_lines = self._adb.SearchLogcatRecord(record,
+        _SURFACE_TEXTURE_TIMESTAMPS_MESSAGE)
+    timestamps = []
+    for line in timestamp_lines:
+      for match in re.findall(_SURFACE_TEXTURE_TIMESTAMP_RE, line['message']):
+        timestamp = long(match)
+        # TODO(skyostil): Figure out why the first two timestamps are zero.
+        if timestamp > 0:
+          timestamps.append(timestamp)
+    timestamps.sort()
+    return timestamps
+
+  @staticmethod
+  def _CalculateDroppedAndRepeatedFrames(app_timestamps, renderer_timestamps):
+    """Calculate the number of dropped and repeated renderer frames. This is
+       done by calculating which renderer produced frame is used in each
+       application produced frame. To reduce false positives, only the
+       intersection of the timestamp ranges is examined.
+
+    Args:
+      app_timestamps: A sorted list of application frame timestamps.
+      renderer_timestamps: A sorted list of renderer frame timestamps.
+
+    Returns:
+      A tuple containing dropped and repeated frame counts and list of integer
+      use counts for every renderer frame in the examined range.
+    """
+    # Reduce the timestamps to the intersection of both sequences.
+    min_app, max_app = app_timestamps[0], app_timestamps[-1]
+    min_renderer, max_renderer = renderer_timestamps[0], renderer_timestamps[-1]
+    min_time = max(min_app, min_renderer)
+    max_time = min(max_app, max_renderer)
+    def FindFirstIndexOver(timestamps, min_time):
+      for i in range(len(timestamps)):
+        if timestamps[i] >= min_time:
+          return i
+    def FindLastIndexUnder(timestamps, max_time):
+      for i in range(len(timestamps) - 1, 0, -1):
+        if timestamps[i] <= max_time:
+          return i
+    def Intersect(timestamps, min_time, max_time):
+      min_index = FindFirstIndexOver(timestamps, min_time)
+      max_index = FindLastIndexUnder(timestamps, max_time)
+      if min_index is None or max_index is None:
+        return []
+      return timestamps[min_index:max_index + 1]
+    app_timestamps = Intersect(app_timestamps, min_time, max_time)
+    renderer_timestamps = Intersect(renderer_timestamps, min_time, max_time)
+
+    # Discard the last renderer frame because any app frame consuming it will be
+    # outside the intersected range.
+    renderer_timestamps = renderer_timestamps[:-1]
+
+    # If there was no common time interval, bail out.
+    if not app_timestamps or not renderer_timestamps:
+      return (0, 0, [0])
+
+    renderer_frame_use_count = dict((t, 0) for t in renderer_timestamps)
+    for app_time in app_timestamps:
+      # Find out which renderer frame was used to draw this app frame.
+      for renderer_time in reversed(renderer_timestamps):
+        if renderer_time < app_time:
+          renderer_frame_use_count[renderer_time] += 1
+          break
+
+    # Calculate statistics on dropped and repeated frames.
+    dropped_frames = 0
+    repeated_frames = 0
+    for renderer_time, use_count in renderer_frame_use_count.items():
+      if use_count == 0:
+        dropped_frames += 1
+      elif use_count > 1:
+        repeated_frames += use_count - 1
+    return (dropped_frames, repeated_frames, renderer_frame_use_count.values())
+
+  def _CollectorThread(self):
+    last_timestamp = 0
+    first_timestamp = 0
+    latencies = []
+    timestamps = []
+
+    while not self._stop_event.is_set():
+      self._get_data_event.wait(1)
+      try:
+        (t, last_timestamp) = self._GetSurfaceFlingerLatencyData(last_timestamp,
+                                                                 latencies,
+                                                                 timestamps)
+        if not first_timestamp:
+          first_timestamp = t
+
+        if self._get_data_event.is_set():
+          self._get_data_event.clear()
+          self._data_queue.put(((last_timestamp - first_timestamp) / 1e9,
+                                latencies, timestamps))
+          latencies = []
+          timestamps = []
+          first_timestamp = 0
+      except Exception as e:
+        # On any error, before aborting, put the exception into _data_queue to
+        # prevent the main thread from waiting at _data_queue.get() infinitely.
+        self._data_queue.put(e)
+        raise
+
+  def _GetDataFromThread(self):
+    self._get_data_event.set()
+    ret = self._data_queue.get()
+    if isinstance(ret, Exception):
+      raise ret
+    return ret
+
+  def _ClearSurfaceFlingerLatencyData(self):
+    """Clears the SurfaceFlinger latency data.
+
+    Returns:
+      True if SurfaceFlinger latency is supported by the device, otherwise
+      False.
+    """
+    # The command returns nothing if it is supported, otherwise returns many
+    # lines of result just like 'dumpsys SurfaceFlinger'.
+    results = self._adb.RunShellCommand(
+        'dumpsys SurfaceFlinger --latency-clear %s/%s' %
+        (self._window_package, self._window_activity))
+    return not len(results)
+
+  def _GetSurfaceFlingerLatencyData(self, previous_timestamp, latencies,
+                                    timestamps):
+    """Returns collected SurfaceFlinger latency data.
+
+    Args:
+      previous_timestamp: The timestamp returned from the previous call or 0.
+          Only data after this timestamp will be returned.
+      latencies: A list to receive latency data. The latencies are integers
+          each of which is the number of refresh periods of each frame.
+      timestamps: A list to receive timestamp data. The timestamps indicate
+          when the application started drawing each frame.
+
+    Returns:
+      A tuple containing:
+      - The timestamp of the beginning of the first frame (ns),
+      - The timestamp of the end of the last frame (ns).
+
+    Raises:
+      Exception if failed to run the SurfaceFlinger command or SurfaceFlinger
+          returned invalid result.
+    """
+    # adb shell dumpsys SurfaceFlinger --latency <window name>
+    # prints some information about the last 128 frames displayed in
+    # that window.
+    # The data returned looks like this:
+    # 16954612
+    # 7657467895508   7657482691352   7657493499756
+    # 7657484466553   7657499645964   7657511077881
+    # 7657500793457   7657516600576   7657527404785
+    # (...)
+    #
+    # The first line is the refresh period (here 16.95 ms), it is followed
+    # by 128 lines w/ 3 timestamps in nanosecond each:
+    # A) when the app started to draw
+    # B) the vsync immediately preceding SF submitting the frame to the h/w
+    # C) timestamp immediately after SF submitted that frame to the h/w
+    #
+    # The difference between the 1st and 3rd timestamp is the frame-latency.
+    # An interesting data is when the frame latency crosses a refresh period
+    # boundary, this can be calculated this way:
+    #
+    # ceil((C - A) / refresh-period)
+    #
+    # (each time the number above changes, we have a "jank").
+    # If this happens a lot during an animation, the animation appears
+    # janky, even if it runs at 60 fps in average.
+    results = self._adb.RunShellCommand(
+        'dumpsys SurfaceFlinger --latency %s/%s' %
+        (self._window_package, self._window_activity), log_result=True)
+    assert len(results)
+
+    refresh_period = int(results[0])
+    last_timestamp = previous_timestamp
+    first_timestamp = 0
+    for line in results[1:]:
+      fields = line.split()
+      if len(fields) == 3:
+        timestamp = long(fields[0])
+        last_timestamp = long(fields[2])
+        if (timestamp > previous_timestamp):
+          if not first_timestamp:
+            first_timestamp = timestamp
+          # This is integral equivalent of ceil((C-A) / refresh-period)
+          latency_ns = int(last_timestamp - timestamp)
+          latencies.append((latency_ns + refresh_period - 1) / refresh_period)
+          timestamps.append(timestamp)
+    return (first_timestamp, last_timestamp)
+
+  def _GetSurfaceStatsLegacy(self):
+    """Legacy method (before JellyBean), returns the current Surface index
+       and timestamp.
+
+    Calculate FPS by measuring the difference of Surface index returned by
+    SurfaceFlinger in a period of time.
+
+    Returns:
+      Dict of {page_flip_count (or 0 if there was an error), timestamp}.
+    """
+    results = self._adb.RunShellCommand('service call SurfaceFlinger 1013')
+    assert len(results) == 1
+    match = re.search('^Result: Parcel\((\w+)', results[0])
+    cur_surface = 0
+    if match:
+      try:
+        cur_surface = int(match.group(1), 16)
+      except Exception:
+        logging.error('Failed to parse current surface from ' + match.group(1))
+    else:
+      logging.warning('Failed to call SurfaceFlinger surface ' + results[0])
+    return {
+        'page_flip_count': cur_surface,
+        'timestamp': datetime.datetime.now(),
+    }