Revert of telemetry: Clean up SurfaceFlinger statistics

build/android/pylib/perf/surface_stats_collector.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.
 
 import Queue
 import datetime
 import logging
 import re
 import threading
 from pylib import android_commands
 from pylib.device import device_utils
 
 
 # Log marker containing SurfaceTexture timestamps.
 _SURFACE_TEXTURE_TIMESTAMPS_MESSAGE = 'SurfaceTexture update timestamps'
 _SURFACE_TEXTURE_TIMESTAMP_RE = r'\d+'
 
+_MIN_NORMALIZED_FRAME_LENGTH = 0.5
+
 
 class SurfaceStatsCollector(object):
   """Collects surface stats for a SurfaceView from the output of SurfaceFlinger.
 
   Args:
     device: A DeviceUtils instance.
   """
+  class Result(object):
+    def __init__(self, name, value, unit):
+      self.name = name
+      self.value = value
+      self.unit = unit
 
   def __init__(self, device):
     # TODO(jbudorick) Remove once telemetry gets switched over.
     if isinstance(device, android_commands.AndroidCommands):
       device = device_utils.DeviceUtils(device)
     self._device = device
     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
+    self._results = []
     self._warn_about_empty_data = True
 
   def DisableWarningAboutEmptyData(self):
     self._warn_about_empty_data = False
 
   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()
     else:
-      raise Exception('SurfaceFlinger not supported on this device.')
+      self._use_legacy_method = True
+      self._surface_before = self._GetSurfaceStatsLegacy()
 
   def Stop(self):
-    assert self._collector_thread
-    (refresh_period, timestamps) = self._GetDataFromThread()
+    self._StorePerfResults()
     if self._collector_thread:
       self._stop_event.set()
       self._collector_thread.join()
       self._collector_thread = None
-    return (refresh_period, timestamps)
+
+  def SampleResults(self):
+    self._StorePerfResults()
+    results = self.GetResults()
+    self._results = []
+    return results
+
+  def GetResults(self):
+    return self._results or self._GetEmptyResults()
+
+  @staticmethod
+  def _GetEmptyResults():
+    return [
+        SurfaceStatsCollector.Result('refresh_period', None, 'seconds'),
+        SurfaceStatsCollector.Result('jank_count', None, 'janks'),
+        SurfaceStatsCollector.Result('max_frame_delay', None, 'vsyncs'),
+        SurfaceStatsCollector.Result('frame_lengths', None, 'vsyncs'),
+        SurfaceStatsCollector.Result('avg_surface_fps', None, 'fps')
+    ]
+
+  @staticmethod
+  def _GetNormalizedDeltas(data, refresh_period, min_normalized_delta=None):
+    deltas = [t2 - t1 for t1, t2 in zip(data, data[1:])]
+    if min_normalized_delta != None:
+      deltas = [d for d in deltas
+                if d / refresh_period >= min_normalized_delta]
+    return (deltas, [delta / refresh_period for delta in deltas])
+
+  @staticmethod
+  def _CalculateResults(refresh_period, timestamps, result_suffix):
+    """Returns a list of SurfaceStatsCollector.Result."""
+    frame_count = len(timestamps)
+    seconds = timestamps[-1] - timestamps[0]
+
+    frame_lengths, normalized_frame_lengths = \
+        SurfaceStatsCollector._GetNormalizedDeltas(
+            timestamps, refresh_period, _MIN_NORMALIZED_FRAME_LENGTH)
+    if len(frame_lengths) < frame_count - 1:
+      logging.warning('Skipping frame lengths that are too short.')
+      frame_count = len(frame_lengths) + 1
+    if len(frame_lengths) == 0:
+      raise Exception('No valid frames lengths found.')
+    _, normalized_changes = \
+        SurfaceStatsCollector._GetNormalizedDeltas(
+            frame_lengths, refresh_period)
+    jankiness = [max(0, round(change)) for change in normalized_changes]
+    pause_threshold = 20
+    jank_count = sum(1 for change in jankiness
+                     if change > 0 and change < pause_threshold)
+    return [
+        SurfaceStatsCollector.Result(
+            'avg_surface_fps' + result_suffix,
+            int(round((frame_count - 1) / seconds)), 'fps'),
+        SurfaceStatsCollector.Result(
+            'jank_count' + result_suffix, jank_count, 'janks'),
+        SurfaceStatsCollector.Result(
+            'max_frame_delay' + result_suffix,
+            round(max(normalized_frame_lengths)),
+            'vsyncs'),
+        SurfaceStatsCollector.Result(
+            'frame_lengths' + result_suffix, normalized_frame_lengths,
+            'vsyncs'),
+    ]
+
+  @staticmethod
+  def _CalculateBuckets(refresh_period, timestamps):
+    results = []
+    for pct in [0.99, 0.5]:
+      sliced = timestamps[min(int(-pct * len(timestamps)), -3) : ]
+      results += SurfaceStatsCollector._CalculateResults(
+          refresh_period, sliced, '_' + str(int(pct * 100)))
+    return results
+
+  def _StorePerfResults(self):
+    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'])
+      self._results.append(SurfaceStatsCollector.Result(
+          'avg_surface_fps', int(round(frame_count / seconds)), 'fps'))
+      return
+
+    # Non-legacy method.
+    assert self._collector_thread
+    (refresh_period, timestamps) = self._GetDataFromThread()
+    if not refresh_period or not len(timestamps) >= 3:
+      if self._warn_about_empty_data:
+        logging.warning('Surface stat data is empty')
+      return
+    self._results.append(SurfaceStatsCollector.Result(
+        'refresh_period', refresh_period, 'seconds'))
+    self._results += self._CalculateResults(refresh_period, timestamps, '')
+    self._results += self._CalculateBuckets(refresh_period, timestamps)
 
   def _CollectorThread(self):
     last_timestamp = 0
     timestamps = []
     retries = 0
 
     while not self._stop_event.is_set():
       self._get_data_event.wait(1)
       try:
         refresh_period, new_timestamps = self._GetSurfaceFlingerFrameData()
@@ skipping 38 matching lines @@
     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._device.RunShellCommand(
         'dumpsys SurfaceFlinger --latency-clear SurfaceView')
     return not len(results)
 
-  def GetSurfaceFlingerPid(self):
-    results = self._device.RunShellCommand('ps | grep surfaceflinger')
-    if not results:
-      raise Exception('Unable to get surface flinger process id')
-    pid = results[0].split()[1]
-    return pid
-
   def _GetSurfaceFlingerFrameData(self):
     """Returns collected SurfaceFlinger frame timing data.
 
     Returns:
       A tuple containing:
-      - The display's nominal refresh period in milliseconds.
-      - A list of timestamps signifying frame presentation times in
-        milliseconds.
+      - The display's nominal refresh period in seconds.
+      - A list of timestamps signifying frame presentation times in seconds.
       The return value may be (None, None) if there was no data collected (for
       example, if the app was closed before the collector thread has finished).
     """
     # 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
@@ skipping 18 matching lines @@
     #
     # We use the special "SurfaceView" window name because the statistics for
     # the activity's main window are not updated when the main web content is
     # composited into a SurfaceView.
     results = self._device.RunShellCommand(
         'dumpsys SurfaceFlinger --latency SurfaceView')
     if not len(results):
       return (None, None)
 
     timestamps = []
-    nanoseconds_per_millisecond = 1e6
-    refresh_period = long(results[0]) / nanoseconds_per_millisecond
+    nanoseconds_per_second = 1e9
+    refresh_period = long(results[0]) / nanoseconds_per_second
 
     # If a fence associated with a frame is still pending when we query the
     # latency data, SurfaceFlinger gives the frame a timestamp of INT64_MAX.
     # Since we only care about completed frames, we will ignore any timestamps
     # with this value.
     pending_fence_timestamp = (1 << 63) - 1
 
     for line in results[1:]:
       fields = line.split()
       if len(fields) != 3:
         continue
       timestamp = long(fields[1])
       if timestamp == pending_fence_timestamp:
         continue
-      timestamp /= nanoseconds_per_millisecond
+      timestamp /= nanoseconds_per_second
       timestamps.append(timestamp)
 
     return (refresh_period, timestamps)
+
+  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._device.RunShellCommand('service call SurfaceFlinger 1013')
+    assert len(results) == 1
+    match = re.search(r'^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(),
+    }