logger: new relative timestamps option, relative to first entry seen

[marc-hb]

Add a new sof-logger -e 0/1 relative timestamps option where the
TIMESTAMP column is relative to the first entry seen.

Removes many digits and makes the TIMESTAMP column much more readable in
short logs.

Also stop showing "NaN" as the first DELTA like something went
wrong. Show zero instead.

The new option is off by default when using -r(aw) and on otherwise.

The first entry is kept always absolute.

Before:

 TIMESTAMP DELTA C# COMPONENT LOCATION CONTENT
[6653843012.343750] ( NaN) c0 dma-trace src/trace/dma-trace.c:339 ERROR FW ...
[6653843111.510417] ( 99.166664) c0 ll-schedule ./schedule/ll_schedule.c:229 perf ll_work
[6653843309.010417] ( 197.500000) c0 ll-schedule ./schedule/ll_schedule.c:399 task add
[6653843314.166667] ( 5.156250) c0 ll-schedule ./schedule/ll_schedule.c:403 task params
[6653843322.031250] ( 7.864583) c0 ll-schedule ./schedule/ll_schedule.c:309 new added
[6653843327.031250] ( 5.000000) c0 ll-schedule ./schedule/ll_schedule.c:312 num_tasks 2
[6653844109.531250] ( 782.500000) c0 sa src/lib/agent.c:65 perf sys_load
[6653844155.156250] ( 45.625000) c0 ll-schedule ./schedule/ll_schedule.c:229 perf ll_work
[6653844384.218750] ( 229.062500) c0 component src/audio/component.c:130 comp new host

After:

 TIMESTAMP DELTA C# COMPONENT LOCATION CONTENT
[686125142.395834] ( 0.000000) c0 dma-trace src/trace/dma-trace.c:339 ERROR FW ...
[ 94.270833] ( 94.270836) c0 ll-schedule ./schedule/ll_schedule.c:229 perf ll_work
[ 296.770833] ( 202.500000) c0 ll-schedule ./schedule/ll_schedule.c:399 task add
[ 301.979167] ( 5.208333) c0 ll-schedule ./schedule/ll_schedule.c:403 task params
[ 309.843750] ( 7.864583) c0 ll-schedule ./schedule/ll_schedule.c:309 new added
[ 314.843750] ( 5.000000) c0 ll-schedule ./schedule/ll_schedule.c:312 num_tasks 2
[ 1092.395833] ( 777.552063) c0 sa src/lib/agent.c:65 perf sys_load
[ 1137.968750] ( 45.572918) c0 ll-schedule ./schedule/ll_schedule.c:229 perf ll_work
[ 1850.208333] ( 712.239563) c0 component src/audio/component.c:130 comp new host

For more output examples check https://sof-ci.01.org/sofpr/PR3985/build8535/devicetest/

Signed-off-by: Marc Herbert marc.herbert@intel.com

[marc-hb]

The only checkpatch warning is because the sample output is too wide. No other checkpatch warning.

https://sof-ci.01.org/sofpr/PR3985/build8535/devicetest/?model=APL_UP2_NOCODEC&testcase=check-suspend-resume-with-capture is some unrelated rtcwake error.

[cujomalainey]

nice feature, thanks

[ktrzcinx]

It looks like mixed declaration and code

[lgirdwood]

@marc-hb cxan you follow coding standard until standard change is agreed by TSC. Thanks.

[marc-hb]

Done. I'm also adding -Wdeclaration-after-statement in PR #3995 so history stops repeating itself. Let's stop wasting most precious code review time with stuff computers can do.

[lgirdwood]

@zrombel good to merge ?

[lgirdwood]

SOFCI TEST

[lgirdwood]

@zrombel are we good to merge, I dont think internal CI tests the logger ?

[marc-hb]

I dont think QuickBuild internal CI tests the logger ?

Let's not assume and take that risk; plenty enough CI issues these days.

https://sof-ci.01.org/sofpr/PR3985/build8535/devicetest/ was almost all fine, see above. Even though the code barely changed, https://sof-ci.01.org/sofpr/PR3985/build8567/devicetest/ is now much worse! Something unrelated and bad was merged in the mean time? Or just bad luck.

• https://sof-ci.01.org/sofpr/PR3985/build8567/devicetest/?model=CML_RVP_SDW&testcase=check-kmod-load-unload-after-playback gas a very strange slogger error, I should take a closer look.

error: Invalid filename length or ldc file does not match firmware

• https://sof-ci.01.org/sofpr/PR3985/build8567/devicetest/?model=TGLH_RVP_HDA&testcase=check-suspend-resume-5 has the usual suspend/resume TIMEOUT

• BSW_CYN_MAX98090 has very random TIMEOUTs, including this one:

mkdir: cannot create directory ‘/home/ubuntu/sof-test/logs/check-pause-resume/2021-04-01-11:47:10-1516’: Read-only file system

I suspect it's just the eMMC again. In fact I thought we had stopped using cyan for that reason. Is cyan back?

Quickbuild is mostly stuck this week and it is stuck now. Previous Quickbuild https://sof-ci.01.org/sof-pr-viewer/#/build/PR3985/build6235261 passed some unit tests then stopped with a strange error:

Failed to run command: git -C /localdisk/processteam/qba3/workspace/24733/SOF_FW diff --name-only origin/master...b5e1784703fbb508e4e5d02c7537224a6d3c8270
Command return code: 128
Command error output: fatal: ambiguous argument 'origin/master...b5e1784703fbb508e4e5d02c7537224a6d3c8270': unknown revision or path not in the working tree.

---

EDIT: I had a look at the ldc error above. It happened at the very start, in other words the logger failed almost immediately. The source checksum was correct. Maybe a hardware of filesystem glitch.

Worryingly, the slogger column is not empty, it has a long log coming from some other run?

[marc-hb]

SOFCI TEST

(failed - disk was full)

[marc-hb]

SOFCI TEST

[marc-hb]

https://sof-ci.01.org/sofpr/PR3985/build8585/devicetest/?model=BYT_MB_NOCODEC&testcase=simultaneous-playback-capture has only some old aplay: pcm_write:2061: write error: Input/output error on BYT and nothing else.

Quickbuild never completed this PR so far.

EDIT: https://sof-ci.01.org/sof-pr-viewer/#/build/PR3985/build6252734 was triggered by @zrombel and was all green

-- version.cmake starting SOF build at 2021-04-02T07:34:49Z UTC
-- Building git commit with parent(s):
dba0865dc 2e6cafa02 0734f3640 (HEAD -> pr_branch) Merge 0734f364013dab551e0fc11903ee34c340e4427b into 2e6cafa02fca352c9f4a085d3c44925e61a19253