From fc1974fd9f4d268c0bacd493b0bdd36d710775c5 Mon Sep 17 00:00:00 2001 From: Jyri Sarha Date: Mon, 17 Feb 2025 21:50:52 +0200 Subject: [PATCH] tools: sof-ipc-timer.py: Timings of module init and config IPC loggings The sof-ipc-timer collects module initialization and configuration timings, and set pipeline state timings from 'journalctl -k -o short-precise' output if SOF IPC debug is enabled. Different kind of outputs can be generated with different flags. Adding just -s gives a summary like this: host-copier.0.playback init min 196 us max 456 us average 322 us of 100 gain.1.1 init min 192 us max 552 us average 327 us of 100 gain.1.1 conf min 197 us max 494 us average 325 us of 100 mixin.1.1 init min 193 us max 8219 us average 406 us of 100 mixout.2.1 init min 197 us max 573 us average 327 us of 100 gain.2.1 init min 197 us max 484 us average 324 us of 100 gain.2.1 conf min 193 us max 418 us average 322 us of 100 smart_amp.2.1 init min 194 us max 526 us average 326 us of 100 smart_amp.2.1 conf min 197 us max 1826 us average 393 us of 100 dai-copier.SSP.NoCodec-0.playback init min 202 us max 2135 us average 479 us of 100 pipeline.1: host-copier.0.playback, gain.1.1, mixin.1.1, pipeline.1 3 min 200 us max 2592 us average 553 us of 200 pipeline.1 4 min 228 us max 3202 us average 673 us of 100 pipeline.1 2 min 208 us max 1867 us average 565 us of 100 pipeline.2: mixout.2.1, gain.2.1, smart_amp.2.1, dai-copier.SSP.NoCodec-0.playback, pipeline.2 3 min 199 us max 2667 us average 863 us of 200 pipeline.2 4 min 205 us max 8656 us average 794 us of 100 Signed-off-by: Jyri Sarha --- tools/sof-ipc-timer.py | 318 +++++++++++++++++++++++++++++++++++++++++ 1 file changed, 318 insertions(+) create mode 100755 tools/sof-ipc-timer.py diff --git a/tools/sof-ipc-timer.py b/tools/sof-ipc-timer.py new file mode 100755 index 00000000..e6c2fa37 --- /dev/null +++ b/tools/sof-ipc-timer.py @@ -0,0 +1,318 @@ +#!/usr/bin/env python3 + +# SPDX-License-Identifier: BSD-3-Clause +# Copyright(c) 2025 Intel Corporation. All rights reserved. + +'''The sof-ipc-timer collects module initialization and configuration +timings from 'journalctl -k -o short-precise' output if SOF IPC debug +is enabled. + +Without any flags there is no output. If you want it all, just put +everything on the command line: -t -i -c -m -p -s + +''' + +import re +import sys +import argparse +from datetime import datetime + +class Component: + '''SOF audio component storage class''' + pipe_id: int + comp_id: int + wname: str + init_times: list + conf_times: list + + def __init__(self, pipe_id, comp_id, wname): + self.pipe_id = pipe_id + self.comp_id = comp_id + self.wname = wname + self.init_times = [] + self.conf_times = [] + + def __str__(self) -> str: + return f'{self.pipe_id}-{self.comp_id:#08x}' + +class Pipeline: + '''SOF audio pipeline storage class''' + pipe_id: int + comps: list + state_times: dict + + def __init__(self, pipe_id): + self.pipe_id = pipe_id + self.comps = [] + self.state_times = {} + + def __str__(self) -> str: + return f'pipeline.{self.pipe_id + 1}' + + def add_state_timing(self, state, usecs): + if self.state_times.get(state) is None: + self.state_times[state] = [] + self.state_times[state].append(usecs) + +class LogLineParser: + def __init__(self, args, comp_data, pipe_data): + self.args = args + self.comp_data = comp_data + self.pipe_data = pipe_data + +class PipelineParser(LogLineParser): + '''Parse line of form + + Feb 25 23:17:00.598919 lnlm-rvp-sdw kernel: snd_sof:sof_ipc4_widget_setup: sof-audio-pci-intel-lnl 0000:00:1f.3: Create pipeline pipeline.1 (pipe 1) - instance 0, core 0 + + 'pipe_id' from ' instance 0,' + ''' + def __init__(self, args, comp_data, pipe_data): + super().__init__(args, comp_data, pipe_data) + + def parse_line(self, line): + if match_obj := re.search(r" Create pipeline ", line): + match_end_pos = match_obj.span()[1] + line_split = line[match_end_pos + 1:].split() + pipe_id = int(line_split[5].rstrip(",")) + if self.pipe_data.get(pipe_id) is None: + self.pipe_data[pipe_id] = Pipeline(pipe_id) + return True + return False + +class WidgetParser(LogLineParser): + '''Parse line of form: + + Feb 25 23:17:00.599838 lnlm-rvp-sdw kernel: snd_sof:sof_ipc4_widget_setup: sof-audio-pci-intel-lnl 0000:00:1f.3: Create widget host-copier.0.playback (pipe 1) - ID 4, instance 0, core 0 + + 'widget_name' from 'host-copier.0.playback' + 'pipi_id' integer form "(pipe 1)" + 'widget_id' MSB integer from "instance 0," and LSB from "ID 4," + ''' + def __init__(self, args, comp_data, pipe_data): + super().__init__(args, comp_data, pipe_data) + + def parse_line(self, line): + if match_obj := re.search(r" Create widget ", line): + match_end_pos = match_obj.span()[1] + line_split = line[match_end_pos:].split() + widget_name = line_split[0] + # pipeline instance id is one smaller than the pipeline number + pipe_id = int(line_split[2].rstrip(")")) - 1 + module_instance_id = int(line_split[7].rstrip(",")) + widget_id = int(line_split[5].rstrip(",")) + # final module id are composed with high16(module instance id) + low16(module id) + widget_id |= module_instance_id << 16 + # do not overwire data we have colledted, only add new items to dictionary + if self.comp_data.get(widget_id) is None: + self.comp_data[widget_id] = Component(pipe_id, widget_id, widget_name) + if not self.pipe_data.get(pipe_id) is None: + self.pipe_data[pipe_id].comps.append(self.comp_data[widget_id]) + return True + return False + +class IpcMsgParser(LogLineParser): + '''Parse three consequtive lines of form: + + Feb 25 23:17:00.599946 lnlm-rvp-sdw kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-lnl 0000:00:1f.3: ipc tx : 0x40000004|0x15: MOD_INIT_INSTANCE [data size: 84] + Feb 25 23:17:00.600048 lnlm-rvp-sdw kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-lnl 0000:00:1f.3: ipc tx reply: 0x60000000|0x15: MOD_INIT_INSTANCE + Feb 25 23:17:00.600185 lnlm-rvp-sdw kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-lnl 0000:00:1f.3: ipc tx done : 0x40000004|0x15: MOD_INIT_INSTANCE [data size: 84] + + 'usecs' from '23:17:00.599946' (please do not run your tests over midnight)- + 'msg_type' from 5 letters following " ipc tx ", either " ", "reply", or "done " + 'msg_str' from '0x40000004|0x15' + 'msg_name' from 'MOD_INIT_INSTANCE' ('MOD_LARGE_CONFIG_SET' or 'GLB_SET_PIPELINE_STATE') + 'primary' integer from '0x40000004' + 'extension' integer from '0x15' + ''' + comp_id: int + pipe_id: int + start: int + state: int + + def __init__(self, args, comp_data, pipe_data): + super().__init__(args, comp_data, pipe_data) + self.reset() + + def reset(self): + self.comp_id = -1 + self.pipe_id = -1 + self.start = -1 + self.state = -1 + + def parse_line(self, line): + if match_obj := re.search(r" ipc tx ( |reply|done )", line): + match_start_pos = match_obj.span()[0] + match_end_pos = match_obj.span()[1] + line_split = line.split() + dt_object = datetime.strptime(line_split[2], "%H:%M:%S.%f") + secs = dt_object.second + dt_object.minute * 60 + dt_object.hour * 3600 + usecs = secs * 1000000 + dt_object.microsecond + msg_type = line[match_start_pos + 8 : match_end_pos] + msg_part = line[match_end_pos:].split() + msg_str = msg_part[1] + msg_name = msg_part[2] + primary = int(msg_str.split('|')[0], 16) + extension = int(msg_str.split('|')[1].rstrip(":"), 16) + if msg_name == "MOD_INIT_INSTANCE" or msg_part[2] == "MOD_LARGE_CONFIG_SET": + self.parse_mod_msg(msg_name, msg_str, msg_type, usecs, primary) + elif msg_name == "GLB_SET_PIPELINE_STATE": + self.parse_glb_set_msg(msg_type, msg_str, usecs, primary) + return True + return False + + def parse_mod_1st(self, usecs, primary): + self.comp_id = primary & 0xFFFFFF + if self.comp_id == 0: + self.comp_id = None + self.start = usecs + + def parse_mod_reply(self, comp, msg_name, usecs): + if msg_name == "MOD_INIT_INSTANCE" and self.args.init_messages: + print("%s:\tinit reply\t%d us" % (comp.wname, usecs - self.start)) + elif msg_name == "MOD_LARGE_CONFIG_SET" and self.args.config_messages: + print("%s:\tconf reply\t%d us" % (comp.wname, usecs - self.start)) + + def parse_mod_done(self, comp, msg_name, msg_str, usecs): + message = "" + pipeline_id = "" + if self.args.message: + message = "\t" + msg_str + if self.args.pipeline_id: + pipeline_id = "\tpipeline id: " + str(comp.pipe_id) + if msg_name == "MOD_INIT_INSTANCE": + if self.args.init_messages: + print("%s:\tinit done\t%d us%s%s" % + (comp.wname, usecs - self.start, message, pipeline_id)) + comp.init_times.append(usecs - self.start) + elif msg_name == "MOD_LARGE_CONFIG_SET": + if self.args.config_messages: + print("%s:\tconf done\t%d us%s%s" % + (comp.wname, usecs - self.start, message, pipeline_id)) + comp.conf_times.append(usecs - self.start) + self.reset() + + def parse_mod_msg(self, msg_name, msg_str, msg_type, usecs, primary): + if msg_type == " ": + self.parse_mod_1st(usecs, primary) + if self.comp_id == None: + return + comp = self.comp_data[self.comp_id] + if msg_type == "reply" and self.args.reply_timings: + self.parse_mod_reply(comp, msg_name, usecs) + elif msg_type == "done ": + self.parse_mod_done(comp, msg_name, msg_str, usecs) + + def parse_glb_set_1st(self, usecs, primary): + self.pipe_id = (primary & 0x00FF0000) >> 16 + self.state = primary & 0xFFFF + self.start = usecs + + def parse_glb_set_reply(self, usecs): + print("pipeline id: %d\tstate %d reply\t %d us" % + (self.pipe_id, self.state, usecs - self.start)) + self.start = usecs + + def parse_glb_set_done(self, msg_str, usecs): + message = "" + if self.args.message: + message = "\t" + msg_str + if self.args.trigger_nessages: + print("pipeline id: %d\tstate %d done\t%d us%s" % + (self.pipe_id, self.state, usecs - self.start, message)) + self.pipe_data[self.pipe_id].add_state_timing(self.state, usecs - self.start) + self.reset() + + def parse_glb_set_msg(self, msg_type, msg_str, usecs, primary): + if msg_type == " ": + self.parse_glb_set_1st(usecs, primary) + elif msg_type == "reply" and self.args.reply_timings: + self.parse_glb_set_reply(usecs) + elif msg_type == "done ": + self.parse_glb_set_done(msg_str, usecs) + +class SOFLinuxLogParser: + def __init__(self, args): + self.args = args + self.comp_data = {} + self.pipe_data = {} + self.pipe_parser = PipelineParser(args, self.comp_data, self.pipe_data) + self.widget_parser = WidgetParser(args, self.comp_data, self.pipe_data) + self.ipc_msg_parser = IpcMsgParser(args, self.comp_data, self.pipe_data) + + def read_log_data(self, file): + for line in file: + if self.pipe_parser.parse_line(line): + continue + if self.widget_parser.parse_line(line): + continue + if self.ipc_msg_parser.parse_line(line): + continue + + def print_min_max_avg(self, prefix, times): + if len(times) == 0: + return + minval = 1000000 + maxval = 0 + valsum = 0 + for val in times: + if val < minval: + minval = val + if val > maxval: + maxval = val + valsum = valsum + val + print("%s\tmin %d us\tmax %d us\taverage %d us of %d" % + (prefix, minval, maxval, valsum / len(times), len(times))) + + def summary(self): + if not self.args.summary: + return + for comp_id in self.comp_data: + mod = self.comp_data[comp_id] + self.print_min_max_avg(mod.wname + " init", mod.init_times) + self.print_min_max_avg(mod.wname + " conf", mod.conf_times) + for pipe_id in self.pipe_data: + pipe = self.pipe_data[pipe_id] + print("%s:" % pipe, end=" ") + for comp in pipe.comps: + print("%s" % comp.wname, end=", ") + print() + for state in pipe.state_times: + state_times_list = pipe.state_times[state] + self.print_min_max_avg(str(pipe) + " " + str(state), state_times_list) + +def parse_args(): + '''Parse command line arguments''' + parser = argparse.ArgumentParser(formatter_class=argparse.RawTextHelpFormatter, + description=__doc__) + parser.add_argument('filename', nargs="?", help="Optional log file, stdin if not defined") + parser.add_argument('-t', '--trigger-nessages', action="store_true", default=False, + help='Show trigger message handling times') + parser.add_argument('-i', '--init-messages', action="store_true", default=False, + help='Show init message handling times') + parser.add_argument('-c', '--config-messages', action="store_true", default=False, + help='Show large config set message handling times') + parser.add_argument('-r', '--reply-timings', action="store_true", default=False, + help='Show time to reply message, "done" time is from "reply"') + parser.add_argument('-m', '--message', action="store_true", default=False, + help='Show 1st message primary and extension parts') + parser.add_argument('-p', '--pipeline-id', action="store_true", default=False, + help='Show pipeline id') + parser.add_argument('-s', '--summary', action="store_true", default=False, + help='Show average, max, and min latencies of message handling') + return parser.parse_args() + +def main(): + args = parse_args() + log_parser = SOFLinuxLogParser(args) + + if args.filename is None: + log_parser.read_log_data(sys.stdin) + else: + with open(args.filename, 'r', encoding='utf8') as file: + log_parser.read_log_data(file) + + log_parser.summary() + +if __name__ == "__main__": + main()