1#!/usr/bin/python 2# Copyright 2018 The Chromium OS Authors. All rights reserved. 3# Use of this source code is governed by a BSD-style license that can be 4# found in the LICENSE file. 5 6"""Checks kernel tracing events to get the FPS of a CrOS device. 7 8This script requires root privilege to work properly. It may interfere 9Chrome tracing because both use ftrace. 10 11Limitation: 12It doesn't support multi-screen. 13It assumes 60 HZ screen refresh rate. 14 15This script can be used both as a stand alone script or a library. 16 17Sample output (when used as a stand alone script): 18 # ./fps_meter.py 19 trace method: workq 20 [111111111111111111111111111111111111111111111111111111111111] FPS: 60 21 [111111111111111111111111111111111111111111111111111111111111] FPS: 60 22 [11111111111111111111111111111111111111111111111 111111111111] FPS: 59 23 [111111111111111111111111111111111111111111111111111111111111] FPS: 60 24 [11111111111111 11111111111111111111 11111111 111111111111111] FPS: 57 25 [111111111111111111111111111111111 11111111111111111111111] FPS: 56 26 [111 111111111111111111111111111111111111111111111111111111] FPS: 57 27 ^ 28 1 : Frame update count detected in this 1/60 sec interval. 29 30Sample Usage (when used as a library). 31 def callback(fps): 32 ... 33 34 with FPSMeter(callback) as fps_meter: 35 ... 36 37When used as a library, it launches two threads to monitor system FPS rate 38periodically. Each time when a FPS rate is sampled, callback() is called with 39the FPS number as its parameter. 40""" 41 42from __future__ import print_function 43 44import argparse 45import atexit 46import collections 47import common 48import functools 49import logging 50import os 51import re 52import sys 53import threading 54import time 55 56from autotest_lib.client.bin import utils as bin_utils 57from autotest_lib.client.common_lib import utils as common_lib_utils 58 59TRACE_ROOT = '/sys/kernel/debug/tracing/' 60VBLANK_SWITCH = os.path.join(TRACE_ROOT, 'events/drm/drm_vblank_event/enable') 61FLIP_SWITCH = os.path.join(TRACE_ROOT, 'events/i915/i915_flip_complete/enable') 62WORKQ_SWITCH = os.path.join( 63 TRACE_ROOT, 'events/workqueue/workqueue_execute_start/enable') 64WORKQ_FILTER = os.path.join( 65 TRACE_ROOT, 'events/workqueue/workqueue_execute_start/filter') 66TRACE_SWITCH = os.path.join(TRACE_ROOT, 'tracing_on') 67TRACE_CLOCK = os.path.join(TRACE_ROOT, 'trace_clock') 68TRACE_LOG = os.path.join(TRACE_ROOT, 'trace') 69TRACE_PIPE = os.path.join(TRACE_ROOT, 'trace_pipe') 70TRACE_MARKER = os.path.join(TRACE_ROOT, 'trace_marker') 71REFRESH_RATE = 60 72NOTIFY_STRING = 'notify_collection' 73STOP_STRING = 'stop_tracing' 74 75 76def is_intel_gpu(): 77 """Determines whether it is intel GPU.""" 78 return os.path.isdir('/sys/bus/pci/drivers/i915') 79 80 81def get_kernel_version(): 82 """ Retruns the kernel version in form of xx.xx. """ 83 m = re.match(r'(\d+\.\d+)\.\d+', bin_utils.get_kernel_version()) 84 if m: 85 return m.group(1) 86 return 'unknown' 87 88 89def get_trace_method(): 90 """Gets the FPS checking method. 91 92 Checks i915_flip_complete for Intel GPU on Kernel 3.18. 93 Checks intel_atomic_commit_work for Intel GPU on Kernel 4.4. 94 Checks drm_vblank_event otherwise. 95 """ 96 if is_intel_gpu(): 97 kernel_version = get_kernel_version() 98 if kernel_version == '4.4': 99 return 'workq' 100 elif kernel_version == '3.18': 101 return 'flip' 102 # Fallback. 103 return 'vblank' 104 105 106def set_simple_switch(value, filename): 107 """ Sets simple switch '1' to the file. """ 108 orig = common_lib_utils.read_file(filename).strip() 109 atexit.register(common_lib_utils.open_write_close, filename, orig) 110 common_lib_utils.open_write_close(filename, value) 111 112 113def set_trace_clock(): 114 """ Sets trace clock to mono time as chrome tracing in CrOS. """ 115 PREFERRED_TRACE_CLOCK = 'mono' 116 clock = common_lib_utils.read_file(TRACE_CLOCK) 117 m = re.match(r'.*\[(\w+)\]', clock) 118 if m: 119 orig_clock = m.group(1) 120 atexit.register(common_lib_utils.open_write_close, 121 TRACE_CLOCK, orig_clock) 122 common_lib_utils.open_write_close(TRACE_CLOCK, PREFERRED_TRACE_CLOCK) 123 124 125def get_kernel_symbol_addr(symbol): 126 """ Gets the kernel symple address. Example line in kallsyms: 127 ffffffffbc46cb03 T sys_exit 128 """ 129 with open('/proc/kallsyms') as kallsyms: 130 for line in kallsyms: 131 items = line.split() 132 if items[2] == symbol: 133 addr = items[0] 134 return addr 135 return None 136 137 138def set_workq_filter(function_name): 139 """ Sets the workq filter. """ 140 addr = get_kernel_symbol_addr(function_name) 141 if addr: 142 filter = 'function == 0x%s' % addr 143 common_lib_utils.open_write_close(WORKQ_FILTER, filter) 144 # Sets to 0 to remove the filter. 145 atexit.register(common_lib_utils.open_write_close, WORKQ_FILTER, '0') 146 147 148def enable_tracing(trace_method): 149 """Enables tracing.""" 150 if trace_method == 'workq': 151 set_simple_switch('1', WORKQ_SWITCH) 152 # There are many workqueue_execute_start events, 153 # filter to reduce CPU usage. 154 set_workq_filter('intel_atomic_commit_work') 155 elif trace_method == 'flip': 156 set_simple_switch('1', FLIP_SWITCH) 157 else: 158 set_simple_switch('1', VBLANK_SWITCH) 159 160 set_simple_switch('1', TRACE_SWITCH) 161 set_trace_clock() 162 163 164def get_fps_info(trace_buffer, end_time): 165 """ Checks all vblanks in the range [end_time - 1.0, end_time]. """ 166 frame_info = [] 167 step = 1.0 / REFRESH_RATE 168 step_time = end_time - 1.0 + step 169 frame_times = [] 170 for _ in range(REFRESH_RATE): 171 # Checks if there are vblanks in a refresh interval. 172 step_count = 0 173 while trace_buffer and trace_buffer[0] < step_time: 174 frame_times.append(trace_buffer.popleft()) 175 step_count += 1 176 177 # Each character represent an 1 / REFRESH_RATE interval. 178 if step_count: 179 if step_count >= 10: 180 frame_info.append('*') 181 else: 182 frame_info.append(str(step_count)) 183 else: 184 frame_info.append(' ') 185 step_time += step 186 187 return frame_info, frame_times 188 189 190def start_thread(function, args=()): 191 """ Starts a thread with given argument. """ 192 new_thread = threading.Thread(target=function, args=args) 193 new_thread.start() 194 195 196class FPSMeter(): 197 """ Initializes a FPSMeter to measure system FPS periodically. """ 198 def __init__(self, callback): 199 self.is_stopping = threading.Event() 200 self.callback = callback 201 202 203 def __enter__(self): 204 self.start() 205 return self 206 207 208 def __exit__(self, type, value, traceback): 209 self.stop() 210 211 212 def notify_collection(self, period_sec=1.0): 213 """ Writes a notification mark periodically. """ 214 logging.info('Notification thread is started') 215 next_notify_time = time.time() + period_sec 216 while True: 217 # Calling time.sleep(1) may suspend for more than 1 second. 218 # Sleeps until a specific time to avoid error accumulation. 219 sleep_time = next_notify_time - time.time() 220 next_notify_time += period_sec 221 # Skips if current time is larger than next_notify_time. 222 if sleep_time > 0: 223 if self.is_stopping.wait(sleep_time): 224 logging.info('Leaving notification thread') 225 # So the main loop doesn't stuck in the readline(). 226 common_lib_utils.open_write_close(TRACE_MARKER, STOP_STRING) 227 break 228 common_lib_utils.open_write_close(TRACE_MARKER, NOTIFY_STRING) 229 230 231 def main_loop(self, trace_method): 232 """ Main loop to parse the trace. 233 234 There are 2 threads involved: 235 Main thread: 236 Using blocking read to get data from trace_pipe. 237 Notify thread: The main thread may wait indifinitely if there 238 is no new trace. Writes to the pipe once per second to avoid 239 the indefinite waiting. 240 """ 241 logging.info('Fps meter main thread is started.') 242 243 # Sample trace: 244 # <idle>-0 [000] dNh3 631.905961: drm_vblank_event: crtc=0, seq=65496 245 # <idle>-0 [000] d.h3 631.922681: drm_vblank_event: crtc=0, seq=65497 246 # fps_meter [003] ..1 632.393953: tracing_mark_write: notify_collection 247 # .. 248 re_notify = re.compile( 249 r'.* (\d+\.\d+): tracing_mark_write: ' + NOTIFY_STRING) 250 if trace_method == 'workq': 251 re_trace = re.compile( 252 r'.* (\d+\.\d+): workqueue_execute_start: ' 253 r'work struct ([\da-f]+): ' 254 r'function intel_atomic_commit_work') 255 elif trace_method == 'flip': 256 re_trace = re.compile( 257 r'.* (\d+\.\d+): i915_flip_complete: ' 258 r'plane=(\d+), obj=([\da-f]+)') 259 else: 260 re_trace = re.compile( 261 r'.* (\d+\.\d+): drm_vblank_event: crtc=(\d+), seq=(\d+)') 262 263 trace_buffer = collections.deque() 264 with open(TRACE_PIPE) as trace_pipe: 265 # The pipe may block a few seconds if using: 266 # for line in trace_pipe 267 while not self.is_stopping.is_set(): 268 line = trace_pipe.readline() 269 m_trace = re_trace.match(line) 270 if m_trace: 271 timestamp = float(m_trace.group(1)) 272 trace_buffer.append(timestamp) 273 else: 274 m_notify = re_notify.match(line) 275 if m_notify: 276 timestamp = float(m_notify.group(1)) 277 self.callback(get_fps_info(trace_buffer, timestamp)) 278 logging.info('Leaving fps meter main thread') 279 280 281 def start(self): 282 """ Starts the FPS meter by launching needed threads. """ 283 # The notificaiton thread. 284 start_thread(self.notify_collection) 285 286 # The main thread. 287 trace_method = get_trace_method() 288 enable_tracing(trace_method) 289 start_thread(self.main_loop, [trace_method]) 290 291 292 def stop(self): 293 """ Stops the FPS meter. Shut down threads. """ 294 logging.info('Shutting down FPS meter') 295 self.is_stopping.set() 296 297 298def output_fps_info(verbose, fps_info): 299 """ Print the fps info to the screen. """ 300 frame_info, frame_times = fps_info 301 fps_count = len([f for f in frame_info if f != ' ']) 302 frame_info_str = ''.join(frame_info) 303 print('[%s] FPS: %2d' % (frame_info_str, fps_count)) 304 if frame_times and verbose: 305 print(', '.join(['%.3f' % t for t in frame_times])) 306 307 308def main(argv): 309 """ Print fps information on the screen. """ 310 parser = argparse.ArgumentParser(description='Print fps infomation.') 311 parser.add_argument('--verbose', action='store_true', 312 help='print verbose frame time info') 313 parser.add_argument('--debug', action='store_true', 314 help='print debug message') 315 options = parser.parse_args() 316 317 if options.debug: 318 rootLogger = logging.getLogger() 319 rootLogger.setLevel(logging.DEBUG) 320 # StreamHandler() defaults to stderr. 321 rootLogger.addHandler(logging.StreamHandler()) 322 323 print('FPS meter trace method %s' % get_trace_method()) 324 with FPSMeter(functools.partial(output_fps_info, options.verbose)): 325 while True: 326 try: 327 time.sleep(86400) 328 except KeyboardInterrupt: 329 print('Exiting...') 330 break 331 332 333if __name__ == '__main__': 334 sys.exit(main(sys.argv[1:])) 335