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