| #!/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. |
| |
| Sample output: |
| # ./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. |
| """ |
| import argparse |
| import atexit |
| import collections |
| 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' |
| |
| |
| def 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): |
| 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): |
| 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 notify_collection(period_sec=1.0): |
| 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: |
| time.sleep(sleep_time) |
| write_to_file(NOTIFY_STRING, TRACE_MARKER) |
| |
| |
| def start_notify_thread(): |
| notify_thread = threading.Thread(target=notify_collection) |
| notify_thread.daemon = True |
| notify_thread.start() |
| |
| |
| def process_trace_buffer(trace_buffer, end_time, verbose=False): |
| # 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 |
| fps_count = 0 |
| 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)) |
| fps_count += 1 |
| else: |
| frame_info.append(' ') |
| step_time += step |
| |
| 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]) |
| |
| |
| def main_loop(trace_method, verbose=False): |
| """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. |
| """ |
| start_notify_thread() |
| |
| # 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 True: |
| 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)) |
| process_trace_buffer(trace_buffer, timestamp, verbose) |
| |
| |
| 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') |
| args = parser.parse_args() |
| |
| trace_method = get_trace_method() |
| print 'trace method:', trace_method |
| enable_tracing(trace_method) |
| main_loop(trace_method, args.verbose) |
| |