probe: add backend for logging via probes

[kv2019i]

probe logging: add backend for logging via probes

Work in progress code that routes Zephyr logs via the logging
subsystem to SOF probe extraction point.

Lot of hardcodes still in this version, but this is tested to work
with Linux SOF driver, crecord and sof/tools/probes for decoding.

Example usage in Linux:

term1# crecord -c3 -d0 -b8192 -f4 -FS32_LE -R48000 -C4 /tmp/extract.dat
term2# echo 0,3,0 > /sys/kernel/debug/sof/probe_points
term1# <terminate crecord>
term1# sof-probes -p /tmp/extract.dat
term1# cat buffer_999999.wav

[kv2019i]

FYI @teburd

[lgirdwood]

@kv2019i we should be able to make this scriptable in sof-tools. We do need a separate demux tool though that can split pcm/log/trace data by slot into individual files.

[kv2019i]

@lgirdwood wrote:

@kv2019i we should be able to make this scriptable in sof-tools. We do need a separate demux tool though that can split pcm/log/trace data by slot into individual files.

sof/tools/probes/probes_main.c is that demux tool, so we have that already.

We might need a more integrated tool. One developer requirement is to observe "live" logs from the FW and the current palette of tools forces to cut the logging to see any decoded logs. So potentially we need a more unified tool that combines probe point configuration, reading data from compress PCM and calling log decoders (e.g. the zephyr/mipi tool for syst catalog). In the end, developer wants to see live logs in human-readable format on her console. FYI @marc-hb @jsarha @pjdobrowolski

[lgirdwood]

We might need a more integrated tool. One developer requirement is to observe "live" logs from the FW and the current palette of tools forces to cut the logging to see any decoded logs. So potentially we need a more unified tool that combines probe point configuration, reading data from compress PCM and calling log decoders (e.g. the zephyr/mipi tool for syst catalog). In the end, developer wants to see live logs in human-readable format on her console. FYI @marc-hb @jsarha @pjdobrowolski

ok, we can update the existing tool to strip the container for slot N and send it's stdout to log/trace tool stdin as a cmd line option.

[kv2019i]

V2 update:

• fixed a few glaring bugs
• some cleanup to code
• renamed special buffer-id to 999999 (99 could be used in fairly typical topologies)

[lgirdwood]

@kv2019i what are the next steps now ?

[kv2019i]

@lgirdwood wrote:

@kv2019i what are the next steps now ?

I'm close to complete an update that gets rid of the buffer-id overload, and simplifies the interface between logger and probe code. Thanks @ujfalusi for the feedback for the interface!

Originally I was thinking that I keep this as draft until @jsarha and @abonislawski have the IPC4 updates ready, and then we merge probes logging as a IPC4 only feature. But, but, the latest versions starts to be so clean, so maybe we start with a IPC3 probes logging imlementation first. This can be used to kick off user-space tool development and testing, and then when the IPC4 work is ready, we can add that on top. I'll push a new PR update today.

[kv2019i]

V3 updated:

• much cleaner implementation (direct hook callback, no need to go via comp_buffer, audio_stream and others)
• small ABI change to add a new probe purpose type
• open: the probe_dma_buf.avail field make the code a bit clumsy.. with audio probes this was not a problem as the probed data was nicely aligned with DMA minimum aligned transfer size, but with logs, the code becomes a bit messy... can be cleaned up
• open: need to figure whether there is a good header/format to use for logging probe data... now setting format with zeros and our SOF probes decoder is happy with this
• open: reliability issues -- occasional hits a Zephyr panic, needs more testing

[kv2019i]

V4 update:

• functionality now ready
• interface changes ready, needs a slight update to the demux tool -> probe-app: add support for non-audio probe buffers #6130
• adds a new Kconfig for the backend (only available in Zephyr builds)
• fix XTOS SOF build
• split generic probe_task() fixes to a separate commit
• todo: cleanup related to "probe.purpose" checks (raised in review)
• todo: double-check the logic to manage "avail checks" in probe_task()
• todo: add probe logging to as a default for Intel platforms (at least), and disable dma-trace

[kv2019i]

V5 updated:

• no longer draft, ready for review
• tested with multiple log formats (text, dictionary, mipi -syst)
• a few major bugfixes that caused the logging to end in FW panic
• places for further cleanup:
  - the DMA buffer handling code is still a bit messy
  - the configurability via Kconfig is limited compared to upstream Zephyr logging backends
• work needed with "crecord" tool (not related to this PR)
  - logs stay buffered in kernel for a long time
  - drain is apparently not working, so end of log stream is lost due to Linux kernel issue, possible related to [RFC]: Add support for drain operation on compress streams linux#3808

[lgirdwood]

LGTM, and I see it picks up the buffer ID change from @lyakh PR too.

[lgirdwood]

Can you add TRACE here too (we can do in 1 ABI bump) as LOG and TRACE are different things in Zephyr.

[kv2019i]

@lgirdwood I can add if it's ok to have it without matching implementation in this PR.

[jsarha]

term1# crecord -c3 -d0 -b8192 -f4 -FS32_LE -R48000 -C4 /tmp/extract.dat
term2# echo 0,3,0 > /sys/kernel/debug/sof/probe_points
term1#
term1# sof-probes -p /tmp/extract.dat
term1# cat buffer_999999.wav

I wonder what I am missing. The echo steps does not produce an error and the probe point is there:
root@jhary:~# cat /sys/kernel/debug/sof/probe_points
Id: 0x00000000 Purpose: 3 Node id: 0x2

Still there is no data captured by crecord ("We read 8192, DSP sent 0" all the time), and obviously nothing when I try to extract the capture. I have this branch and "CONFIG_LOG_BACKEND_SOF_PROBE=y" in my confing in addition to old probes options (PCM probes work), should I need something more?

[kv2019i]

V6 uploaded:

• moved the backend code from sof/src/trace/ to sof/src/logging/
• addressed comments by @lyakh and @lgirdwood