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 5 import Queue 6 import datetime 7 import logging 8 import re 9 import threading 10 from pylib import android_commands 11 from 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 21 class 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