| # Copyright 2015 ARM Limited |
| # |
| # Licensed under the Apache License, Version 2.0 (the "License"); |
| # you may not use this file except in compliance with the License. |
| # You may obtain a copy of the License at |
| # |
| # http://www.apache.org/licenses/LICENSE-2.0 |
| # |
| # Unless required by applicable law or agreed to in writing, software |
| # distributed under the License is distributed on an "AS IS" BASIS, |
| # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
| # See the License for the specific language governing permissions and |
| # limitations under the License. |
| # |
| |
| from __future__ import division |
| import os |
| import json |
| import time |
| import re |
| import subprocess |
| |
| from devlib.trace import TraceCollector |
| from devlib.host import PACKAGE_BIN_DIRECTORY |
| from devlib.exception import TargetError, HostError |
| from devlib.utils.misc import check_output, which |
| |
| |
| TRACE_MARKER_START = 'TRACE_MARKER_START' |
| TRACE_MARKER_STOP = 'TRACE_MARKER_STOP' |
| OUTPUT_TRACE_FILE = 'trace.dat' |
| OUTPUT_PROFILE_FILE = 'trace_stat.dat' |
| DEFAULT_EVENTS = [ |
| 'cpu_frequency', |
| 'cpu_idle', |
| 'sched_migrate_task', |
| 'sched_process_exec', |
| 'sched_process_fork', |
| 'sched_stat_iowait', |
| 'sched_switch', |
| 'sched_wakeup', |
| 'sched_wakeup_new', |
| ] |
| TIMEOUT = 180 |
| |
| # Regexps for parsing of function profiling data |
| CPU_RE = re.compile(r' Function \(CPU([0-9]+)\)') |
| STATS_RE = re.compile(r'([^ ]*) +([0-9]+) +([0-9.]+) us +([0-9.]+) us +([0-9.]+) us') |
| |
| class FtraceCollector(TraceCollector): |
| |
| def __init__(self, target, |
| events=None, |
| functions=None, |
| buffer_size=None, |
| buffer_size_step=1000, |
| tracing_path='/sys/kernel/debug/tracing', |
| automark=True, |
| autoreport=True, |
| autoview=False, |
| no_install=False, |
| strict=False, |
| report_on_target=False, |
| ): |
| super(FtraceCollector, self).__init__(target) |
| self.events = events if events is not None else DEFAULT_EVENTS |
| self.functions = functions |
| self.buffer_size = buffer_size |
| self.buffer_size_step = buffer_size_step |
| self.tracing_path = tracing_path |
| self.automark = automark |
| self.autoreport = autoreport |
| self.autoview = autoview |
| self.report_on_target = report_on_target |
| self.target_output_file = target.path.join(self.target.working_directory, OUTPUT_TRACE_FILE) |
| text_file_name = target.path.splitext(OUTPUT_TRACE_FILE)[0] + '.txt' |
| self.target_text_file = target.path.join(self.target.working_directory, text_file_name) |
| self.target_binary = None |
| self.host_binary = None |
| self.start_time = None |
| self.stop_time = None |
| self.event_string = None |
| self.function_string = None |
| self._reset_needed = True |
| |
| # Setup tracing paths |
| self.available_events_file = self.target.path.join(self.tracing_path, 'available_events') |
| self.available_functions_file = self.target.path.join(self.tracing_path, 'available_filter_functions') |
| self.buffer_size_file = self.target.path.join(self.tracing_path, 'buffer_size_kb') |
| self.current_tracer_file = self.target.path.join(self.tracing_path, 'current_tracer') |
| self.function_profile_file = self.target.path.join(self.tracing_path, 'function_profile_enabled') |
| self.marker_file = self.target.path.join(self.tracing_path, 'trace_marker') |
| self.ftrace_filter_file = self.target.path.join(self.tracing_path, 'set_ftrace_filter') |
| |
| self.host_binary = which('trace-cmd') |
| self.kernelshark = which('kernelshark') |
| |
| if not self.target.is_rooted: |
| raise TargetError('trace-cmd instrument cannot be used on an unrooted device.') |
| if self.autoreport and not self.report_on_target and self.host_binary is None: |
| raise HostError('trace-cmd binary must be installed on the host if autoreport=True.') |
| if self.autoview and self.kernelshark is None: |
| raise HostError('kernelshark binary must be installed on the host if autoview=True.') |
| if not no_install: |
| host_file = os.path.join(PACKAGE_BIN_DIRECTORY, self.target.abi, 'trace-cmd') |
| self.target_binary = self.target.install(host_file) |
| else: |
| if not self.target.is_installed('trace-cmd'): |
| raise TargetError('No trace-cmd found on device and no_install=True is specified.') |
| self.target_binary = 'trace-cmd' |
| |
| # Validate required events to be traced |
| available_events = self.target.execute( |
| 'cat {}'.format(self.available_events_file), |
| as_root=True).splitlines() |
| selected_events = [] |
| for event in self.events: |
| # Convert globs supported by FTrace into valid regexp globs |
| _event = event |
| if event[0] != '*': |
| _event = '*' + event |
| event_re = re.compile(_event.replace('*', '.*')) |
| # Select events matching the required ones |
| if len(filter(event_re.match, available_events)) == 0: |
| message = 'Event [{}] not available for tracing'.format(event) |
| if strict: |
| raise TargetError(message) |
| self.target.logger.warning(message) |
| else: |
| selected_events.append(event) |
| # If function profiling is enabled we always need at least one event. |
| # Thus, if not other events have been specified, try to add at least |
| # a tracepoint which is always available and possibly triggered few |
| # times. |
| if self.functions and len(selected_events) == 0: |
| selected_events = ['sched_wakeup_new'] |
| self.event_string = _build_trace_events(selected_events) |
| |
| # Check for function tracing support |
| if self.functions: |
| if not self.target.file_exists(self.function_profile_file): |
| raise TargetError('Function profiling not supported. '\ |
| 'A kernel build with CONFIG_FUNCTION_PROFILER enable is required') |
| # Validate required functions to be traced |
| available_functions = self.target.execute( |
| 'cat {}'.format(self.available_functions_file), |
| as_root=True).splitlines() |
| selected_functions = [] |
| for function in self.functions: |
| if function not in available_functions: |
| message = 'Function [{}] not available for profiling'.format(function) |
| if strict: |
| raise TargetError(message) |
| self.target.logger.warning(message) |
| else: |
| selected_functions.append(function) |
| self.function_string = _build_trace_functions(selected_functions) |
| |
| def reset(self): |
| if self.buffer_size: |
| self._set_buffer_size() |
| self.target.execute('{} reset'.format(self.target_binary), |
| as_root=True, timeout=TIMEOUT) |
| self._reset_needed = False |
| |
| def start(self): |
| self.start_time = time.time() |
| if self._reset_needed: |
| self.reset() |
| self.target.execute('{} start {}'.format(self.target_binary, self.event_string), |
| as_root=True) |
| if self.automark: |
| self.mark_start() |
| if 'cpufreq' in self.target.modules: |
| self.logger.debug('Trace CPUFreq frequencies') |
| self.target.cpufreq.trace_frequencies() |
| if 'cpuidle' in self.target.modules: |
| self.logger.debug('Trace CPUIdle states') |
| self.target.cpuidle.perturb_cpus() |
| # Enable kernel function profiling |
| if self.functions: |
| self.target.execute('echo nop > {}'.format(self.current_tracer_file), |
| as_root=True) |
| self.target.execute('echo 0 > {}'.format(self.function_profile_file), |
| as_root=True) |
| self.target.execute('echo {} > {}'.format(self.function_string, self.ftrace_filter_file), |
| as_root=True) |
| self.target.execute('echo 1 > {}'.format(self.function_profile_file), |
| as_root=True) |
| |
| |
| def stop(self): |
| # Disable kernel function profiling |
| if self.functions: |
| self.target.execute('echo 1 > {}'.format(self.function_profile_file), |
| as_root=True) |
| if 'cpufreq' in self.target.modules: |
| self.logger.debug('Trace CPUFreq frequencies') |
| self.target.cpufreq.trace_frequencies() |
| self.stop_time = time.time() |
| if self.automark: |
| self.mark_stop() |
| self.target.execute('{} stop'.format(self.target_binary), |
| timeout=TIMEOUT, as_root=True) |
| self._reset_needed = True |
| |
| def get_trace(self, outfile): |
| if os.path.isdir(outfile): |
| outfile = os.path.join(outfile, os.path.basename(self.target_output_file)) |
| self.target.execute('{0} extract -o {1}; chmod 666 {1}'.format(self.target_binary, |
| self.target_output_file), |
| timeout=TIMEOUT, as_root=True) |
| |
| # The size of trace.dat will depend on how long trace-cmd was running. |
| # Therefore timout for the pull command must also be adjusted |
| # accordingly. |
| pull_timeout = 5 * (self.stop_time - self.start_time) |
| self.target.pull(self.target_output_file, outfile, timeout=pull_timeout) |
| if not os.path.isfile(outfile): |
| self.logger.warning('Binary trace not pulled from device.') |
| else: |
| if self.autoreport: |
| textfile = os.path.splitext(outfile)[0] + '.txt' |
| if self.report_on_target: |
| self.generate_report_on_target() |
| self.target.pull(self.target_text_file, |
| textfile, timeout=pull_timeout) |
| else: |
| self.report(outfile, textfile) |
| if self.autoview: |
| self.view(outfile) |
| |
| def get_stats(self, outfile): |
| if not self.functions: |
| return |
| |
| if os.path.isdir(outfile): |
| outfile = os.path.join(outfile, OUTPUT_PROFILE_FILE) |
| output = self.target._execute_util('ftrace_get_function_stats', |
| as_root=True) |
| |
| function_stats = {} |
| for line in output.splitlines(): |
| # Match a new CPU dataset |
| match = CPU_RE.search(line) |
| if match: |
| cpu_id = int(match.group(1)) |
| function_stats[cpu_id] = {} |
| self.logger.debug("Processing stats for CPU%d...", cpu_id) |
| continue |
| # Match a new function dataset |
| match = STATS_RE.search(line) |
| if match: |
| fname = match.group(1) |
| function_stats[cpu_id][fname] = { |
| 'hits' : int(match.group(2)), |
| 'time' : float(match.group(3)), |
| 'avg' : float(match.group(4)), |
| 's_2' : float(match.group(5)), |
| } |
| self.logger.debug(" %s: %s", |
| fname, function_stats[cpu_id][fname]) |
| |
| self.logger.debug("FTrace stats output [%s]...", outfile) |
| with open(outfile, 'w') as fh: |
| json.dump(function_stats, fh, indent=4) |
| self.logger.debug("FTrace function stats save in [%s]", outfile) |
| |
| return function_stats |
| |
| def report(self, binfile, destfile): |
| # To get the output of trace.dat, trace-cmd must be installed |
| # This is done host-side because the generated file is very large |
| try: |
| command = '{} report {} > {}'.format(self.host_binary, binfile, destfile) |
| self.logger.debug(command) |
| process = subprocess.Popen(command, stderr=subprocess.PIPE, shell=True) |
| _, error = process.communicate() |
| if process.returncode: |
| raise TargetError('trace-cmd returned non-zero exit code {}'.format(process.returncode)) |
| if error: |
| # logged at debug level, as trace-cmd always outputs some |
| # errors that seem benign. |
| self.logger.debug(error) |
| if os.path.isfile(destfile): |
| self.logger.debug('Verifying traces.') |
| with open(destfile) as fh: |
| for line in fh: |
| if 'EVENTS DROPPED' in line: |
| self.logger.warning('Dropped events detected.') |
| break |
| else: |
| self.logger.debug('Trace verified.') |
| else: |
| self.logger.warning('Could not generate trace.txt.') |
| except OSError: |
| raise HostError('Could not find trace-cmd. Please make sure it is installed and is in PATH.') |
| |
| def generate_report_on_target(self): |
| command = '{} report {} > {}'.format(self.target_binary, |
| self.target_output_file, |
| self.target_text_file) |
| self.target.execute(command, timeout=TIMEOUT) |
| |
| def view(self, binfile): |
| check_output('{} {}'.format(self.kernelshark, binfile), shell=True) |
| |
| def teardown(self): |
| self.target.remove(self.target.path.join(self.target.working_directory, OUTPUT_TRACE_FILE)) |
| |
| def mark_start(self): |
| self.target.write_value(self.marker_file, TRACE_MARKER_START, verify=False) |
| |
| def mark_stop(self): |
| self.target.write_value(self.marker_file, TRACE_MARKER_STOP, verify=False) |
| |
| def _set_buffer_size(self): |
| target_buffer_size = self.buffer_size |
| attempt_buffer_size = target_buffer_size |
| buffer_size = 0 |
| floor = 1000 if target_buffer_size > 1000 else target_buffer_size |
| while attempt_buffer_size >= floor: |
| self.target.write_value(self.buffer_size_file, attempt_buffer_size, verify=False) |
| buffer_size = self.target.read_int(self.buffer_size_file) |
| if buffer_size == attempt_buffer_size: |
| break |
| else: |
| attempt_buffer_size -= self.buffer_size_step |
| if buffer_size == target_buffer_size: |
| return |
| while attempt_buffer_size < target_buffer_size: |
| attempt_buffer_size += self.buffer_size_step |
| self.target.write_value(self.buffer_size_file, attempt_buffer_size, verify=False) |
| buffer_size = self.target.read_int(self.buffer_size_file) |
| if attempt_buffer_size != buffer_size: |
| message = 'Failed to set trace buffer size to {}, value set was {}' |
| self.logger.warning(message.format(target_buffer_size, buffer_size)) |
| break |
| |
| |
| def _build_trace_events(events): |
| event_string = ' '.join(['-e {}'.format(e) for e in events]) |
| return event_string |
| |
| def _build_trace_functions(functions): |
| function_string = " ".join(functions) |
| return function_string |