tools: sof-ipc-timer.py: Timings of module init and config IPC loggings #1262
Conversation
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>
jsarha
force-pushed
the
dmesg_ipc_diff_timer_v2
branch
from
54df69f to
fc1974f
Compare
marc-hb
left a comment
marc-hb
left a comment
There was a problem hiding this comment.
Super quick and totally superficial codestyle review. You will need to find someone else to review the actual logic!
Some of the pylint warnings seem valid. If you want you can turn off the others with inline comment, just git grep pylint for examples.
https://github.com/thesofproject/sof-test/actions/runs/13813544629/job/38640776340?pr=1262
| self.state = -1 | ||
|
|
||
| def parse_line(self, line): | ||
| if match_obj := re.search(r" ipc tx ( |reply|done )", line): |
There was a problem hiding this comment.
Using the relatively new := saves two lines but costs 15 lines of indentation.
| if match_obj := re.search(r" ipc tx ( |reply|done )", line): | |
| match_obj = re.search(r" ipc tx ( |reply|done )", line): | |
| if not match_obj: | |
| return False: |
There was a problem hiding this comment.
On those lines I am not particularly pressed about indentation, but its relevant to see the whole branch including the re.search() all at once. To my eye the both are more ore less equal, or at least there is more pressing code clean up before this.
There was a problem hiding this comment.
The "Return Early" pattern is about a lot more than indentation. I should stop mentioning indentation, it's only the most obvious and visible symptom.
| super().__init__(args, comp_data, pipe_data) | ||
|
|
||
| def parse_line(self, line): | ||
| if match_obj := re.search(r" Create widget ", line): |
| elif msg_type == "done ": | ||
| self.parse_glb_set_done(msg_str, usecs) | ||
|
|
||
| class SOFLinuxLogParser: |
There was a problem hiding this comment.
This singleton seems a bit overkill to just hide global variables but why not...
There was a problem hiding this comment.
It saves me some writing to have those common data-members in only one place.
| log_parser = SOFLinuxLogParser(args) | ||
|
|
||
| if args.filename is None: | ||
| log_parser.read_log_data(sys.stdin) |
There was a problem hiding this comment.
Nice! I thought you needed to read the file twice? NVM.
There was a problem hiding this comment.
Yep, after reading the logs abit, I realized that the "Create" line will always appear before the IPC exchange related to the widgets they create, so I can do everything in one go.
jsarha
left a comment
jsarha
left a comment
There was a problem hiding this comment.
Thanks for your comments. I think I will need push yet completely new PR, since my current git branch has a lot of new features, fixes and cleanups in mixed order, and I don't think sorting them to separate commits makes too much sense.
... and there is still a lot more cleaning up to do, even with once commit approach, and couple of more features to add.
| self.state = -1 | ||
|
|
||
| def parse_line(self, line): | ||
| if match_obj := re.search(r" ipc tx ( |reply|done )", line): |
There was a problem hiding this comment.
On those lines I am not particularly pressed about indentation, but its relevant to see the whole branch including the re.search() all at once. To my eye the both are more ore less equal, or at least there is more pressing code clean up before this.
| elif msg_type == "done ": | ||
| self.parse_glb_set_done(msg_str, usecs) | ||
|
|
||
| class SOFLinuxLogParser: |
There was a problem hiding this comment.
It saves me some writing to have those common data-members in only one place.
| log_parser = SOFLinuxLogParser(args) | ||
|
|
||
| if args.filename is None: | ||
| log_parser.read_log_data(sys.stdin) |
There was a problem hiding this comment.
Yep, after reading the logs abit, I realized that the "Create" line will always appear before the IPC exchange related to the widgets they create, so I can do everything in one go.
|
There is yet another PR and this old one is abandoned: #1266 |
2 participants
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
sof-ipc-timer.py: Fix summary only functionality