• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
1# Copyright 2013 The Chromium Authors. All rights reserved.
2# Use of this source code is governed by a BSD-style license that can be
3# found in the LICENSE file.
4
5import Queue
6import datetime
7import logging
8import re
9import threading
10from pylib import android_commands
11from pylib.device import device_utils
12
13
14# Log marker containing SurfaceTexture timestamps.
15_SURFACE_TEXTURE_TIMESTAMPS_MESSAGE = 'SurfaceTexture update timestamps'
16_SURFACE_TEXTURE_TIMESTAMP_RE = '\d+'
17
18_MIN_NORMALIZED_FRAME_LENGTH = 0.5
19
20
21class SurfaceStatsCollector(object):
22  """Collects surface stats for a SurfaceView from the output of SurfaceFlinger.
23
24  Args:
25    device: A DeviceUtils instance.
26  """
27  class Result(object):
28    def __init__(self, name, value, unit):
29      self.name = name
30      self.value = value
31      self.unit = unit
32
33  def __init__(self, device):
34    # TODO(jbudorick) Remove once telemetry gets switched over.
35    if isinstance(device, android_commands.AndroidCommands):
36      device = device_utils.DeviceUtils(device)
37    self._device = device
38    self._collector_thread = None
39    self._use_legacy_method = False
40    self._surface_before = None
41    self._get_data_event = None
42    self._data_queue = None
43    self._stop_event = None
44    self._results = []
45    self._warn_about_empty_data = True
46
47  def DisableWarningAboutEmptyData(self):
48    self._warn_about_empty_data = False
49
50  def Start(self):
51    assert not self._collector_thread
52
53    if self._ClearSurfaceFlingerLatencyData():
54      self._get_data_event = threading.Event()
55      self._stop_event = threading.Event()
56      self._data_queue = Queue.Queue()
57      self._collector_thread = threading.Thread(target=self._CollectorThread)
58      self._collector_thread.start()
59    else:
60      self._use_legacy_method = True
61      self._surface_before = self._GetSurfaceStatsLegacy()
62
63  def Stop(self):
64    self._StorePerfResults()
65    if self._collector_thread:
66      self._stop_event.set()
67      self._collector_thread.join()
68      self._collector_thread = None
69
70  def SampleResults(self):
71    self._StorePerfResults()
72    results = self.GetResults()
73    self._results = []
74    return results
75
76  def GetResults(self):
77    return self._results or self._GetEmptyResults()
78
79  @staticmethod
80  def _GetEmptyResults():
81    return [
82        SurfaceStatsCollector.Result('refresh_period', None, 'seconds'),
83        SurfaceStatsCollector.Result('jank_count', None, 'janks'),
84        SurfaceStatsCollector.Result('max_frame_delay', None, 'vsyncs'),
85        SurfaceStatsCollector.Result('frame_lengths', None, 'vsyncs'),
86        SurfaceStatsCollector.Result('avg_surface_fps', None, 'fps')
87    ]
88
89  @staticmethod
90  def _GetNormalizedDeltas(data, refresh_period, min_normalized_delta=None):
91    deltas = [t2 - t1 for t1, t2 in zip(data, data[1:])]
92    if min_normalized_delta != None:
93      deltas = filter(lambda d: d / refresh_period >= min_normalized_delta,
94                      deltas)
95    return (deltas, [delta / refresh_period for delta in deltas])
96
97  @staticmethod
98  def _CalculateResults(refresh_period, timestamps, result_suffix):
99    """Returns a list of SurfaceStatsCollector.Result."""
100    frame_count = len(timestamps)
101    seconds = timestamps[-1] - timestamps[0]
102
103    frame_lengths, normalized_frame_lengths = \
104        SurfaceStatsCollector._GetNormalizedDeltas(
105            timestamps, refresh_period, _MIN_NORMALIZED_FRAME_LENGTH)
106    if len(frame_lengths) < frame_count - 1:
107      logging.warning('Skipping frame lengths that are too short.')
108      frame_count = len(frame_lengths) + 1
109    if len(frame_lengths) == 0:
110      raise Exception('No valid frames lengths found.')
111    _, normalized_changes = \
112        SurfaceStatsCollector._GetNormalizedDeltas(
113            frame_lengths, refresh_period)
114    jankiness = [max(0, round(change)) for change in normalized_changes]
115    pause_threshold = 20
116    jank_count = sum(1 for change in jankiness
117                     if change > 0 and change < pause_threshold)
118    return [
119        SurfaceStatsCollector.Result(
120            'avg_surface_fps' + result_suffix,
121            int(round((frame_count - 1) / seconds)), 'fps'),
122        SurfaceStatsCollector.Result(
123            'jank_count' + result_suffix, jank_count, 'janks'),
124        SurfaceStatsCollector.Result(
125            'max_frame_delay' + result_suffix,
126            round(max(normalized_frame_lengths)),
127            'vsyncs'),
128        SurfaceStatsCollector.Result(
129            'frame_lengths' + result_suffix, normalized_frame_lengths,
130            'vsyncs'),
131    ]
132
133  @staticmethod
134  def _CalculateBuckets(refresh_period, timestamps):
135    results = []
136    for pct in [0.99, 0.5]:
137      sliced = timestamps[min(int(-pct * len(timestamps)), -3) : ]
138      results += SurfaceStatsCollector._CalculateResults(
139          refresh_period, sliced, '_' + str(int(pct * 100)))
140    return results
141
142  def _StorePerfResults(self):
143    if self._use_legacy_method:
144      surface_after = self._GetSurfaceStatsLegacy()
145      td = surface_after['timestamp'] - self._surface_before['timestamp']
146      seconds = td.seconds + td.microseconds / 1e6
147      frame_count = (surface_after['page_flip_count'] -
148                     self._surface_before['page_flip_count'])
149      self._results.append(SurfaceStatsCollector.Result(
150          'avg_surface_fps', int(round(frame_count / seconds)), 'fps'))
151      return
152
153    # Non-legacy method.
154    assert self._collector_thread
155    (refresh_period, timestamps) = self._GetDataFromThread()
156    if not refresh_period or not len(timestamps) >= 3:
157      if self._warn_about_empty_data:
158        logging.warning('Surface stat data is empty')
159      return
160    self._results.append(SurfaceStatsCollector.Result(
161        'refresh_period', refresh_period, 'seconds'))
162    self._results += self._CalculateResults(refresh_period, timestamps, '')
163    self._results += self._CalculateBuckets(refresh_period, timestamps)
164
165  def _CollectorThread(self):
166    last_timestamp = 0
167    timestamps = []
168    retries = 0
169
170    while not self._stop_event.is_set():
171      self._get_data_event.wait(1)
172      try:
173        refresh_period, new_timestamps = self._GetSurfaceFlingerFrameData()
174        if refresh_period is None or timestamps is None:
175          retries += 1
176          if retries < 3:
177            continue
178          if last_timestamp:
179            # Some data has already been collected, but either the app
180            # was closed or there's no new data. Signal the main thread and
181            # wait.
182            self._data_queue.put((None, None))
183            self._stop_event.wait()
184            break
185          raise Exception('Unable to get surface flinger latency data')
186
187        timestamps += [timestamp for timestamp in new_timestamps
188                       if timestamp > last_timestamp]
189        if len(timestamps):
190          last_timestamp = timestamps[-1]
191
192        if self._get_data_event.is_set():
193          self._get_data_event.clear()
194          self._data_queue.put((refresh_period, timestamps))
195          timestamps = []
196      except Exception as e:
197        # On any error, before aborting, put the exception into _data_queue to
198        # prevent the main thread from waiting at _data_queue.get() infinitely.
199        self._data_queue.put(e)
200        raise
201
202  def _GetDataFromThread(self):
203    self._get_data_event.set()
204    ret = self._data_queue.get()
205    if isinstance(ret, Exception):
206      raise ret
207    return ret
208
209  def _ClearSurfaceFlingerLatencyData(self):
210    """Clears the SurfaceFlinger latency data.
211
212    Returns:
213      True if SurfaceFlinger latency is supported by the device, otherwise
214      False.
215    """
216    # The command returns nothing if it is supported, otherwise returns many
217    # lines of result just like 'dumpsys SurfaceFlinger'.
218    results = self._device.RunShellCommand(
219        'dumpsys SurfaceFlinger --latency-clear SurfaceView')
220    return not len(results)
221
222  def _GetSurfaceFlingerFrameData(self):
223    """Returns collected SurfaceFlinger frame timing data.
224
225    Returns:
226      A tuple containing:
227      - The display's nominal refresh period in seconds.
228      - A list of timestamps signifying frame presentation times in seconds.
229      The return value may be (None, None) if there was no data collected (for
230      example, if the app was closed before the collector thread has finished).
231    """
232    # adb shell dumpsys SurfaceFlinger --latency <window name>
233    # prints some information about the last 128 frames displayed in
234    # that window.
235    # The data returned looks like this:
236    # 16954612
237    # 7657467895508   7657482691352   7657493499756
238    # 7657484466553   7657499645964   7657511077881
239    # 7657500793457   7657516600576   7657527404785
240    # (...)
241    #
242    # The first line is the refresh period (here 16.95 ms), it is followed
243    # by 128 lines w/ 3 timestamps in nanosecond each:
244    # A) when the app started to draw
245    # B) the vsync immediately preceding SF submitting the frame to the h/w
246    # C) timestamp immediately after SF submitted that frame to the h/w
247    #
248    # The difference between the 1st and 3rd timestamp is the frame-latency.
249    # An interesting data is when the frame latency crosses a refresh period
250    # boundary, this can be calculated this way:
251    #
252    # ceil((C - A) / refresh-period)
253    #
254    # (each time the number above changes, we have a "jank").
255    # If this happens a lot during an animation, the animation appears
256    # janky, even if it runs at 60 fps in average.
257    #
258    # We use the special "SurfaceView" window name because the statistics for
259    # the activity's main window are not updated when the main web content is
260    # composited into a SurfaceView.
261    results = self._device.RunShellCommand(
262        'dumpsys SurfaceFlinger --latency SurfaceView')
263    if not len(results):
264      return (None, None)
265
266    timestamps = []
267    nanoseconds_per_second = 1e9
268    refresh_period = long(results[0]) / nanoseconds_per_second
269
270    # If a fence associated with a frame is still pending when we query the
271    # latency data, SurfaceFlinger gives the frame a timestamp of INT64_MAX.
272    # Since we only care about completed frames, we will ignore any timestamps
273    # with this value.
274    pending_fence_timestamp = (1 << 63) - 1
275
276    for line in results[1:]:
277      fields = line.split()
278      if len(fields) != 3:
279        continue
280      timestamp = long(fields[1])
281      if timestamp == pending_fence_timestamp:
282        continue
283      timestamp /= nanoseconds_per_second
284      timestamps.append(timestamp)
285
286    return (refresh_period, timestamps)
287
288  def _GetSurfaceStatsLegacy(self):
289    """Legacy method (before JellyBean), returns the current Surface index
290       and timestamp.
291
292    Calculate FPS by measuring the difference of Surface index returned by
293    SurfaceFlinger in a period of time.
294
295    Returns:
296      Dict of {page_flip_count (or 0 if there was an error), timestamp}.
297    """
298    results = self._device.RunShellCommand('service call SurfaceFlinger 1013')
299    assert len(results) == 1
300    match = re.search('^Result: Parcel\((\w+)', results[0])
301    cur_surface = 0
302    if match:
303      try:
304        cur_surface = int(match.group(1), 16)
305      except Exception:
306        logging.error('Failed to parse current surface from ' + match.group(1))
307    else:
308      logging.warning('Failed to call SurfaceFlinger surface ' + results[0])
309    return {
310        'page_flip_count': cur_surface,
311        'timestamp': datetime.datetime.now(),
312    }
313