fps_meter: measuring fps with ftrace
Sample output:
[111111111111111111111111111111111111111111111111111111111111] FPS: 60
[11111111111111 11111111111111111111 11111111 111111111111111] FPS: 57
[111111111111111111111111111111111 11111111111111111111111] FPS: 56
BUG=chromium:805780
TEST=manual test
Change-Id: Id174a1027aca4e7d3365338331a64f16cf886f04
Reviewed-on: https://chromium-review.googlesource.com/880532
Commit-Ready: Vovo Yang <vovoy@chromium.org>
Tested-by: Vovo Yang <vovoy@chromium.org>
Reviewed-by: Cheng-Yu Lee <cylee@google.com>
diff --git a/fps_meter/fps_meter.py b/fps_meter/fps_meter.py
new file mode 100755
index 0000000..c7ca29a
--- /dev/null
+++ b/fps_meter/fps_meter.py
@@ -0,0 +1,237 @@
+#!/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 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):
+ # 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
+ 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:
+ 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)
+
+
+def main_loop(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.
+ """
+ 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)
+
+
+if __name__ == '__main__':
+ trace_method = get_trace_method()
+ print 'trace method:', trace_method
+ enable_tracing(trace_method)
+ main_loop(trace_method)
+
