From 856629d0e835aab7b385f7e2fd33fe58ac99c01d Mon Sep 17 00:00:00 2001 From: Jyri Sarha Date: Mon, 21 Jul 2025 23:36:29 +0300 Subject: [PATCH 1/6] logging: Remove orphan src/logging/Kconfig, see src/trace/Kconfig 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 --- src/logging/Kconfig | 36 ------------------------------------ 1 file changed, 36 deletions(-) delete mode 100644 src/logging/Kconfig diff --git a/src/logging/Kconfig b/src/logging/Kconfig deleted file mode 100644 index 9d854f68aae4..000000000000 --- a/src/logging/Kconfig +++ /dev/null @@ -1,36 +0,0 @@ -# SPDX-License-Identifier: BSD-3-Clause - -# Trace configs - -menu "Logging" - -config LOG_BACKEND_SOF_PROBE - bool "Logging backend with SOF probes" - depends on LOG - select LOG_OUTPUT - help - Enable backend for log output via SOF probe interface. - Probe interface allows to transmit logs and PCM data, muxed over - a shared DMA channel. - Logging is enabled by setting up a probe point with - probe purpose value of PROBE_PURPOSE_LOGGING. - -config LOG_BACKEND_SOF_PROBE_OUTPUT_DICTIONARY - bool "Dictionary" - select LOG_DICTIONARY_SUPPORT - help - Set output format of the SOF probe logging backend to - Zephyr log dictionary. - The resulting log file can be parsed with tools in - zephyr/scripts/logging/dictionary - A dictionary for the binary is created during build. - -config LOG_BACKEND_SOF_PROBE_OUTPUT - int "Set logging output format" - default 1 if LOG_MIPI_SYST_ENABLE - default 2 if LOG_BACKEND_SOF_PROBE_OUTPUT_DICTIONARY - default 0 # Text encoding is default - help - Set the logging format for SOF probe output. - -endmenu From 7984ed96f5fe57bd3fafb5fb9340016d09a78ca7 Mon Sep 17 00:00:00 2001 From: Jyri Sarha Date: Tue, 22 Jul 2025 00:06:53 +0300 Subject: [PATCH 2/6] probe: Reorder the init function to be more logical 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 --- src/probe/probe.c | 16 ++++++++-------- 1 file changed, 8 insertions(+), 8 deletions(-) diff --git a/src/probe/probe.c b/src/probe/probe.c index 6421d4b473c3..6762b8943d94 100644 --- a/src/probe/probe.c +++ b/src/probe/probe.c @@ -365,6 +365,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", @@ -400,14 +408,6 @@ int probe_init(const struct probe_dma *probe_dma) _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; } From a750a05afa5713af01d4cc0cc45396b43b862cf6 Mon Sep 17 00:00:00 2001 From: Jyri Sarha Date: Sat, 1 Oct 2022 00:30:28 +0300 Subject: [PATCH 3/6] probe: Add probes logging auto enable option The add config option to automatically enable probes logging when probes extraction dma is started. Signed-off-by: Jyri Sarha --- src/probe/probe.c | 27 +++++++++++++++++++++++++++ src/trace/Kconfig | 10 ++++++++++ 2 files changed, 37 insertions(+) diff --git a/src/probe/probe.c b/src/probe/probe.c index 6762b8943d94..a389db0b4f84 100644 --- a/src/probe/probe.c +++ b/src/probe/probe.c @@ -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(); @@ -402,6 +425,10 @@ 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"); diff --git a/src/trace/Kconfig b/src/trace/Kconfig index 5ff6b2001130..92ccb461ed18 100644 --- a/src/trace/Kconfig +++ b/src/trace/Kconfig @@ -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 From 5c09c5dc506be1e03a03048ba030341868ea4846 Mon Sep 17 00:00:00 2001 From: Jyri Sarha Date: Mon, 30 Jun 2025 22:38:34 +0300 Subject: [PATCH 4/6] probe: logging: Return the bytes written in probe_logging_hook() Write only the amount of bytes that fits to DMA buffer and return the amount written. Signed-off-by: Jyri Sarha --- src/include/sof/probe/probe.h | 3 ++- src/probe/probe.c | 13 +++++++++---- 2 files changed, 11 insertions(+), 5 deletions(-) diff --git a/src/include/sof/probe/probe.h b/src/include/sof/probe/probe.h index f3f01435902b..de8873ad0a67 100644 --- a/src/include/sof/probe/probe.h +++ b/src/include/sof/probe/probe.h @@ -9,11 +9,12 @@ #define __SOF_PROBE_PROBE_H__ #include +#include /** * 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); diff --git a/src/probe/probe.c b/src/probe/probe.c index a389db0b4f84..2a03b34ef445 100644 --- a/src/probe/probe.c +++ b/src/probe/probe.c @@ -867,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 From f479fce6f2ccb39bbeb0613f591692351bcd037f Mon Sep 17 00:00:00 2001 From: Jyri Sarha Date: Tue, 1 Jul 2025 01:16:25 +0300 Subject: [PATCH 5/6] logging: probe: Add buffer to collect logs before probes DMA is up 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 --- src/logging/log_backend_probe.c | 79 ++++++++++++++++++++++++++++++++- 1 file changed, 77 insertions(+), 2 deletions(-) diff --git a/src/logging/log_backend_probe.c b/src/logging/log_backend_probe.c index b701fb88756b..0b852d780455 100644 --- a/src/logging/log_backend_probe.c +++ b/src/logging/log_backend_probe.c @@ -14,6 +14,10 @@ #include #include +#ifdef PROBE_LOG_DEBUG +#include +#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 @@ -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", + 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); + } else { + if (prebuf.wpos) + pre_buffer_drain(); + + log_push(data, length); + } return length; } From 57df5680619f1951c2da0774873c637b9ddd96fd Mon Sep 17 00:00:00 2001 From: Jyri Sarha Date: Tue, 22 Jul 2025 23:25:37 +0300 Subject: [PATCH 6/6] probe: logging: Remove logging hook when logging disabled 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 --- src/probe/probe.c | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/src/probe/probe.c b/src/probe/probe.c index 2a03b34ef445..7a9cb4121573 100644 --- a/src/probe/probe.c +++ b/src/probe/probe.c @@ -1433,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); +#endif #if CONFIG_IPC_MAJOR_4 dev = ipc_get_comp_by_id(ipc_get(), IPC4_COMP_ID(buf_id->fields.module_id, @@ -1498,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; }