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 <jyri.sarha@linux.intel.com>

Author: Jyri Sarha

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()