• 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 logging
6import re
7import threading
8
9import six
10
11if six.PY3:
12  import queue # pylint: disable=wrong-import-order
13else:
14  import Queue as queue # pylint: disable=wrong-import-order
15
16# Log marker containing SurfaceTexture timestamps.
17_SURFACE_TEXTURE_TIMESTAMPS_MESSAGE = 'SurfaceTexture update timestamps'
18_SURFACE_TEXTURE_TIMESTAMP_RE = r'\d+'
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
28  def __init__(self, device):
29    self._device = device
30    self._collector_thread = None
31    self._surface_before = None
32    self._get_data_event = None
33    self._data_queue = None
34    self._stop_event = None
35    self._warn_about_empty_data = True
36
37  def DisableWarningAboutEmptyData(self):
38    self._warn_about_empty_data = False
39
40  def Start(self):
41    assert not self._collector_thread
42
43    if self._ClearSurfaceFlingerLatencyData():
44      self._get_data_event = threading.Event()
45      self._stop_event = threading.Event()
46      self._data_queue = queue.Queue()
47      self._collector_thread = threading.Thread(target=self._CollectorThread)
48      self._collector_thread.start()
49    else:
50      raise Exception('SurfaceFlinger not supported on this device.')
51
52  def Stop(self):
53    assert self._collector_thread
54    (refresh_period, timestamps) = self._GetDataFromThread()
55    if self._collector_thread:
56      self._stop_event.set()
57      self._collector_thread.join()
58      self._collector_thread = None
59    return (refresh_period, timestamps)
60
61  def _CollectorThread(self):
62    last_timestamp = 0
63    timestamps = []
64    retries = 0
65
66    while not self._stop_event.is_set():
67      self._get_data_event.wait(1)
68      try:
69        refresh_period, new_timestamps = self._GetSurfaceFlingerFrameData()
70        if refresh_period is None or timestamps is None:
71          retries += 1
72          if retries < 3:
73            continue
74          if last_timestamp:
75            # Some data has already been collected, but either the app
76            # was closed or there's no new data. Signal the main thread and
77            # wait.
78            self._data_queue.put((None, None))
79            self._stop_event.wait()
80            break
81          raise Exception('Unable to get surface flinger latency data')
82
83        timestamps += [
84            timestamp for timestamp in new_timestamps
85            if timestamp > last_timestamp
86        ]
87        if len(timestamps):
88          last_timestamp = timestamps[-1]
89
90        if self._get_data_event.is_set():
91          self._get_data_event.clear()
92          self._data_queue.put((refresh_period, timestamps))
93          timestamps = []
94      except Exception as e:
95        # On any error, before aborting, put the exception into _data_queue to
96        # prevent the main thread from waiting at _data_queue.get() infinitely.
97        self._data_queue.put(e)
98        raise
99
100  def _GetDataFromThread(self):
101    self._get_data_event.set()
102    ret = self._data_queue.get()
103    if isinstance(ret, Exception):
104      raise ret
105    return ret
106
107  def _ClearSurfaceFlingerLatencyData(self):
108    """Clears the SurfaceFlinger latency data.
109
110    Returns:
111      True if SurfaceFlinger latency is supported by the device, otherwise
112      False.
113    """
114    # The command returns nothing if it is supported, otherwise returns many
115    # lines of result just like 'dumpsys SurfaceFlinger'.
116    results = self._device.RunShellCommand(
117        ['dumpsys', 'SurfaceFlinger', '--latency-clear', 'SurfaceView'],
118        check_return=True)
119    return not len(results)
120
121  def GetSurfaceFlingerPid(self):
122    try:
123      # Returns the first matching PID found.
124      return next(p.pid for p in self._device.ListProcesses('surfaceflinger'))
125    except StopIteration:
126      raise Exception('Unable to get surface flinger process id')
127
128  def _GetSurfaceViewWindowName(self):
129    results = self._device.RunShellCommand(
130        ['dumpsys', 'SurfaceFlinger', '--list'], check_return=True)
131    for window_name in results:
132      if window_name.startswith('SurfaceView'):
133        return window_name
134    return None
135
136  def _GetSurfaceFlingerFrameData(self):
137    """Returns collected SurfaceFlinger frame timing data.
138
139    Returns:
140      A tuple containing:
141      - The display's nominal refresh period in milliseconds.
142      - A list of timestamps signifying frame presentation times in
143        milliseconds.
144      The return value may be (None, None) if there was no data collected (for
145      example, if the app was closed before the collector thread has finished).
146    """
147    window_name = self._GetSurfaceViewWindowName()
148    command = ['dumpsys', 'SurfaceFlinger', '--latency']
149    # Even if we don't find the window name, run the command to get the refresh
150    # period.
151    if window_name:
152      command.append(window_name)
153    output = self._device.RunShellCommand(command, check_return=True)
154    return ParseFrameData(output, parse_timestamps=bool(window_name))
155
156
157def to_long_int(val):
158  """Cast val to a long int type."""
159  return long(val) if six.PY2 else int(val)
160
161def ParseFrameData(lines, parse_timestamps):
162  # adb shell dumpsys SurfaceFlinger --latency <window name>
163  # prints some information about the last 128 frames displayed in
164  # that window.
165  # The data returned looks like this:
166  # 16954612
167  # 7657467895508   7657482691352   7657493499756
168  # 7657484466553   7657499645964   7657511077881
169  # 7657500793457   7657516600576   7657527404785
170  # (...)
171  #
172  # The first line is the refresh period (here 16.95 ms), it is followed
173  # by 128 lines w/ 3 timestamps in nanosecond each:
174  # A) when the app started to draw
175  # B) the vsync immediately preceding SF submitting the frame to the h/w
176  # C) timestamp immediately after SF submitted that frame to the h/w
177  #
178  # The difference between the 1st and 3rd timestamp is the frame-latency.
179  # An interesting data is when the frame latency crosses a refresh period
180  # boundary, this can be calculated this way:
181  #
182  # ceil((C - A) / refresh-period)
183  #
184  # (each time the number above changes, we have a "jank").
185  # If this happens a lot during an animation, the animation appears
186  # janky, even if it runs at 60 fps in average.
187  # pylint: disable=redefined-variable-type
188  results = []
189  for line in lines:
190    # Skip over lines with anything other than digits and whitespace.
191    if re.search(r'[^\d\s]', line):
192      logging.warning('unexpected output: %s', line)
193    else:
194      results.append(line)
195  if not results:
196    return None, None
197
198  timestamps = []
199  nanoseconds_per_millisecond = 1e6
200  refresh_period = to_long_int(results[0]) / nanoseconds_per_millisecond
201
202  if not parse_timestamps:
203    return refresh_period, timestamps
204
205  # If a fence associated with a frame is still pending when we query the
206  # latency data, SurfaceFlinger gives the frame a timestamp of INT64_MAX.
207  # Since we only care about completed frames, we will ignore any timestamps
208  # with this value.
209  pending_fence_timestamp = (1 << 63) - 1
210
211  for line in results[1:]:
212    fields = line.split()
213    if len(fields) != 3:
214      logging.warning('Unexpected line: %s', line)
215      continue
216    timestamp = to_long_int(fields[1])
217
218    if timestamp == pending_fence_timestamp:
219      continue
220    timestamp /= nanoseconds_per_millisecond
221    timestamps.append(timestamp)
222
223  return refresh_period, timestamps
224