logger: add ktime and date in header

[marc-hb]

Every log file should have a date.

ktime can be related to the TIMESTAMP column. It is especially useful to
spot logs delayed or stuck.

Some logs use ktime while others use a date and it can be sometimes
difficult to connect them with one another. This header can help.

Before:

TIMESTAMP (us) DELTA C# COMPONENT CONTENT
[  5120116529] (  0) c0 dma-trace ERROR FW ABI 0x3012001 ...

After:

TIMESTAMP (us) DELTA C# COMPONENT  CONTENT ktime=5132.663s @ 2021-04-27 14:36:09 -0700 PDT
[  5120116529] (  0) c0 dma-trace ERROR FW ABI 0x3012001 ...

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

[marc-hb]

check-sof-logger fails all across https://sof-ci.01.org/sofpr/PR4105/build8853/devicetest/ because it expects the CONTENT$ name to be the last word on the header line. I'm relaxing the regular expression in the first commit of thesofproject/sof-test#668. The second and main commit in 668 is a bigger and unrelated change, maybe I should split them into even more PRs...

[marc-hb]

SOFCI TEST

[marc-hb]

Some tests failed in https://sof-ci.01.org/sof-pr-viewer/#/build/PR4105/build6363075 but only on ICL_SSP and not all tests running on ICL_SSP so these failures do not seem related to this pure header change.

02:26:39.527   ipc_notif
02:26:39.527   Notification TraceDmaPosition (90020000, 00000018)
               Payload:
               00000018 90020000 00000000 00000940 
               00000000 00000051  received!

02:26:39.527   => Exception in test.
02:26:39.543     Exception IoCtlError occurred at 'C:\\work\\tools\\pyexecnetcache\\cavs_scripts-py\\utilities\\dev_audio_windows.py':101
                 IOCTL returned error: error=1450, status=0, out_buff:
                 00 00 00 00 
                 00 00 00 00 
                 00 00 00 00 
                 00 00 00 0

In fact this PR cannot have caused these tests to fail because they... worryingly do not build sof-logger from the latest source but use some other, more static version instead! You can tell by opening dma_trace_1.log at the link above and looking at the first line, it still looks like this which means it misses not just this PR but also other sof-logger header change d6f6a45 which was merged more than 12 hours ago.

@zrombel, @ktrzcinx :

• can you help with these ICL_SSP failures?
• do you know when/how sof-logger gets updated in QB? Maybe I broke it already but no one knows yet :-(

[marc-hb]

After merging thesofproject/sof-test#668 , https://sof-ci.01.org/sofpr/PR4105/build8854/devicetest/ is all green and the outputs look good.

[lgirdwood]

Bw, just confirming that this will still allow @ktrzcinx do do a diff ? i.e. we can turn the date off.

[marc-hb]

Very good question. I thought about this and assumed a single line difference for identical logs was a "feature" but thinking about it a bit more now I see these new timestamps could complicate some automated diff / scripting. If anyone has ever used the -g option + diffed the output in a script then I can very easily disable this too when -g is used.

[lgirdwood]

@marc-hb yeah, I would support the diff mode. I think @ktrzcinx has found this mode very useful for debug.

[marc-hb]

Done, this can now be turned off with -g that (also) removes the timestamp column.

[cujomalainey]

Done, this can now be turned off with -g that (also) removes the timestamp column.

then there is me who fails to check -h so I C-v + d in vim to solve my problems 🙃

[marc-hb]

The checktree regression seen in https://github.com/thesofproject/sof/pull/4105/checks?check_run_id=2461722482 has been introduced by #4111 , unrelated.

The rtcwake failure in https://sof-ci.01.org/sofpr/PR4105/build8867/devicetest/?model=APL_UP2_NOCODEC&testcase=check-suspend-resume-with-capture is very interesting (and unrelated)

rtcwake: assuming RTC uses UTC ...
rtcwake: wakeup from "mem" using /dev/rtc0 at Wed Apr 28 22:14:48 2021
2021-04-28 22:14:50 UTC Sub-Test: [REMOTE_COMMAND] sleep for 5
2021-04-28 22:14:55 UTC Sub-Test: [REMOTE_INFO] Check for the kernel log status
declare -- cmd="journalctl_cmd --since=@1619648077"
2021-04-28 22:14:55 UTC [ERROR] Caught kernel log error
===========================>>
[ 1218.444372] kernel: rtc_cmos 00:02: Alarms can be up to one month in the future