tools: sof-ipc-timer.py: IPC message processing times from logs

[jsarha]

The sof-ipc-timer collects IPC message processing times from 'journalctl -k -o short-precise' output if SOF IPC debug is enabled.

The recognized messages are GLB_CREATE_PIPELINE, GLB_DELETE_PIPELINE, MOD_INIT_INSTANCE, MOD_LARGE_CONFIG_SET (only with valid module id), MOD_BIND, MOD_UNBIND, and GLB_SET_PIPELINE_STATE.

Different kind of outputs can be generated with different flags. Adding just -s gives a summary. Giving full FW side log, using FW built with CONFIG_DEBUG_IPC_TIMINGS=y, gives more accurate FW processing times.

With the above flags the output may look like this:

host-copier.2.playback fw init min 76 us max 77 us average 76 us of 10
gain.5.1 fw init min 49 us max 51 us average 49 us of 10
gain.5.1 fw conf min 23 us max 23 us average 23 us of 10
src.5.1 fw init min 33 us max 43 us average 37 us of 10
mixin.5.1 fw init min 38 us max 44 us average 39 us of 10
mixout.6.1 fw init min 31 us max 38 us average 32 us of 10
gain.6.1 fw init min 37 us max 45 us average 37 us of 10
gain.6.1 fw conf min 19 us max 20 us average 19 us of 10
dai-copier.SSP.NoCodec-2.playback fw init min 157 us max 166 us average 159 us of 10
pipeline.5: host-copier.2.playback, gain.5.1, src.5.1, mixin.5.1,
pipeline.5 create fw min 18 us max 23 us average 18 us of 10
pipeline.5 1.PAUSED fw min 26 us max 31 us average 28 us of 10
pipeline.5 RUNNING fw min 823 us max 1177 us average 939 us of 10
pipeline.5 PAUSED fw min 319 us max 774 us average 433 us of 10
pipeline.5 delete fw min 185 us max 190 us average 186 us of 10
pipeline.6: mixout.6.1, gain.6.1, dai-copier.SSP.NoCodec-2.playback,
pipeline.6 create fw min 27 us max 27 us average 27 us of 10
pipeline.6 1.PAUSED fw min 22 us max 22 us average 22 us of 10
pipeline.6 RUNNING fw min 327 us max 1302 us average 800 us of 10
pipeline.6 PAUSED fw min 361 us max 997 us average 501 us of 10
pipeline.6 delete fw min 173 us max 183 us average 175 us of 10
host-copier.2.playback>gain.5.1 bind fw min 43 us max 45 us average 44 us of 10
gain.5.1>src.5.1 bind fw min 38 us max 46 us average 40 us of 10
src.5.1>mixin.5.1 bind fw min 40 us max 47 us average 44 us of 10
mixin.5.1>mixout.6.1 bind fw min 40 us max 48 us average 43 us of 10
mixin.5.1>mixout.6.1 unbind fw min 24 us max 24 us average 24 us of 10
mixout.6.1>gain.6.1 bind fw min 45 us max 52 us average 49 us of 10
gain.6.1>dai-copier.SSP.NoCodec-2.playback bind fw min 40 us max 50 us average 43 us of 10
pipes 6 5: RESET fw min 230 us max 231 us average 230 us of 10

[jsarha]

Ok, this got a little bit out of hand, and I need to move one to other tasks. So please have mercy on the PR, I promise to fix all the bug found later on, but now I need leave this for the time being. I think its better to have this merged than to leave this PR hanging in limbo.

There are many new features hoped for in the discussion related to the already published results. The latest product of this script can be found here: thesofproject/sof#9880 (comment)

The script features also depend on this so far unmerged PR: thesofproject/linux#5366

[jsarha]

Some last minute cleanups and commit message update.

[jsarha]

@golowanow could you take a look to get this merged?

[golowanow]

@golowanow could you take a look to get this merged?

sure, could you please fix pylint warnings meanwhile ?

[jsarha]

@golowanow could you take a look to get this merged?

sure, could you please fix pylint warnings meanwhile ?

Will do, thou I doubt I can make pylint all quiet. But in a mean while a minor update to match latest changes to this PR: thesofproject/linux#5366

[jsarha]

pylint output is now clean, but I did it by disabling most of the style nagging, to see if there is some functional problems. Now there should be none.
@golowanow if you want some pylint warning on, just ask, but not all of them please.