1# Copyright (c) 2013 The Chromium OS Authors. All rights reserved.
2# Use of this source code is governed by a BSD-style license that can be
3# found in the LICENSE file.
4
5import logging
6import numpy
7import os
8import re
9import threading
10import time
11
12TRACING_DIR = '/sys/kernel/debug/tracing'
13BUFFER_SIZE_RUNNING = '5000'
14BUFFER_SIZE_IDLE = '1408'
15
16def tracing_write(file_name, msg):
17    """Helper method to write a file in kernel debugfs.
18
19    @param file_name: The file to write in debugfs.
20    @param msg: The content to write.
21    """
22    with open(os.path.join(TRACING_DIR, file_name), 'w') as f:
23        f.write(msg)
24        f.flush()
25
26
27def enable_tracing(events_list=None):
28    """Enable kernel tracing.
29
30    @param events_list: The list of events to monitor.  Defaults to None to
31        monitor all events.
32    """
33    tracing_write('trace_clock', 'global')
34    tracing_write('buffer_size_kb', BUFFER_SIZE_RUNNING)
35    if events_list:
36        tracing_write('set_event', '\n'.join(events_list))
37    tracing_write('tracing_on', '1')
38
39
40def disable_tracing():
41    """Disable kernel tracing."""
42    tracing_write('tracing_on', '0')
43    tracing_write('set_event', '')
44    tracing_write('trace', '0')
45    tracing_write('buffer_size_kb', BUFFER_SIZE_IDLE)
46
47
48def get_trace_log():
49    """Get kernel tracing log."""
50    with open(os.path.join(TRACING_DIR, 'trace'), 'r') as f:
51        return f.read()
52
53
54class Sampler(object):
55    """Base sampler class."""
56
57    def __init__(self, period, duration, events=None):
58        self.period = period
59        self.duration = duration
60        self.events = events or []
61        self.sampler_callback = None
62        self.stop_sampling = threading.Event()
63        self.sampling_thread = None
64
65    @property
66    def stopped(self):
67        """Check if sampler is stopped."""
68        return self.stop_sampling.is_set()
69
70    def _do_sampling(self):
71        """Main sampling loop."""
72        while True:
73            next_sampling_time = time.time() + self.period
74            try:
75                enable_tracing(events_list=self.events)
76                if self.stop_sampling.wait(self.duration):
77                    return
78                self.parse_ftrace(get_trace_log())
79                self.sampler_callback(self)
80            finally:
81                disable_tracing()
82                self.reset()
83            if self.stop_sampling.wait(next_sampling_time - time.time()):
84                return
85
86    def start_sampling_thread(self):
87        """Start a thread to sample events."""
88        if not self.sampler_callback:
89            raise RuntimeError('Sampler callback function is not set')
90        self.stop_sampling.clear()
91        self.sampling_thread = threading.Thread(target=self._do_sampling)
92        self.sampling_thread.daemon = True
93        self.sampling_thread.start()
94
95    def stop_sampling_thread(self):
96        """Stop sampling thread."""
97        self.stop_sampling.set()
98        self.reset()
99
100    def parse_ftrace(self, data):
101        """Parse ftrace data.
102
103        @param data: The ftrace data to parse.
104        """
105        raise NotImplementedError
106
107    def reset(self):
108        """Reset the sampler."""
109        raise NotImplementedError
110
111
112class ExynosSampler(Sampler):
113    """Sampler for Exynos platform."""
114    def __init__(self, *args, **kwargs):
115        kwargs['events'] = ['exynos_page_flip_state']
116        super(ExynosSampler, self).__init__(*args, **kwargs)
117        self.frame_buffers = {}
118
119    def reset(self):
120        self.frame_buffers.clear()
121
122    def parse_ftrace(self, data):
123        """Read and parse the ftrace file"""
124        # Parse using RE and named group match (?P<xxx>yyy) for clarity.
125        # Format:
126        # TASK-PID CPU#  |||| TIMESTAMP  FUNCTION
127        #    X-007 [001] .... 001.000001: (a line-wrap in Python here ...)
128        #          exynos_page_flip_state: pipe=0, fb=25, state=wait_kds
129        re_pattern = (
130            '\s*(?P<task>.+)-' + # task
131            '(?P<pid>\d+)\s+' + # pid
132            '\[(?P<cpu>\d+)\]\s+' + # cpu#
133            '(?P<inhp>....)\s+' + # inhp: irqs-off, need-resched,
134                                  #       hardirq/softirq, preempt-depth
135            '(?P<timestamp>\d+\.\d+):\s+' + # timestamp
136            '(?P<head>exynos_page_flip_state):\s+' + # head
137            '(?P<detail>.*)') # detail: 'pipe=0, fb=25, state=wait_kds'
138
139        for line in data.split('\n'):
140            m = re.match(re_pattern, line)
141            if m is None: # not a valid trace line (e.g. comment)
142                continue
143            m_dict = m.groupdict() # named group of RE match (m_dict['task']...)
144            pipe, fb, state = self.exynos_parser(m_dict['detail'])
145            timestamp = float(m_dict['timestamp'])
146            self.end_last_fb_state(pipe, fb, timestamp)
147            self.start_new_fb_state(pipe, fb, state, timestamp)
148
149        self.calc_stat()
150
151    def exynos_parser(self, detail):
152        """Parse exynos event's detail.
153
154        @param detail: a string like 'pipe=0, fb=25, state=wait_kds'
155        @return: tuple of (pipe, fb, state), pipe and fb in int,
156                 state in string
157        """
158        re_pattern = (
159            'pipe=(?P<pipe>\d+), ' + # pipe
160            'fb=(?P<fb>\d+), ' + # fb
161            'state=(?P<state>.*)') # state
162        if re.match(re_pattern, detail) is None:
163            logging.debug('==fail==' + re_pattern + ', ' + detail)
164        m_dict = re.match(re_pattern, detail).groupdict()
165        return int(m_dict['pipe']), int(m_dict['fb']), m_dict['state']
166
167    def end_last_fb_state(self, pipe, fb, end_time):
168        """End the currently opened state of the specified frame buffer
169
170        @param pipe: the pipe id
171        @param fb: the frame buffer id
172        @param end_time: timestamp when the state ends
173        """
174        self.get_frame_buffer(pipe, fb).end_state(end_time)
175
176    def start_new_fb_state(self, pipe, fb, state, start_time):
177        """Start the specified state on the specified frame buffer
178
179        @param pipe: the pipe id
180        @param fb: the frame buffer id
181        @param state: which state to start
182        @param start_time: timestamp when the state starts
183        """
184        self.get_frame_buffer(pipe, fb).start_state(state, start_time)
185
186    def calc_stat(self):
187        """Calculate the statistics of state duration of all frame buffers"""
188        for fb in self.frame_buffers.values():
189            fb.calc_state_avg_stdev()
190
191    def frame_buffer_unique_hash(self, pipe, fb):
192        """A hash function that returns the unique identifier of a frame buffer.
193           The hash is a string that is unique in the sense of pipe and fb.
194
195        @param pipe: the pipe id
196        @param fb: the frame buffer id
197        @return: a unique hash string, like "pipe:0,fb:25"
198        """
199        return "pipe:%d,fb:%d" % (pipe, fb)
200
201    def get_frame_buffer(self, pipe, fb):
202        """Return the frame buffer with specified pipe and fb.
203           If the frame buffer does not exist, create one and return it.
204
205        @param pipe: the pipe id
206        @param fb: the frame buffer id
207        @return: the frame buffer specified by pipe and fb
208        """
209        key = self.frame_buffer_unique_hash(pipe, fb)
210        if key not in self.frame_buffers:
211            self.frame_buffers[key] = FrameBuffer(pipe, fb)
212        return self.frame_buffers[key]
213
214
215class FrameBuffer():
216    """Represents a frame buffer, which holds all its states"""
217    def __init__(self, pipe, fb):
218        """Initialize the frame buffer.
219
220        @param pipe: the pipe id of the frame buffer
221        @param fb: the fb id of the frame buffer
222        """
223        self.pipe = pipe
224        self.fb = fb
225        self.states = {}
226        self.active_state = None # currently active state (to be ended later)
227
228    def start_state(self, state_name, start_time):
229        """Start the specified state
230
231        @param state_name: name of the state to be started
232        @param start_time: timestamp when the state starts
233        """
234        if state_name not in self.states:
235            self.states[state_name] = State(state_name)
236        self.states[state_name].start(start_time)
237        self.active_state = state_name
238
239    def end_state(self, end_time):
240        """End the specified state, in which the duration will be stored
241
242        @param end_time: timestamp when the state ends
243        """
244        if self.active_state is not None:
245            self.states[self.active_state].end(end_time)
246            self.active_state = None
247
248    def calc_state_avg_stdev(self):
249        """Call all states to compute its own average and standard deviation"""
250        logging.debug("====pipe:%d, fb:%d====", self.pipe, self.fb)
251        for s in self.states.values():
252            s.calc_avg_stdev()
253
254
255class State():
256    """Hold the data of a specific state (e.g. wait_kds, wait_apply, ...)"""
257    def __init__(self, state_name):
258        """Initialize data
259
260        @param state_name: name of this state
261        """
262        self.state_name = state_name
263        self.last_start_time = None
264        self.duration_data = []
265        self.avg = None
266        self.stdev = None
267
268    def start(self, start_time):
269        """Mark this state as started by saving the start time
270
271        @param start_time: timestamp when the state starts
272        """
273        self.last_start_time = start_time
274
275    def end(self, end_time):
276        """Save the state's duration and mark this state as ended
277
278        @param end_time: timestamp when the state ends
279        """
280        if self.last_start_time is not None:
281            self.duration_data.append(end_time - self.last_start_time)
282            self.last_start_time = None
283
284    def calc_avg_stdev(self):
285        """Calculate the average and standard deviation of all duration data"""
286        self.avg = numpy.mean(self.duration_data)
287        self.stdev = numpy.std(self.duration_data)
288