• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
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