From 45af5f41bc824a73e1a30004a048ef899ad59073 Mon Sep 17 00:00:00 2001 From: Kajetan Puchalski Date: Wed, 23 Aug 2023 16:53:42 +0100 Subject: [PATCH 1/2] ftrace: Support trace-cmd record mode The current implementation of the FtraceCollector only supports using ftrace in its start-stop mode which keeps the traces in memory and then writes to file at the end. Trace-cmd also supports a different mode - record which writes to file periodically meaning that it allows recording traces that would exceed the 'start' mode buffer size in exchange for added noise. This commit adds support for selecting which mode trace-cmd should be run in. It adds a new collector parameter - 'trace_cmd_mode' which is used to distinguish between the two approaches. While at it, it also cleans up the collector in some places, e.g. the teardown() method. Signed-off-by: Kajetan Puchalski --- devlib/collector/ftrace.py | 91 +++++++++++++++++++++++--------------- 1 file changed, 56 insertions(+), 35 deletions(-) diff --git a/devlib/collector/ftrace.py b/devlib/collector/ftrace.py index 9c1795924..e3c29bbb8 100644 --- a/devlib/collector/ftrace.py +++ b/devlib/collector/ftrace.py @@ -19,6 +19,7 @@ import re import subprocess import sys +import signal import contextlib from shlex import quote @@ -51,6 +52,7 @@ 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(CollectorBase): # pylint: disable=too-many-locals,too-many-branches,too-many-statements @@ -71,6 +73,7 @@ def __init__(self, target, report_on_target=False, trace_clock='local', saved_cmdlines_nr=4096, + trace_cmd_mode='start', ): super(FtraceCollector, self).__init__(target) self.events = events if events is not None else DEFAULT_EVENTS @@ -85,9 +88,7 @@ def __init__(self, target, self.autoview = autoview self.strict = strict 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.trace_cmd_mode = trace_cmd_mode self.output_path = None self.target_binary = None self.host_binary = None @@ -98,6 +99,13 @@ def __init__(self, target, self.trace_clock = trace_clock self.saved_cmdlines_nr = saved_cmdlines_nr self._reset_needed = True + self.bg_cmd = None + self.tmp_working_directory = self.target.execute("{} mktemp -p {} -d".format( + self.target.busybox, self.target.working_directory, + ), as_root=True).strip() + self.target_output_file = target.path.join(self.tmp_working_directory, OUTPUT_TRACE_FILE) + text_file_name = target.path.splitext(OUTPUT_TRACE_FILE)[0] + '.txt' + self.target_text_file = target.path.join(self.tmp_working_directory, text_file_name) # pylint: disable=bad-whitespace # Setup tracing paths @@ -240,8 +248,7 @@ def available_functions(self): return self.target.read_value(self.available_functions_file).splitlines() def reset(self): - self.target.execute('{} reset -B devlib'.format(self.target_binary), - as_root=True, timeout=TIMEOUT) + self.target.execute('{} reset -B devlib'.format(self.target_binary), as_root=True, timeout=TIMEOUT) # trace-cmd start will not set the top-level buffer size if passed -B # parameter, but unfortunately some events still end up there (e.g. @@ -249,10 +256,7 @@ def reset(self): # might be too small and some event lost. top_buffer_size = self.top_buffer_size if self.top_buffer_size else self.buffer_size if top_buffer_size: - self.target.write_value( - self.target.path.join(self.tracing_path, 'buffer_size_kb'), - top_buffer_size, - ) + self.target.write_value(self.target.path.join(self.tracing_path, 'buffer_size_kb'), top_buffer_size) if self.functions: self.target.write_value(self.function_profile_file, 0, verify=False) @@ -276,18 +280,30 @@ async def start(self): with contextlib.suppress(TargetStableError): self.target.write_value('/proc/sys/kernel/kptr_restrict', 0) - self.target.execute( - '{} start -B devlib {buffer_size} {cmdlines_size} {clock} {events} {tracer} {functions}'.format( - self.target_binary, - events=self.event_string, - tracer=tracer_string, - functions=tracecmd_functions, - buffer_size='-b {}'.format(self.buffer_size) if self.buffer_size is not None else '', - clock='-C {}'.format(self.trace_clock) if self.trace_clock else '', - cmdlines_size='--cmdlines-size {}'.format(self.saved_cmdlines_nr) if self.saved_cmdlines_nr is not None else '', - ), - as_root=True, + trace_cmd = '{} {command} -B devlib {buffer_size} {cmdlines_size} {clock} {events} {tracer} {functions}'.format( + self.target_binary, + command=self.trace_cmd_mode, + events=self.event_string, + tracer=tracer_string, + functions=tracecmd_functions, + buffer_size='-b {}'.format(self.buffer_size) if self.buffer_size is not None else '', + clock='-C {}'.format(self.trace_clock) if self.trace_clock else '', + cmdlines_size='--cmdlines-size {}'.format(self.saved_cmdlines_nr) if self.saved_cmdlines_nr is not None else '', ) + + if self.trace_cmd_mode == 'record': + trace_cmd = "cd {} && {command} {output}".format( + self.tmp_working_directory, + command=trace_cmd, + output="-o {}".format(self.target_output_file) + ) + if self.bg_cmd is None: + self.bg_cmd = self.target.background(trace_cmd, as_root=True) + else: + raise TargetStableError('ftrace collector is not re-entrant') + else: + self.target.execute(trace_cmd, as_root=True) + if self.automark: self.mark_start() if 'cpufreq' in self.target.modules: @@ -310,7 +326,6 @@ async def start(self): as_root=True), ) - def stop(self): # Disable kernel function profiling if self.functions and self.tracer is None: @@ -322,8 +337,12 @@ def stop(self): self.stop_time = time.time() if self.automark: self.mark_stop() - self.target.execute('{} stop -B devlib'.format(self.target_binary), - timeout=TIMEOUT, as_root=True) + if self.trace_cmd_mode == 'record': + self.bg_cmd.send_signal(signal.SIGINT) + self.bg_cmd.wait() + self.bg_cmd = None + else: + self.target.execute('{} stop -B devlib'.format(self.target_binary), timeout=TIMEOUT, as_root=True) self._reset_needed = True def set_output(self, output_path): @@ -334,15 +353,13 @@ def set_output(self, output_path): def get_data(self): if self.output_path is None: raise RuntimeError("Output path was not set.") - self.target.execute('{0} extract -B devlib -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 = 10 * (self.stop_time - self.start_time) - self.target.pull(self.target_output_file, self.output_path, timeout=pull_timeout) + + if self.trace_cmd_mode == 'start': + self.target.execute('{0} extract -B devlib -o {1}; chmod 666 {1}'.format( + self.target_binary, self.target_output_file + ), timeout=TIMEOUT, as_root=True) + + self.target.pull(self.target_output_file, self.output_path) output = CollectorOutput() if not os.path.isfile(self.output_path): self.logger.warning('Binary trace not pulled from device.') @@ -352,8 +369,7 @@ def get_data(self): textfile = os.path.splitext(self.output_path)[0] + '.txt' if self.report_on_target: self.generate_report_on_target() - self.target.pull(self.target_text_file, - textfile, timeout=pull_timeout) + self.target.pull(self.target_text_file, textfile) else: self.report(self.output_path, textfile) output.append(CollectorOutputEntry(textfile, 'file')) @@ -440,7 +456,12 @@ 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)) + self.target.remove(self.target_output_file) + if self.report_on_target: + self.target.remove(self.target_text_file) + + def finalize(self): + self.target.remove(self.tmp_working_directory) def mark_start(self): self.target.write_value(self.marker_file, TRACE_MARKER_START, verify=False) From 5ef563e54ca75bfc600725a68a8b0b42ee9822d9 Mon Sep 17 00:00:00 2001 From: Kajetan Puchalski Date: Wed, 23 Aug 2023 17:31:30 +0100 Subject: [PATCH 2/2] ftrace: Allow setting the interval for record mode The trace-cmd record mode allows setting the interval to determine how often it will write to the trace file. The default is 1000 (us, ie. 1ms). Add a collector parameter to allow setting that interval. This will only have an effect when trace_cmd_mode is 'record' as the option does not exist for 'start' mode. Signed-off-by: Kajetan Puchalski --- devlib/collector/ftrace.py | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/devlib/collector/ftrace.py b/devlib/collector/ftrace.py index e3c29bbb8..1a0f742b1 100644 --- a/devlib/collector/ftrace.py +++ b/devlib/collector/ftrace.py @@ -74,6 +74,7 @@ def __init__(self, target, trace_clock='local', saved_cmdlines_nr=4096, trace_cmd_mode='start', + record_interval=1000, ): super(FtraceCollector, self).__init__(target) self.events = events if events is not None else DEFAULT_EVENTS @@ -98,6 +99,7 @@ def __init__(self, target, self.function_string = None self.trace_clock = trace_clock self.saved_cmdlines_nr = saved_cmdlines_nr + self.record_interval = record_interval self._reset_needed = True self.bg_cmd = None self.tmp_working_directory = self.target.execute("{} mktemp -p {} -d".format( @@ -292,9 +294,10 @@ async def start(self): ) if self.trace_cmd_mode == 'record': - trace_cmd = "cd {} && {command} {output}".format( + trace_cmd = "cd {} && {command} {interval} {output}".format( self.tmp_working_directory, command=trace_cmd, + interval="-s {}".format(self.record_interval), output="-o {}".format(self.target_output_file) ) if self.bg_cmd is None: