Skip to content

Probe log autostart and prebuffering #10096

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
kv2019i merged 6 commits into from
Jul 28, 2025
+140 −51
Merged

Probe log autostart and prebuffering #10096

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
856629d
logging: Remove orphan src/logging/Kconfig, see src/trace/Kconfig
Jul 21, 2025
7984ed9
probe: Reorder the init function to be more logical
Jul 21, 2025
a750a05
probe: Add probes logging auto enable option
jsarha Sep 30, 2022
5c09c5d
probe: logging: Return the bytes written in probe_logging_hook()
Jun 30, 2025
f479fce
logging: probe: Add buffer to collect logs before probes DMA is up
Jun 30, 2025
57df568
probe: logging: Remove logging hook when logging disabled
Jul 22, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
3 changes: 2 additions & 1 deletion src/include/sof/probe/probe.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -9,11 +9,12 @@
#define __SOF_PROBE_PROBE_H__

#include <ipc/probe.h>
#include <sys/types.h>

/**
* A buffer of logging data is available for processing.
*/
typedef void(*probe_logging_hook_t)(uint8_t *buffer, size_t length);
typedef ssize_t(*probe_logging_hook_t)(uint8_t *buffer, size_t length);

#if CONFIG_LOG_BACKEND_SOF_PROBE
const struct log_backend *log_backend_probe_get(void);
Expand Down
36 changes: 0 additions & 36 deletions src/logging/Kconfig
View file
Open in desktop

This file was deleted.

79 changes: 77 additions & 2 deletions src/logging/log_backend_probe.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -14,6 +14,10 @@
#include <sof/lib/notifier.h>
#include <sof/probe/probe.h>

#ifdef PROBE_LOG_DEBUG
#include <stdio.h>
#endif

/*
* A lock is needed as log_process() and log_panic() have no internal locks
* to prevent concurrency. Meaning if log_process is called after
Expand All @@ -33,10 +37,81 @@ static uint8_t log_buf[LOG_BUF_SIZE];

static probe_logging_hook_t probe_hook;

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

do {
int ret = probe_hook(data + pos, length - pos);

if (ret < 0)
break;
pos += ret;
} while (pos < length);
}

#define PRE_BUFFER_SIZE 4096
static struct probe_pre_buffer {
uint8_t *buf;
size_t wpos;
size_t len;
} prebuf;

static void pre_buffer_drain(void)
{
#ifdef PROBE_LOG_DEBUG
/* NOTE: The debug code only works with ascii/text log output */
uint64_t stamp = sof_cycle_get_64();
char msg[80];
int mlen;

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

@lyakh lyakh Jul 23, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Contributor Author

@jsarha jsarha Jul 23, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

prebuf.len - prebuf.wpos);
log_push(msg, MIN(mlen, sizeof(msg)));
#endif

log_push(prebuf.buf, prebuf.wpos);
rfree(prebuf.buf);
prebuf.buf = NULL;
prebuf.len = 0;
prebuf.wpos = 0;

#ifdef PROBE_LOG_DEBUG
mlen = snprintf(msg, sizeof(msg), "[Buffer drained in %llu us]\n",
k_cyc_to_us_near64(sof_cycle_get_64() - stamp));

log_push(msg, MIN(mlen, sizeof(msg)));
#endif
}

static void pre_buffer(uint8_t *data, size_t length)
{
int ret;

prebuf.len += length;
if (!prebuf.buf) {
prebuf.buf = rzalloc(SOF_MEM_FLAG_USER, PRE_BUFFER_SIZE);
if (!prebuf.buf)
return;
}
/* Protection against buffer over flow relies on memcpy_s() */
ret = memcpy_s(&prebuf.buf[prebuf.wpos], PRE_BUFFER_SIZE - prebuf.wpos, data, length);
if (!ret)
prebuf.wpos += length;
}

static int probe_char_out(uint8_t *data, size_t length, void *ctx)
{
if (probe_hook)
probe_hook(data, length);
if (!probe_hook) {
pre_buffer(data, length);
Copy link
Collaborator

@lyakh lyakh Jul 22, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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?

Copy link
Contributor Author

@jsarha jsarha Jul 22, 2025 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Collaborator

@lyakh lyakh Jul 23, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

} else {
if (prebuf.wpos)
pre_buffer_drain();

log_push(data, length);
}

return length;
}
Expand Down
63 changes: 51 additions & 12 deletions src/probe/probe.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -338,6 +338,29 @@ static enum task_state probe_task(void *data)
return SOF_TASK_STATE_RESCHEDULE;
}

#if CONFIG_LOG_BACKEND_SOF_PROBE_OUTPUT_AUTO_ENABLE
static void probe_auto_enable_logs(uint32_t stream_tag)
{
struct probe_point log_point = {
#if CONFIG_IPC_MAJOR_4
.buffer_id = {
.full_id = 0,
},
#else
.buffer_id = 0,
#endif
.purpose = PROBE_PURPOSE_EXTRACTION,
.stream_tag = stream_tag,
};
int ret;

ret = probe_point_add(1, &log_point);

if (ret)
tr_err(&pr_tr, "probe_auto_enable_logs() failed");
}
#endif

int probe_init(const struct probe_dma *probe_dma)
{
struct probe_pdata *_probe = probe_get();
Expand Down Expand Up @@ -365,6 +388,14 @@ int probe_init(const struct probe_dma *probe_dma)
return -ENOMEM;
}

/* initialize injection DMAs as invalid */
for (i = 0; i < CONFIG_PROBE_DMA_MAX; i++)
_probe->inject_dma[i].stream_tag = PROBE_DMA_INVALID;

/* initialize probe points as invalid */
for (i = 0; i < CONFIG_PROBE_POINTS_MAX; i++)
_probe->probe_points[i].stream_tag = PROBE_POINT_INVALID;

/* setup extraction dma if requested */
if (probe_dma) {
tr_dbg(&pr_tr, "\tstream_tag = %u, dma_buffer_size = %u",
Expand Down Expand Up @@ -394,20 +425,16 @@ int probe_init(const struct probe_dma *probe_dma)
SOF_UUID(probe_task_uuid),
SOF_SCHEDULE_LL_TIMER, SOF_TASK_PRI_LOW,
probe_task, _probe, 0, 0);

#if CONFIG_LOG_BACKEND_SOF_PROBE_OUTPUT_AUTO_ENABLE
probe_auto_enable_logs(probe_dma->stream_tag);
#endif
} else {
tr_dbg(&pr_tr, "\tno extraction DMA setup");

_probe->ext_dma.stream_tag = PROBE_DMA_INVALID;
}

/* initialize injection DMAs as invalid */
for (i = 0; i < CONFIG_PROBE_DMA_MAX; i++)
_probe->inject_dma[i].stream_tag = PROBE_DMA_INVALID;

/* initialize probe points as invalid */
for (i = 0; i < CONFIG_PROBE_POINTS_MAX; i++)
_probe->probe_points[i].stream_tag = PROBE_POINT_INVALID;

return 0;
}

Expand Down Expand Up @@ -840,27 +867,32 @@ static void kick_probe_task(struct probe_pdata *_probe)
}

#if CONFIG_LOG_BACKEND_SOF_PROBE
static void probe_logging_hook(uint8_t *buffer, size_t length)
static ssize_t probe_logging_hook(uint8_t *buffer, size_t length)
{
struct probe_pdata *_probe = probe_get();
uint64_t checksum;
size_t max_len;
int ret;

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

ret = probe_gen_header(PROBE_LOGGING_BUFFER_ID, length, 0, &checksum);
if (ret < 0)
return;
return ret;

ret = copy_to_pbuffer(&_probe->ext_dma.dmapb,
buffer, length);
if (ret < 0)
return;
return ret;

ret = copy_to_pbuffer(&_probe->ext_dma.dmapb,
&checksum, sizeof(checksum));
if (ret < 0)
return;
return ret;

kick_probe_task(_probe);
return length;
}
#endif

Expand Down Expand Up @@ -1401,6 +1433,10 @@ int probe_point_remove(uint32_t count, const uint32_t *buffer_id)

if (_probe->probe_points[j].stream_tag != PROBE_POINT_INVALID &&
buf_id->full_id == buffer_id[i]) {
#if CONFIG_LOG_BACKEND_SOF_PROBE
if (enable_logs(&_probe->probe_points[j]))
probe_logging_init(NULL);
Copy link
Collaborator

@lyakh lyakh Jul 23, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Contributor Author

@jsarha jsarha Jul 23, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Collaborator

@lyakh lyakh Jul 24, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Contributor Author

@jsarha jsarha Jul 29, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@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.

#endif
#if CONFIG_IPC_MAJOR_4
dev = ipc_get_comp_by_id(ipc_get(),
IPC4_COMP_ID(buf_id->fields.module_id,
Expand Down Expand Up @@ -1466,6 +1502,9 @@ static int probe_free(struct processing_module *mod)

probe_deinit();

#if CONFIG_LOG_BACKEND_SOF_PROBE
probe_logging_init(NULL);
#endif
return 0;
}

Expand Down
10 changes: 10 additions & 0 deletions src/trace/Kconfig
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -108,6 +108,16 @@ config LOG_BACKEND_SOF_PROBE
Logging is enabled by setting up a probe point with
probe purpose value of PROBE_PURPOSE_LOGGING.

config LOG_BACKEND_SOF_PROBE_OUTPUT_AUTO_ENABLE
bool "Automatically enable probes logging when probe dma is started"
depends on LOG_BACKEND_SOF_PROBE
help
Automatically enable logging as soon as probes DMA
starts. This option simplifies probes logging back
end usage as there is no need to enable logs after
every boot. The probes DMA is still needed before the
log output can be enabled.

config LOG_BACKEND_SOF_PROBE_OUTPUT_DICTIONARY
bool "Dictionary"
select LOG_DICTIONARY_SUPPORT
Expand Down
Loading