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 3 # found in the LICENSE file. 4 5 import Queue 6 import datetime 7 import logging 8 import re 9 import threading 10 11 from pylib import perf_tests_helper 12 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): 32 self._adb = 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 } 299
