1# Copyright 2015 ARM Limited 2# 3# Licensed under the Apache License, Version 2.0 (the "License"); 4# you may not use this file except in compliance with the License. 5# You may obtain a copy of the License at 6# 7# http://www.apache.org/licenses/LICENSE-2.0 8# 9# Unless required by applicable law or agreed to in writing, software 10# distributed under the License is distributed on an "AS IS" BASIS, 11# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 12# See the License for the specific language governing permissions and 13# limitations under the License. 14# 15 16from __future__ import division 17import os 18import json 19import time 20import re 21import subprocess 22 23from devlib.trace import TraceCollector 24from devlib.host import PACKAGE_BIN_DIRECTORY 25from devlib.exception import TargetError, HostError 26from devlib.utils.misc import check_output, which 27 28 29TRACE_MARKER_START = 'TRACE_MARKER_START' 30TRACE_MARKER_STOP = 'TRACE_MARKER_STOP' 31OUTPUT_TRACE_FILE = 'trace.dat' 32OUTPUT_PROFILE_FILE = 'trace_stat.dat' 33DEFAULT_EVENTS = [ 34 'cpu_frequency', 35 'cpu_idle', 36 'sched_migrate_task', 37 'sched_process_exec', 38 'sched_process_fork', 39 'sched_stat_iowait', 40 'sched_switch', 41 'sched_wakeup', 42 'sched_wakeup_new', 43] 44TIMEOUT = 180 45 46# Regexps for parsing of function profiling data 47CPU_RE = re.compile(r' Function \(CPU([0-9]+)\)') 48STATS_RE = re.compile(r'([^ ]*) +([0-9]+) +([0-9.]+) us +([0-9.]+) us +([0-9.]+) us') 49 50class FtraceCollector(TraceCollector): 51 52 def __init__(self, target, 53 events=None, 54 functions=None, 55 buffer_size=None, 56 buffer_size_step=1000, 57 tracing_path='/sys/kernel/debug/tracing', 58 automark=True, 59 autoreport=True, 60 autoview=False, 61 no_install=False, 62 strict=False, 63 report_on_target=False, 64 ): 65 super(FtraceCollector, self).__init__(target) 66 self.events = events if events is not None else DEFAULT_EVENTS 67 self.functions = functions 68 self.buffer_size = buffer_size 69 self.buffer_size_step = buffer_size_step 70 self.tracing_path = tracing_path 71 self.automark = automark 72 self.autoreport = autoreport 73 self.autoview = autoview 74 self.report_on_target = report_on_target 75 self.target_output_file = target.path.join(self.target.working_directory, OUTPUT_TRACE_FILE) 76 text_file_name = target.path.splitext(OUTPUT_TRACE_FILE)[0] + '.txt' 77 self.target_text_file = target.path.join(self.target.working_directory, text_file_name) 78 self.target_binary = None 79 self.host_binary = None 80 self.start_time = None 81 self.stop_time = None 82 self.event_string = None 83 self.function_string = None 84 self._reset_needed = True 85 86 # Setup tracing paths 87 self.available_events_file = self.target.path.join(self.tracing_path, 'available_events') 88 self.available_functions_file = self.target.path.join(self.tracing_path, 'available_filter_functions') 89 self.buffer_size_file = self.target.path.join(self.tracing_path, 'buffer_size_kb') 90 self.current_tracer_file = self.target.path.join(self.tracing_path, 'current_tracer') 91 self.function_profile_file = self.target.path.join(self.tracing_path, 'function_profile_enabled') 92 self.marker_file = self.target.path.join(self.tracing_path, 'trace_marker') 93 self.ftrace_filter_file = self.target.path.join(self.tracing_path, 'set_ftrace_filter') 94 95 self.host_binary = which('trace-cmd') 96 self.kernelshark = which('kernelshark') 97 98 if not self.target.is_rooted: 99 raise TargetError('trace-cmd instrument cannot be used on an unrooted device.') 100 if self.autoreport and not self.report_on_target and self.host_binary is None: 101 raise HostError('trace-cmd binary must be installed on the host if autoreport=True.') 102 if self.autoview and self.kernelshark is None: 103 raise HostError('kernelshark binary must be installed on the host if autoview=True.') 104 if not no_install: 105 host_file = os.path.join(PACKAGE_BIN_DIRECTORY, self.target.abi, 'trace-cmd') 106 self.target_binary = self.target.install(host_file) 107 else: 108 if not self.target.is_installed('trace-cmd'): 109 raise TargetError('No trace-cmd found on device and no_install=True is specified.') 110 self.target_binary = 'trace-cmd' 111 112 # Validate required events to be traced 113 available_events = self.target.execute( 114 'cat {}'.format(self.available_events_file), 115 as_root=True).splitlines() 116 selected_events = [] 117 for event in self.events: 118 # Convert globs supported by FTrace into valid regexp globs 119 _event = event 120 if event[0] != '*': 121 _event = '*' + event 122 event_re = re.compile(_event.replace('*', '.*')) 123 # Select events matching the required ones 124 if len(filter(event_re.match, available_events)) == 0: 125 message = 'Event [{}] not available for tracing'.format(event) 126 if strict: 127 raise TargetError(message) 128 self.target.logger.warning(message) 129 else: 130 selected_events.append(event) 131 # If function profiling is enabled we always need at least one event. 132 # Thus, if not other events have been specified, try to add at least 133 # a tracepoint which is always available and possibly triggered few 134 # times. 135 if self.functions and len(selected_events) == 0: 136 selected_events = ['sched_wakeup_new'] 137 self.event_string = _build_trace_events(selected_events) 138 139 # Check for function tracing support 140 if self.functions: 141 if not self.target.file_exists(self.function_profile_file): 142 raise TargetError('Function profiling not supported. '\ 143 'A kernel build with CONFIG_FUNCTION_PROFILER enable is required') 144 # Validate required functions to be traced 145 available_functions = self.target.execute( 146 'cat {}'.format(self.available_functions_file), 147 as_root=True).splitlines() 148 selected_functions = [] 149 for function in self.functions: 150 if function not in available_functions: 151 message = 'Function [{}] not available for profiling'.format(function) 152 if strict: 153 raise TargetError(message) 154 self.target.logger.warning(message) 155 else: 156 selected_functions.append(function) 157 self.function_string = _build_trace_functions(selected_functions) 158 159 def reset(self): 160 if self.buffer_size: 161 self._set_buffer_size() 162 self.target.execute('{} reset'.format(self.target_binary), 163 as_root=True, timeout=TIMEOUT) 164 self._reset_needed = False 165 166 def start(self): 167 self.start_time = time.time() 168 if self._reset_needed: 169 self.reset() 170 self.target.execute('{} start {}'.format(self.target_binary, self.event_string), 171 as_root=True) 172 if self.automark: 173 self.mark_start() 174 if 'cpufreq' in self.target.modules: 175 self.logger.debug('Trace CPUFreq frequencies') 176 self.target.cpufreq.trace_frequencies() 177 if 'cpuidle' in self.target.modules: 178 self.logger.debug('Trace CPUIdle states') 179 self.target.cpuidle.perturb_cpus() 180 # Enable kernel function profiling 181 if self.functions: 182 self.target.execute('echo nop > {}'.format(self.current_tracer_file), 183 as_root=True) 184 self.target.execute('echo 0 > {}'.format(self.function_profile_file), 185 as_root=True) 186 self.target.execute('echo {} > {}'.format(self.function_string, self.ftrace_filter_file), 187 as_root=True) 188 self.target.execute('echo 1 > {}'.format(self.function_profile_file), 189 as_root=True) 190 191 192 def stop(self): 193 # Disable kernel function profiling 194 if self.functions: 195 self.target.execute('echo 1 > {}'.format(self.function_profile_file), 196 as_root=True) 197 if 'cpufreq' in self.target.modules: 198 self.logger.debug('Trace CPUFreq frequencies') 199 self.target.cpufreq.trace_frequencies() 200 self.stop_time = time.time() 201 if self.automark: 202 self.mark_stop() 203 self.target.execute('{} stop'.format(self.target_binary), 204 timeout=TIMEOUT, as_root=True) 205 self._reset_needed = True 206 207 def get_trace(self, outfile): 208 if os.path.isdir(outfile): 209 outfile = os.path.join(outfile, os.path.basename(self.target_output_file)) 210 self.target.execute('{0} extract -o {1}; chmod 666 {1}'.format(self.target_binary, 211 self.target_output_file), 212 timeout=TIMEOUT, as_root=True) 213 214 # The size of trace.dat will depend on how long trace-cmd was running. 215 # Therefore timout for the pull command must also be adjusted 216 # accordingly. 217 pull_timeout = 5 * (self.stop_time - self.start_time) 218 self.target.pull(self.target_output_file, outfile, timeout=pull_timeout) 219 if not os.path.isfile(outfile): 220 self.logger.warning('Binary trace not pulled from device.') 221 else: 222 if self.autoreport: 223 textfile = os.path.splitext(outfile)[0] + '.txt' 224 if self.report_on_target: 225 self.generate_report_on_target() 226 self.target.pull(self.target_text_file, 227 textfile, timeout=pull_timeout) 228 else: 229 self.report(outfile, textfile) 230 if self.autoview: 231 self.view(outfile) 232 233 def get_stats(self, outfile): 234 if not self.functions: 235 return 236 237 if os.path.isdir(outfile): 238 outfile = os.path.join(outfile, OUTPUT_PROFILE_FILE) 239 output = self.target._execute_util('ftrace_get_function_stats', 240 as_root=True) 241 242 function_stats = {} 243 for line in output.splitlines(): 244 # Match a new CPU dataset 245 match = CPU_RE.search(line) 246 if match: 247 cpu_id = int(match.group(1)) 248 function_stats[cpu_id] = {} 249 self.logger.debug("Processing stats for CPU%d...", cpu_id) 250 continue 251 # Match a new function dataset 252 match = STATS_RE.search(line) 253 if match: 254 fname = match.group(1) 255 function_stats[cpu_id][fname] = { 256 'hits' : int(match.group(2)), 257 'time' : float(match.group(3)), 258 'avg' : float(match.group(4)), 259 's_2' : float(match.group(5)), 260 } 261 self.logger.debug(" %s: %s", 262 fname, function_stats[cpu_id][fname]) 263 264 self.logger.debug("FTrace stats output [%s]...", outfile) 265 with open(outfile, 'w') as fh: 266 json.dump(function_stats, fh, indent=4) 267 self.logger.debug("FTrace function stats save in [%s]", outfile) 268 269 return function_stats 270 271 def report(self, binfile, destfile): 272 # To get the output of trace.dat, trace-cmd must be installed 273 # This is done host-side because the generated file is very large 274 try: 275 command = '{} report {} > {}'.format(self.host_binary, binfile, destfile) 276 self.logger.debug(command) 277 process = subprocess.Popen(command, stderr=subprocess.PIPE, shell=True) 278 _, error = process.communicate() 279 if process.returncode: 280 raise TargetError('trace-cmd returned non-zero exit code {}'.format(process.returncode)) 281 if error: 282 # logged at debug level, as trace-cmd always outputs some 283 # errors that seem benign. 284 self.logger.debug(error) 285 if os.path.isfile(destfile): 286 self.logger.debug('Verifying traces.') 287 with open(destfile) as fh: 288 for line in fh: 289 if 'EVENTS DROPPED' in line: 290 self.logger.warning('Dropped events detected.') 291 break 292 else: 293 self.logger.debug('Trace verified.') 294 else: 295 self.logger.warning('Could not generate trace.txt.') 296 except OSError: 297 raise HostError('Could not find trace-cmd. Please make sure it is installed and is in PATH.') 298 299 def generate_report_on_target(self): 300 command = '{} report {} > {}'.format(self.target_binary, 301 self.target_output_file, 302 self.target_text_file) 303 self.target.execute(command, timeout=TIMEOUT) 304 305 def view(self, binfile): 306 check_output('{} {}'.format(self.kernelshark, binfile), shell=True) 307 308 def teardown(self): 309 self.target.remove(self.target.path.join(self.target.working_directory, OUTPUT_TRACE_FILE)) 310 311 def mark_start(self): 312 self.target.write_value(self.marker_file, TRACE_MARKER_START, verify=False) 313 314 def mark_stop(self): 315 self.target.write_value(self.marker_file, TRACE_MARKER_STOP, verify=False) 316 317 def _set_buffer_size(self): 318 target_buffer_size = self.buffer_size 319 attempt_buffer_size = target_buffer_size 320 buffer_size = 0 321 floor = 1000 if target_buffer_size > 1000 else target_buffer_size 322 while attempt_buffer_size >= floor: 323 self.target.write_value(self.buffer_size_file, attempt_buffer_size, verify=False) 324 buffer_size = self.target.read_int(self.buffer_size_file) 325 if buffer_size == attempt_buffer_size: 326 break 327 else: 328 attempt_buffer_size -= self.buffer_size_step 329 if buffer_size == target_buffer_size: 330 return 331 while attempt_buffer_size < target_buffer_size: 332 attempt_buffer_size += self.buffer_size_step 333 self.target.write_value(self.buffer_size_file, attempt_buffer_size, verify=False) 334 buffer_size = self.target.read_int(self.buffer_size_file) 335 if attempt_buffer_size != buffer_size: 336 message = 'Failed to set trace buffer size to {}, value set was {}' 337 self.logger.warning(message.format(target_buffer_size, buffer_size)) 338 break 339 340 341def _build_trace_events(events): 342 event_string = ' '.join(['-e {}'.format(e) for e in events]) 343 return event_string 344 345def _build_trace_functions(functions): 346 function_string = " ".join(functions) 347 return function_string 348