telemetry: Update Android frame latency metrics

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
 
@@ skipping 52 matching lines @@
 
   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'])
     else:
       assert self._collector_thread
-      (seconds, latencies) = self._GetDataFromThread()
-      if not seconds or not len(latencies):
+      (refresh_period, timestamps) = self._GetDataFromThread()
+      if not refresh_period or not len(timestamps) >= 3:
         logging.warning('Surface stat data is empty')
         return
+      frame_count = len(timestamps)
+      seconds = timestamps[-1] - timestamps[0]
 
-      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
+      frame_lengths = [t2 - t1 for t1, t2 in zip(timestamps, timestamps[1:])]
+      normalized_frame_lengths = [length / refresh_period for length in
+                                  frame_lengths]
+
+      length_changes = [d2 - d1 for d1, d2 in zip(frame_lengths,
+                                                  frame_lengths[1:])]
+      normalized_changes = [change / refresh_period
+                            for change in length_changes]

[bulach, 2013/03/18 18:45:03]

not sure if it'd be any more readable, but it seems we'd avoid an extra local
(length_changes) by extracting:

@staticmethod
def _GetNormalizedDeltas(data, refresh_period):
  deltas = [t2 - t1 for t1, t2 in zip(data, data[1:])]
  return (deltas, [delta / refresh_period for delta in deltas])

then:
frame_lengths, normalized_frame_lengths = _GetNormalizedDeltas(timestamps,
refresh_period)
_, normalized_changes = _GetNormalizedDeltas(frame_lengths, refresh_period)

[Sami, 2013/03/18 19:03:15]

That's much more readable, thanks!

+      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)
 
       self._results.append(SurfaceStatsCollector.Result(
-          'surface_latencies', latencies, ''))
+          'refresh_period', [refresh_period], 'seconds'))
       self._results.append(SurfaceStatsCollector.Result(
-          'peak_jitter', [max(latencies)], ''))
+          'jank_count', [jank_count], 'janks'))
       self._results.append(SurfaceStatsCollector.Result(
-          'jitter_percent', [jitter_count * 100.0 / frame_count], 'percent'))
+          'max_frame_delay', [round(max(normalized_frame_lengths))],
+          'vsyncs'))
+      self._results.append(SurfaceStatsCollector.Result(
+          'frame_lengths', normalized_frame_lengths, 'vsyncs'))
     self._results.append(SurfaceStatsCollector.Result(
-          'avg_surface_fps', [int(round(frame_count / seconds))], 'fps'))
+        'avg_surface_fps', [int(round(frame_count / seconds))], 'fps'))
 
   def _CollectorThread(self):
     last_timestamp = 0
-    first_timestamp = 0
-    latencies = []
+    timestamps = []
     retries = 0
-    has_collected_data = False
 
     while not self._stop_event.is_set():
       self._get_data_event.wait(1)
       try:
-        (t, last_timestamp) = self._GetSurfaceFlingerLatencyData(last_timestamp,
-                                                                 latencies)
-        if (t, last_timestamp) == (None, None):
+        refresh_period, new_timestamps = self._GetSurfaceFlingerFrameData()
+        if refresh_period is None or timestamps is None:
           retries += 1
           if retries < 3:
             continue
-          if has_collected_data:
+          if last_timestamp:
             # Some data has already been collected, but either the app
             # was closed or there's no new data. Signal the main thread and
             # wait.
             self._data_queue.put((None, None))
             self._stop_event.wait()
             break
           raise Exception('Unable to get surface flinger latency data')
 
-        has_collected_data = True
-
-        if not first_timestamp:
-          first_timestamp = t
+        timestamps += [timestamp for timestamp in new_timestamps
+                       if timestamp > last_timestamp]
+        if len(timestamps):
+          last_timestamp = timestamps[-1]
 
         if self._get_data_event.is_set():
           self._get_data_event.clear()
-          self._data_queue.put(((last_timestamp - first_timestamp) / 1e9,
-                                latencies))
-          latencies = []
-          first_timestamp = 0
+          self._data_queue.put((refresh_period, timestamps))
+          timestamps = []
       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 SurfaceView')
     return not len(results)
 
-  def _GetSurfaceFlingerLatencyData(self, previous_timestamp, latencies):
-    """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.
+  def _GetSurfaceFlingerFrameData(self):
+    """Returns collected SurfaceFlinger frame timing data.
 
     Returns:
       A tuple containing:
-      - The timestamp of the beginning of the first frame (ns),
-      - The timestamp of the end of the last frame (ns).
-      The tuple may be (None, None) if there was no data collected (for example,
-      if the app was closed before the collector thread has finished).
+      - 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
     # 7657500793457   7657516600576   7657527404785
     # (...)
@@ skipping 15 matching lines @@
     # janky, even if it runs at 60 fps in average.
     #
     # 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._adb.RunShellCommand(
         'dumpsys SurfaceFlinger --latency SurfaceView', log_result=True)
     if not len(results):
       return (None, None)
 
-    refresh_period = int(results[0])
-    last_timestamp = previous_timestamp
-    first_timestamp = 0
+    timestamps = []
+    nanoseconds_per_second = 1e9
+    refresh_period = long(results[0]) / nanoseconds_per_second
+
     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)
-    return (first_timestamp, last_timestamp)
+      if len(fields) != 3:
+        continue
+      timestamp = long(fields[1]) / 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._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(),
     }