tools: sof-ipc-timer.py: Timings of module init and config IPC loggings #1255
Conversation
The sof-ipc-timer collects module initialization and configuration timings from 'journalctl -k -o short-precise' output if SOF IPC debug is enabled. Signed-off-by: Jyri Sarha <jyri.sarha@linux.intel.com>
| def main(): | ||
| args = parse_args() | ||
|
|
||
| with open(args.filename, 'r', encoding='utf8') as file: |
There was a problem hiding this comment.
IMHO a tool like this should really be "stdin-capable". Or even stdin-only which is flexible enough:
journalctl -k | tools/sof-ipc-timer.py
tools/sof-ipc-timer.py < capture.txt
for line in sys.stdin:``
There was a problem hiding this comment.
@marc-hb currently the file is read twice (at least AFAICS), wouldn't be very convenient with stdin
| mod_id = None | ||
| start = None | ||
| for line in f: | ||
| if match_obj := re.search(r" ipc tx ( |reply|done )", line): |
There was a problem hiding this comment.
The massive length of the indented block is a sure sign it should split into separate functions. Small functions also make interactive testing possible, that's what the "__main__" idiom below is for:
ipython3
>> import sof-ipc-timer
>> small_function("some log line")There was a problem hiding this comment.
The massive length of the indented block is a sure sign it should split into separate functions.
@lgirdwood 's comment just reminded me of something: naming is hard (c), but when you find good function names they act like a Table of Contents that lets you quickly get the gist of what is happening without reading the whole code/book.
Functions are not just about code re-use, they're useful even when you invoke them only once; for testability and readability.
| return f'{self.ppln_id}-{self.comp_id:#08x}' | ||
|
|
||
| def read_comp_data(f): | ||
| '''Process the dmesg to get the component ID to component name mapping, |
There was a problem hiding this comment.
| '''Process the dmesg to get the component ID to component name mapping, | |
| '''Process the kernel logs to get the component ID to component name mapping, |
dmesg wraps around. journalctl -k does not.
journalctl can focus on certain intervals, dmesg cannot AFAIK. For instance journalctl --since $test_start_time
dmesg? Just say no :-)
| # msg_type shoule be either " ", "reply", or "done " | ||
| msg_type = line[match_obj.span()[0] + 8 : match_obj.span()[1]] | ||
| msg_part = line[span_end_pos:].split() | ||
| primary = int(msg_part[1].split('|')[0], 16) | ||
| extension = int(msg_part[1].split('|')[1].rstrip(":"), 16) | ||
| if msg_part[2] == "MOD_INIT_INSTANCE" or msg_part[2] == "MOD_LARGE_CONFIG_SET": | ||
| if msg_type == " ": | ||
| mod_id = primary & 0xFFFFFF | ||
| if mod_id == 0: | ||
| mod_id = None | ||
| continue | ||
| start = usecs | ||
| if mod_id == None: | ||
| continue | ||
| comp = comp_data[mod_id] | ||
| if msg_type == "reply" and args.reply_timings: | ||
| if msg_part[2] == "MOD_INIT_INSTANCE": | ||
| print("%s:\tinit reply\t%d us" % (comp.wname, usecs - start)) | ||
| elif msg_part[2] == "MOD_LARGE_CONFIG_SET": | ||
| print("%s:\tconf reply\t%d us" % (comp.wname, usecs - start)) | ||
| start = usecs | ||
| elif msg_type == "done ": | ||
| module_id = "" | ||
| pipeline_id = "" | ||
| if args.module_id: | ||
| module_id = "\tmodule id: " + format(mod_id, '#08x') | ||
| if args.pipeline_id: | ||
| pipeline_id = "\tpipeline id: " + str(comp.ppln_id) | ||
| if msg_part[2] == "MOD_INIT_INSTANCE": | ||
| print("%s:\tinit done\t%d us%s%s" % | ||
| (comp.wname, usecs - start, module_id, pipeline_id)) | ||
| elif msg_part[2] == "MOD_LARGE_CONFIG_SET": | ||
| print("%s:\tconf done\t%d us%s%s" % | ||
| (comp.wname, usecs - start, module_id, pipeline_id)) | ||
| mod_id = None | ||
| start = None | ||
| end = None |
There was a problem hiding this comment.
Could also do with more inline comments describing each stage
The sof-ipc-timer collects module initialization and configuration timings from 'journalctl -k -o short-precise' output if SOF IPC debug is enabled.