Probe log autostart and prebuffering #10096

jsarha · 2025-07-04T09:22:02Z

The PR adds probe logging autostart right after the probes DMA is up and pre buffering to collect the logs from before that happens.

The debug_stream PR is there only to fix the typos and extra newlines that got annoying after seeing them too many times.

Copilot

Pull Request Overview

This PR introduces automatic activation of probe logging when the probe DMA starts and implements a pre-buffering mechanism to capture early log data before the logging hook is registered. Additionally, it refactors the logging hook signature and fixes typos in the debug_stream module.

Auto-enables probe logging during probe_init via a new probe_auto_enable_logs helper.
Changes probe_logging_hook to return processed byte count and adds pre-buffering/draining logic in log_backend_probe.
Adds a Kconfig option for auto-enable and corrects module name/log formatting in debug_stream_slot.

Reviewed Changes

Copilot reviewed 5 out of 5 changed files in this pull request and generated 2 comments.

Show a summary per file

File	Description
src/probe/probe.c	Added `probe_auto_enable_logs` declaration and invocation; updated `probe_logging_hook` to return byte count.
src/logging/log_backend_probe.c	Introduced `log_push`, pre-buffer logic (`pre_buffer`/`pre_buffer_drain`), and conditional hook invocation.
src/logging/Kconfig	Added `LOG_BACKEND_SOF_PROBE_OUTPUT_AUTO_ENABLE` option.
src/include/sof/probe/probe.h	Updated `probe_logging_hook_t` typedef to return `int`.
src/debug/debug_stream/debug_stream_slot.c	Fixed typos in `LOG_MODULE_REGISTER` and removed redundant newlines in logging calls.

Comments suppressed due to low confidence (2)

src/probe/probe.c:341

[nitpick] Consider adding a brief comment describing when and why probe_auto_enable_logs should be used, to improve code readability and maintainability.

static void probe_auto_enable_logs(uint32_t stream_tag);

src/logging/log_backend_probe.c:88

The new pre-buffering logic is not covered by existing tests; consider adding unit tests to verify behavior when buffering data and when buffer overflows.

static void pre_buffer(uint8_t *data, size_t length)

src/logging/Kconfig

src/logging/log_backend_probe.c

src/probe/probe.c

kv2019i · 2025-07-04T10:30:37Z

src/probe/probe.c


 #if CONFIG_LOG_BACKEND_SOF_PROBE
-static void probe_logging_hook(uint8_t *buffer, size_t length)
+static int probe_logging_hook(uint8_t *buffer, size_t length)


Should probe_char_out() in log_backend_probe.c be modified as well (and before)? It seems it doesn't handle the case where hook cannot consume all the data currently.

EDIT: ok, the next patch in series changes the logic.

return ssize_t?

src/logging/log_backend_probe.c

src/debug/debug_stream/debug_stream_slot.c

src/logging/log_backend_probe.c

jsarha · 2025-07-05T13:55:39Z

Fixed the check patch issues (typo in commit message, and space after cast), and added a comment to memcpy_s() call about how how it prevents buffer overflows.

src/probe/probe.c

The src/logging/Kconfig has never been rsourced from src/Kconfig, so better to remove the idle file to avoid confusion. The same options are duplicated in src/trace/Kconfig. Signed-off-by: Jyri Sarha <jyri.sarha@linux.intel.com>

jsarha · 2025-07-21T21:58:13Z

removed idle src/logging/Kconfig
added new Kconfig options to src/trace/Kconfig
followed Guennadis suggestions
added #if around probe_auto_enable_logs() to avoid unused func warings
rebased and updated rzalloc() call according to the new API

It makes more sense to initialize the probe data right after the allocation than at the end of the function. Signed-off-by: Jyri Sarha <jyri.sarha@linux.intel.com>

The add config option to automatically enable probes logging when probes extraction dma is started. Signed-off-by: Jyri Sarha <jyri.sarha@intel.com>

jsarha · 2025-07-22T08:36:07Z

fixed a typo in commit message
restored #if #endif that were dropped in bad merge

lyakh · 2025-07-22T06:18:08Z

src/probe/probe.c

+static int probe_logging_hook(uint8_t *buffer, size_t length)
 {
 	struct probe_pdata *_probe = probe_get();
+	uint32_t max_len;


lyakh · 2025-07-22T06:19:28Z

src/probe/probe.c


 #if CONFIG_LOG_BACKEND_SOF_PROBE
-static void probe_logging_hook(uint8_t *buffer, size_t length)
+static int probe_logging_hook(uint8_t *buffer, size_t length)


return ssize_t?

lyakh · 2025-07-22T06:24:36Z

src/logging/log_backend_probe.c


+static void log_push(uint8_t *data, size_t length)
+{
+	int pos = 0;


lyakh · 2025-07-22T06:31:04Z

src/logging/log_backend_probe.c

+static struct probe_pre_buffer {
+	uint8_t *buf;
+	uint32_t wpos;
+	uint32_t len;


don't see a need for fixed-size types. I'd use "logical" types like size_t etc.

lyakh · 2025-07-22T06:33:35Z

src/logging/log_backend_probe.c

+
+	mlen = snprintf(msg, sizeof(msg), "[Drain %u bytes of pre buffered logs]\n", prebuf.wpos);
+	if (prebuf.len > prebuf.wpos)
+		mlen += snprintf(&msg[mlen], sizeof(msg) - mlen, "[%u bytes dropped]\n",


here msg + mlen seems more logical to me than &msg[mlen]

Ok, I'll change that, but these are really a matter of taste.

lyakh · 2025-07-22T06:37:19Z

src/logging/log_backend_probe.c

+	char msg[80];
+	int mlen;
+
+	mlen = snprintf(msg, sizeof(msg), "[Drain %u bytes of pre buffered logs]\n", prebuf.wpos);


mlen can be > sizeof(msg):

If the output was truncated due to this limit, then the return value is the number of characters (excluding the terminating null byte) which would have been written to the final string if enough space had been available.

Ok, thanks. Forgot about that.

src/logging/log_backend_probe.c

lyakh · 2025-07-22T06:45:54Z

src/logging/log_backend_probe.c

-	if (probe_hook)
-		probe_hook(data, length);
+	if (!probe_hook) {
+		pre_buffer(data, length);


I don't quite understand the flow, but the buffer is only allocated here, and freed in the first pre_buffer_drain(). How does this work? Are there always calls to probe_char_out() with probe_hook == NULL before a single call to probe_char_out() with probe_hook != NULL?

probe_char_out() is called when ever sometihng is logged. probe_hook is set when probes dma is up and special "log"-probepoint is added (the autoenable option is set its added automatically when probes dma is set up). So the logs are buffered if there is no place to push them and the buffer is drained when the probes dma is started.

.... but hmm, it does not appear the logging hook is disabled any where. That is unfortunate as the buffering is not enabled again even if the probes DMA is dropped. I think there is still need for one more commit.

@jsarha ah, thanks for explaining! Somehow didn't catch that yesterday

lyakh

minor comments, can also be addressed in a follow-up

lyakh · 2025-07-23T06:15:55Z

src/probe/probe.c

 	int ret;

+	max_len = _probe->ext_dma.dmapb.avail - sizeof(struct probe_data_packet) - sizeof(checksum);
+	length = MIN(max_len, (uint32_t)length);


the type-cast doesn't seem to be needed

lyakh · 2025-07-23T06:26:22Z

src/probe/probe.c

 			    buf_id->full_id == buffer_id[i]) {
+#if CONFIG_LOG_BACKEND_SOF_PROBE
+				if (enable_logs(&_probe->probe_points[j]))
+					probe_logging_init(NULL);


in the commit message by "probes module is unloaded" you mean the Linux kernel module? And after this call probes would return to pre-buffering? Sounds good

Yes, and that indeed happens. I tested that. Here is how it looks like if PROBE_LOG_DEBUG is set:

[ 0.021313] <inf> clock: clock_set_freq: clock 2 set freq 393216000Hz freq_idx 1 old 0 [ 0.021313] <inf> ll_schedule: zephyr_ll_task_schedule_common: task add 0xa01233c0 0xa00bee84U priority 0 flags 0x0 [ 0.021313] <inf> ll_schedule: zephyr_domain_register: zephyr_domain_register domain->type 1 domain->clk 0 domain->ticks_per_ms 38400 period 1000 [ 0.021313] <inf> dai_intel_ssp: dai_ssp_get_properties: SSP32: fifo 172048, handshake 6, init delay 0 ^C root@9049fa09b4de:~# crecord -c3 -d0 -b8192 -f4 -FS32_LE -R48000 -C4 | sof-probes -l sof-probes: Creating file buffer_16777216.bin [Drain 881 bytes of pre buffered logs] [ 0.021606] <inf> ipc: ipc_cmd: rx : 0x4300000d|0x20301000 [ 0.021606] <inf> probe: probe_get_config: comp:255 0xd 1 probe points sent [ 0.021606] <inf> ipc: ipc_cmd: rx : 0x4400000d|0x30400004 [ 0.021606] <inf> probe: probe_set_config: comp:255 0xd probe_set_config() [ 0.021606] <inf> ipc: ipc_cmd: rx : 0x4b00000d|0xff0000 [ 0.021606] <inf> probe: probe_free: comp:255 0xd probe_free() [ 0.021606] <inf> ll_schedule: zephyr_ll_task_done: task complete 0xa0121d28 0xa00bef44U [ 0.021606] <inf> ll_schedule: zephyr_ll_task_done: num_tasks 1 total_num_tasks 5 [ 0.021606] <inf> ll_schedule: zephyr_domain_unregister: zephyr_domain_unregister domain->type 1 domain->clk 0 [ 0.021606] <inf> dma: sof_dma_put: dma_put(), dma = 0x400cd910, sref = 1 [ 0.021953] <inf> ll_schedule: stats_report: ll core 2 timer avg 5788, max 6200, overruns 0 [Buffer drained in 26 us] [ 0.022366] <inf> ipc: ipc_cmd: rx : 0x4000000d|0xff000c [ 0.022366] <inf> probe: probe_mod_init: comp:255 0xd probe_mod_init() [ 0.022366] <inf> dma: sof_dma_get: dma_get() ID 0 sref = 2 busy channels 0

@jsarha looks good! But is the module there really unloaded or is it just the capture stopped?

@lyakh , at least probe_free() and probe_mod_init() is called according to the logs, so AFAICT the module has been unloaded and loaded again.

lyakh · 2025-07-23T06:33:25Z

src/logging/log_backend_probe.c

+
+	mlen = snprintf(msg, sizeof(msg), "[Drain %zu bytes of pre buffered logs]\n", prebuf.wpos);
+	if (prebuf.len > prebuf.wpos)
+		mlen += snprintf(msg + mlen, sizeof(msg) - mlen, "[%zu bytes dropped]\n",


this also implicitly assumes that sizeof(msg) < mlen at this point. This should be true with an 80-character msg buffer, but...

Ok I'll add "&& mlen < sizeof(msg)" to the if statement. It would be better if snprintf size argument would be signed so that negative size would be detected.

lyakh · 2025-07-23T06:34:36Z

src/logging/log_backend_probe.c

-	if (probe_hook)
-		probe_hook(data, length);
+	if (!probe_hook) {
+		pre_buffer(data, length);


@jsarha ah, thanks for explaining! Somehow didn't catch that yesterday

Write only the amount of bytes that fits to DMA buffer and return the amount written. Signed-off-by: Jyri Sarha <jyri.sarha@linux.intel.com>

Allocate a 4kb buffer to collect the logs arriving before probes DMA is up. Send the contents of the buffer when the callback indicating that DMA is running is set and free the buffer. Busy wait the DMA progress in case the buffer does not fit into the DMA buffer at once. Signed-off-by: Jyri Sarha <jyri.sarha@linux.intel.com>

Remove logging hook when logging is disabled or probes module is unloaded. This should re-enable buffering in case the probes dma client crashes and is respawned or something similar happens. Signed-off-by: Jyri Sarha <jyri.sarha@linux.intel.com>

jsarha marked this pull request as ready for review July 4, 2025 09:22

Copilot AI review requested due to automatic review settings July 4, 2025 09:22

jsarha requested review from dbaluta, kv2019i, lbetlej, lgirdwood, mmaka1 and plbossart as code owners July 4, 2025 09:22

Copilot AI reviewed Jul 4, 2025

View reviewed changes

src/logging/Kconfig Outdated Show resolved Hide resolved

src/logging/log_backend_probe.c Show resolved Hide resolved

jsarha force-pushed the probe_log_improvements branch from 3a6096c to a1af44c Compare July 4, 2025 10:26

kv2019i reviewed Jul 4, 2025

View reviewed changes

jsarha force-pushed the probe_log_improvements branch from a1af44c to 7904f99 Compare July 4, 2025 12:06

kv2019i approved these changes Jul 4, 2025

View reviewed changes

src/logging/log_backend_probe.c Outdated Show resolved Hide resolved

src/logging/log_backend_probe.c Show resolved Hide resolved

jsarha force-pushed the probe_log_improvements branch from 7904f99 to 1cecf5d Compare July 5, 2025 13:51

lyakh reviewed Jul 7, 2025

View reviewed changes

src/probe/probe.c Outdated Show resolved Hide resolved

src/probe/probe.c Outdated Show resolved Hide resolved

jsarha force-pushed the probe_log_improvements branch from 1cecf5d to 189981b Compare July 21, 2025 21:57

Jyri Sarha and others added 2 commits July 22, 2025 11:10

probe: Reorder the init function to be more logical

7984ed9

It makes more sense to initialize the probe data right after the allocation than at the end of the function. Signed-off-by: Jyri Sarha <jyri.sarha@linux.intel.com>

probe: Add probes logging auto enable option

a750a05

The add config option to automatically enable probes logging when probes extraction dma is started. Signed-off-by: Jyri Sarha <jyri.sarha@intel.com>

jsarha force-pushed the probe_log_improvements branch from 189981b to 1dcdad3 Compare July 22, 2025 08:35

jsarha mentioned this pull request Jul 22, 2025

probe: Add probes logging auto enable option #6364

Closed

lgirdwood approved these changes Jul 22, 2025

View reviewed changes

lyakh reviewed Jul 22, 2025

View reviewed changes

jsarha force-pushed the probe_log_improvements branch 2 times, most recently from a7825b3 to f48c5e2 Compare July 22, 2025 21:04

lyakh approved these changes Jul 23, 2025

View reviewed changes

probe: logging: Return the bytes written in probe_logging_hook()

5c09c5d

Write only the amount of bytes that fits to DMA buffer and return the amount written. Signed-off-by: Jyri Sarha <jyri.sarha@linux.intel.com>

Jyri Sarha added 2 commits July 23, 2025 12:26

jsarha force-pushed the probe_log_improvements branch from f48c5e2 to 57df568 Compare July 23, 2025 09:34

kv2019i merged commit a1993c4 into thesofproject:main Jul 28, 2025
37 of 45 checks passed

Probe log autostart and prebuffering #10096

Probe log autostart and prebuffering #10096

Uh oh!

Conversation

jsarha commented Jul 4, 2025

Uh oh!

Copilot AI left a comment

Choose a reason for hiding this comment

Pull Request Overview

Reviewed Changes

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

jsarha commented Jul 5, 2025

Uh oh!

Uh oh!

Uh oh!

jsarha commented Jul 21, 2025

Uh oh!

jsarha commented Jul 22, 2025

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

jsarha Jul 22, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

lyakh left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

jsarha Jul 22, 2025 •

edited

Loading