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