| #!/usr/bin/python |
| # Copyright 2018 The Chromium OS Authors. All rights reserved. |
| # Use of this source code is governed by a BSD-style license that can be |
| # found in the LICENSE file. |
| |
| """Checks kernel tracing events to get the FPS of a CrOS device. |
| |
| This script requires root privilege to work properly. It may interfere |
| Chrome tracing because both use ftrace. |
| |
| Limitation: |
| It doesn't support multi-screen. |
| It assumes 60 HZ screen refresh rate. |
| |
| This script can be used both as a stand alone script or a library. |
| |
| Sample output (when used as a stand alone script): |
| # ./fps_meter.py |
| trace method: workq |
| [111111111111111111111111111111111111111111111111111111111111] FPS: 60 |
| [111111111111111111111111111111111111111111111111111111111111] FPS: 60 |
| [11111111111111111111111111111111111111111111111 111111111111] FPS: 59 |
| [111111111111111111111111111111111111111111111111111111111111] FPS: 60 |
| [11111111111111 11111111111111111111 11111111 111111111111111] FPS: 57 |
| [111111111111111111111111111111111 11111111111111111111111] FPS: 56 |
| [111 111111111111111111111111111111111111111111111111111111] FPS: 57 |
| ^ |
| 1 : Frame update count detected in this 1/60 sec interval. |
| |
| Sample Usage (when used as a library). |
| def callback(fps): |
| ... |
| |
| with FPSMeter(callback) as fps_meter: |
| ... |
| |
| When used as a library, it launches two threads to monitor system FPS rate |
| periodically. Each time when a FPS rate is sampled, callback() is called with |
| the FPS number as its parameter. |
| """ |
| import argparse |
| import atexit |
| import collections |
| import functools |
| import logging |
| import os |
| import re |
| import threading |
| import time |
| |
| TRACE_ROOT = '/sys/kernel/debug/tracing/' |
| VBLANK_SWITCH = os.path.join(TRACE_ROOT, 'events/drm/drm_vblank_event/enable') |
| FLIP_SWITCH = os.path.join(TRACE_ROOT, 'events/i915/i915_flip_complete/enable') |
| WORKQ_SWITCH = os.path.join( |
| TRACE_ROOT, 'events/workqueue/workqueue_execute_start/enable') |
| WORKQ_FILTER = os.path.join( |
| TRACE_ROOT, 'events/workqueue/workqueue_execute_start/filter') |
| TRACE_SWITCH = os.path.join(TRACE_ROOT, 'tracing_on') |
| TRACE_CLOCK = os.path.join(TRACE_ROOT, 'trace_clock') |
| TRACE_LOG = os.path.join(TRACE_ROOT, 'trace') |
| TRACE_PIPE = os.path.join(TRACE_ROOT, 'trace_pipe') |
| TRACE_MARKER = os.path.join(TRACE_ROOT, 'trace_marker') |
| REFRESH_RATE = 60 |
| NOTIFY_STRING = 'notify_collection' |
| STOP_STRING = 'stop_tracing' |
| |
| |
| def is_intel_gpu(): |
| """Whether is intel GPU.""" |
| return os.path.isdir('/sys/bus/pci/drivers/i915') |
| |
| |
| def get_kernel_version(): |
| with open('/proc/version') as fin: |
| m = re.match(r'Linux version (\d+.\d+).\d+', fin.read()) |
| if m: |
| return m.group(1) |
| return 'unknown' |
| |
| |
| def get_trace_method(): |
| """Gets the FPS checking method. |
| |
| Checks i915_flip_complete for Intel GPU on Kernel 3.18. |
| Checks intel_atomic_commit_work for Intel GPU on Kernel 4.4. |
| Checks drm_vblank_event otherwise. |
| """ |
| if is_intel_gpu(): |
| kernel_version = get_kernel_version() |
| if kernel_version == '4.4': |
| return 'workq' |
| elif kernel_version == '3.18': |
| return 'flip' |
| # Fallback. |
| return 'vblank' |
| |
| |
| def write_to_file(content, filename): |
| """Writes content to a file.""" |
| with open(filename, 'w') as fout: |
| fout.write(content) |
| |
| |
| def set_simple_switch(value, filename): |
| with open(filename) as fin: |
| orig = fin.read().strip() |
| atexit.register(write_to_file, orig, filename) |
| write_to_file(value, filename) |
| |
| |
| def set_trace_clock(): |
| # Set trace clock to mono time as chrome tracing in CrOS. |
| PREFERRED_TRACE_CLOCK = 'mono' |
| with open(TRACE_CLOCK) as trace_clock: |
| m = re.match(r'.*\[(\w+)\]', trace_clock.read()) |
| if m: |
| orig_clock = m.group(1) |
| atexit.register(write_to_file, orig_clock, TRACE_CLOCK) |
| write_to_file(PREFERRED_TRACE_CLOCK, TRACE_CLOCK) |
| |
| |
| def get_kernel_symbol_addr(symbol): |
| # Example line in kallsyms: |
| # ffffffffbc46cb03 T sys_exit |
| with open('/proc/kallsyms') as kallsyms: |
| for line in kallsyms: |
| items = line.split() |
| if items[2] == symbol: |
| addr = items[0] |
| return addr |
| return None |
| |
| |
| def set_workq_filter(function_name): |
| addr = get_kernel_symbol_addr(function_name) |
| if addr: |
| filter = 'function == 0x%s' % addr |
| write_to_file(filter, WORKQ_FILTER) |
| # Sets to 0 to remove the filter. |
| atexit.register(write_to_file, '0', WORKQ_FILTER) |
| |
| |
| def enable_tracing(trace_method): |
| """Enables tracing.""" |
| if trace_method == 'workq': |
| set_simple_switch('1', WORKQ_SWITCH) |
| # There are many workqueue_execute_start events, |
| # filter to reduce CPU usage. |
| set_workq_filter('intel_atomic_commit_work') |
| elif trace_method == 'flip': |
| set_simple_switch('1', FLIP_SWITCH) |
| else: |
| set_simple_switch('1', VBLANK_SWITCH) |
| |
| set_simple_switch('1', TRACE_SWITCH) |
| set_trace_clock() |
| |
| |
| def get_fps_info(trace_buffer, end_time): |
| # Checks all vblanks in the range [end_time - 1.0, end_time]. |
| frame_info = [] |
| step = 1.0 / REFRESH_RATE |
| step_time = end_time - 1.0 + step |
| frame_times = [] |
| for _ in range(REFRESH_RATE): |
| # Checks if there are vblanks in a refresh interval. |
| step_count = 0 |
| while trace_buffer and trace_buffer[0] < step_time: |
| frame_times.append(trace_buffer.popleft()) |
| step_count += 1 |
| |
| # Each character represent an 1 / REFRESH_RATE interval. |
| if step_count: |
| if step_count >= 10: |
| frame_info.append('*') |
| else: |
| frame_info.append(str(step_count)) |
| else: |
| frame_info.append(' ') |
| step_time += step |
| |
| return frame_info, frame_times |
| |
| |
| def start_thread(function, args=()): |
| """Starts a thread with given argument.""" |
| new_thread = threading.Thread(target=function, args=args) |
| new_thread.start() |
| |
| |
| class FPSMeter(): |
| """A FPSMeter to measure system FPS periodically.""" |
| def __init__(self, callback): |
| self.is_stopping = threading.Event() |
| self.callback = callback |
| |
| def __enter__(self): |
| self.start() |
| return self |
| |
| def __exit__(self, type, value, traceback): |
| self.stop() |
| |
| def notify_collection(self, period_sec=1.0): |
| """Writes a notification mark periodically.""" |
| logging.info('Notification thread is started') |
| next_notify_time = time.time() + period_sec |
| while True: |
| # Calling time.sleep(1) may suspend for more than 1 second. |
| # Sleeps until a specific time to avoid error accumulation. |
| sleep_time = next_notify_time - time.time() |
| next_notify_time += period_sec |
| # Skips if current time is larger than next_notify_time. |
| if sleep_time > 0: |
| if self.is_stopping.wait(sleep_time): |
| logging.info('Leaving notification thread') |
| # So the main loop doesn't stuck in the readline(). |
| write_to_file(STOP_STRING, TRACE_MARKER) |
| break |
| write_to_file(NOTIFY_STRING, TRACE_MARKER) |
| |
| def main_loop(self, trace_method): |
| """Main loop to parse the trace. |
| |
| There are 2 threads involved: |
| Main thread: |
| Using blocking read to get data from trace_pipe. |
| Notify thread: The main thread may wait indifinitely if there |
| is no new trace. Writes to the pipe once per second to avoid |
| the indefinite waiting. |
| """ |
| logging.info('Fps meter main thread is started.') |
| |
| # Sample trace: |
| # <idle>-0 [000] dNh3 631.905961: drm_vblank_event: crtc=0, seq=65496 |
| # <idle>-0 [000] d.h3 631.922681: drm_vblank_event: crtc=0, seq=65497 |
| # fps_meter [003] ...1 632.393953: tracing_mark_write: notify_collection |
| # ... |
| re_notify = re.compile( |
| r'.* (\d+.\d+): tracing_mark_write: ' + NOTIFY_STRING) |
| if trace_method == 'workq': |
| re_trace = re.compile( |
| r'.* (\d+.\d+): workqueue_execute_start: work struct ([\da-f]+): ' |
| 'function intel_atomic_commit_work') |
| elif trace_method == 'flip': |
| re_trace = re.compile( |
| r'.* (\d+.\d+): i915_flip_complete: plane=(\d+), obj=([\da-f]+)') |
| else: |
| re_trace = re.compile( |
| r'.* (\d+.\d+): drm_vblank_event: crtc=(\d+), seq=(\d+)') |
| |
| trace_buffer = collections.deque() |
| with open(TRACE_PIPE) as trace_pipe: |
| # The pipe may block a few seconds if using: |
| # for line in trace_pipe |
| while not self.is_stopping.is_set(): |
| line = trace_pipe.readline() |
| m_trace = re_trace.match(line) |
| if m_trace: |
| timestamp = float(m_trace.group(1)) |
| trace_buffer.append(timestamp) |
| else: |
| m_notify = re_notify.match(line) |
| if m_notify: |
| timestamp = float(m_notify.group(1)) |
| self.callback(get_fps_info(trace_buffer, timestamp)) |
| logging.info('Leaving fps meter main thread') |
| |
| def start(self): |
| """Starts the FPS meter by launching needed threads.""" |
| # The notificaiton thread. |
| start_thread(self.notify_collection) |
| |
| # The main thread. |
| trace_method = get_trace_method() |
| enable_tracing(trace_method) |
| start_thread(self.main_loop, [trace_method]) |
| |
| def stop(self): |
| """Stops the FPS meter. Shut down threads.""" |
| logging.info('Shutting down FPS meter') |
| self.is_stopping.set() |
| |
| |
| def output_fps_info(verbose, fps_info): |
| frame_info, frame_times = fps_info |
| fps_count = len([f for f in frame_info if f != ' ']) |
| frame_info_str = ''.join(frame_info) |
| print '[%s] FPS: %2d' % (frame_info_str, fps_count) |
| if frame_times and verbose: |
| print ', '.join(['%.3f' % t for t in frame_times]) |
| |
| |
| if __name__ == '__main__': |
| # parsing arguments |
| parser = argparse.ArgumentParser(description='Print fps infomation.') |
| parser.add_argument('-v', dest='verbose', action='store_true', |
| help='print verbose frame time info') |
| parser.add_argument('-d', dest='debug', action='store_true', |
| help='print debug message') |
| args = parser.parse_args() |
| |
| if args.debug: |
| rootLogger = logging.getLogger() |
| rootLogger.setLevel(logging.DEBUG) |
| # StreamHandler() defaults to stderr. |
| rootLogger.addHandler(logging.StreamHandler()) |
| |
| print 'FPS meter trace method %s' % get_trace_method() |
| with FPSMeter(functools.partial(output_fps_info, args.verbose)) as fps_meter: |
| while True: |
| try: |
| time.sleep(86400) |
| except KeyboardInterrupt: |
| print 'Exiting...' |
| break |