From bcc553565fba72beeb61212d62bbb147805cf203 Mon Sep 17 00:00:00 2001 From: Kai Vehmanen Date: Thu, 11 Aug 2022 17:37:45 +0300 Subject: [PATCH 1/2] probe: fix probe_task to handle non-aligned amount of data Modify probe task to support cases where the amount of available data is not multiple of the DMA copy size, or wraps around in the DMA buffer. Signed-off-by: Kai Vehmanen --- src/probe/probe.c | 25 +++++++++++++++++++++---- 1 file changed, 21 insertions(+), 4 deletions(-) diff --git a/src/probe/probe.c b/src/probe/probe.c index 09a6c062d941..f3b69c6a8d2e 100644 --- a/src/probe/probe.c +++ b/src/probe/probe.c @@ -200,13 +200,28 @@ static int probe_dma_deinit(struct probe_dma_ext *dma) static enum task_state probe_task(void *data) { struct probe_pdata *_probe = probe_get(); + uint32_t copy_align, avail; int err; - if (_probe->ext_dma.dmapb.avail > 0) + if (!_probe->ext_dma.dmapb.avail) + return SOF_TASK_STATE_RESCHEDULE; + + err = dma_get_attribute(_probe->ext_dma.dc.dmac, DMA_ATTR_COPY_ALIGNMENT, + ©_align); + if (err < 0) { + tr_err(&pr_tr, "probe_task(): dma_get_attribute failed."); + return SOF_TASK_STATE_COMPLETED; + } + + avail = ALIGN_DOWN(_probe->ext_dma.dmapb.avail, copy_align); + if (avail + _probe->ext_dma.dmapb.r_ptr >= _probe->ext_dma.dmapb.end_addr) + avail = _probe->ext_dma.dmapb.end_addr - _probe->ext_dma.dmapb.r_ptr; + + if (avail > 0) err = dma_copy_to_host_nowait(&_probe->ext_dma.dc, &_probe->ext_dma.config, 0, (void *)_probe->ext_dma.dmapb.r_ptr, - _probe->ext_dma.dmapb.avail); + avail); else return SOF_TASK_STATE_RESCHEDULE; @@ -216,8 +231,10 @@ static enum task_state probe_task(void *data) } /* buffer data sent, set read pointer and clear avail bytes */ - _probe->ext_dma.dmapb.r_ptr = _probe->ext_dma.dmapb.w_ptr; - _probe->ext_dma.dmapb.avail = 0; + _probe->ext_dma.dmapb.r_ptr += avail; + if (_probe->ext_dma.dmapb.r_ptr >= _probe->ext_dma.dmapb.end_addr) + _probe->ext_dma.dmapb.r_ptr -= _probe->ext_dma.dmapb.size; + _probe->ext_dma.dmapb.avail -= avail; return SOF_TASK_STATE_RESCHEDULE; } From 2b0e74a88655ac9e62a9370b83a065481ba4e7b5 Mon Sep 17 00:00:00 2001 From: Kai Vehmanen Date: Thu, 11 Aug 2022 17:40:07 +0300 Subject: [PATCH 2/2] probe: add backend for logging via probes Implement a Zephyr logging backend which routes the logs via SOF probes interface. Tested with Linux SOF driver, crecord and sof/tools/probes for decoding. The patch modifies the probes IPC3 interface, adding a new probe purpose field (PROBE_PURPOSE_LOGGING, 0x3) to specify probe extraction for logging. A field for system trace (as is also reserved (PROBE_PURPOSE_TRACING). 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# term1# sof-probes -p /tmp/extract.dat term1# cat buffer_0.bin Signed-off-by: Kai Vehmanen --- src/include/ipc/probe.h | 4 +- src/include/kernel/abi.h | 2 +- src/include/sof/probe/probe.h | 19 ++++++ src/logging/Kconfig | 36 +++++++++++ src/logging/log_backend_probe.c | 111 ++++++++++++++++++++++++++++++++ src/probe/probe.c | 102 +++++++++++++++++++++-------- src/trace/Kconfig | 29 +++++++++ zephyr/CMakeLists.txt | 6 +- 8 files changed, 278 insertions(+), 31 deletions(-) create mode 100644 src/logging/Kconfig create mode 100644 src/logging/log_backend_probe.c diff --git a/src/include/ipc/probe.h b/src/include/ipc/probe.h index 24d590da2d8e..335de396d201 100644 --- a/src/include/ipc/probe.h +++ b/src/include/ipc/probe.h @@ -22,6 +22,8 @@ #define PROBE_PURPOSE_EXTRACTION 0x1 #define PROBE_PURPOSE_INJECTION 0x2 +#define PROBE_PURPOSE_LOGGING 0x3 +#define PROBE_PURPOSE_TRACING 0x4 #define PROBE_EXTRACT_SYNC_WORD 0xBABEBEBA @@ -109,7 +111,7 @@ struct probe_dma { */ struct probe_point { uint32_t buffer_id; /**< ID of buffer to which probe is attached */ - uint32_t purpose; /**< PROBE_PURPOSE_EXTRACTION or PROBE_PURPOSE_INJECTION */ + uint32_t purpose; /**< PROBE_PURPOSE_xxx */ uint32_t stream_tag; /**< Stream tag of DMA via which data will be provided for injection. * For extraction purposes, stream tag is ignored when received, * but returned actual extraction stream tag via INFO function. diff --git a/src/include/kernel/abi.h b/src/include/kernel/abi.h index b14618749a5e..4c05fb5be4b3 100644 --- a/src/include/kernel/abi.h +++ b/src/include/kernel/abi.h @@ -29,7 +29,7 @@ /** \brief SOF ABI version major, minor and patch numbers */ #define SOF_ABI_MAJOR 3 -#define SOF_ABI_MINOR 23 +#define SOF_ABI_MINOR 24 #define SOF_ABI_PATCH 0 /** \brief SOF ABI version number. Format within 32bit word is MMmmmppp */ diff --git a/src/include/sof/probe/probe.h b/src/include/sof/probe/probe.h index d0a5b289a9de..0ead9862b4b9 100644 --- a/src/include/sof/probe/probe.h +++ b/src/include/sof/probe/probe.h @@ -12,6 +12,25 @@ #include +/* + * Buffer id used in the probe output stream headers for + * logging data packet. + */ +#define PROBE_LOGGING_BUFFER_ID 0 + +/** + * A buffer of logging data is available for processing. + */ +typedef void(*probe_logging_hook_t)(uint8_t *buffer, size_t length); + +/** + * @brief Initialize the probe logging backend. + * + * @param hook Function is called when new logging data is written + * out by the logger. + */ +void probe_logging_init(probe_logging_hook_t hook); + /* * \brief Initialize probes subsystem * diff --git a/src/logging/Kconfig b/src/logging/Kconfig new file mode 100644 index 000000000000..9d854f68aae4 --- /dev/null +++ b/src/logging/Kconfig @@ -0,0 +1,36 @@ +# 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 diff --git a/src/logging/log_backend_probe.c b/src/logging/log_backend_probe.c new file mode 100644 index 000000000000..16ba5b49585b --- /dev/null +++ b/src/logging/log_backend_probe.c @@ -0,0 +1,111 @@ +// SPDX-License-Identifier: BSD-3-Clause +// +// Copyright(c) 2022 Intel Corporation. All rights reserved. + +#include +#include +#include +#include +#include + +#include +#include +#include +#include +#include + +/* + * A lock is needed as log_process() and log_panic() have no internal locks + * to prevent concurrency. Meaning if log_process is called after + * log_panic was called previously, log_process may happen from another + * CPU and calling context than the log processing thread running in + * the background. On an SMP system this is a race. + * + * This caused a race on the output trace such that the logging output + * was garbled and useless. + */ +static struct k_spinlock probe_lock; + +static uint32_t probe_log_format_current = CONFIG_LOG_BACKEND_SOF_PROBE_OUTPUT; + +#define LOG_BUF_SIZE 80 +static uint8_t log_buf[LOG_BUF_SIZE]; + +static probe_logging_hook_t probe_hook; + +static int probe_char_out(uint8_t *data, size_t length, void *ctx) +{ + if (probe_hook) + probe_hook(data, length); + + return length; +} + +LOG_OUTPUT_DEFINE(log_output_adsp_probe, probe_char_out, log_buf, sizeof(log_buf)); + +static uint32_t format_flags(void) +{ + uint32_t flags = LOG_OUTPUT_FLAG_LEVEL | LOG_OUTPUT_FLAG_TIMESTAMP; + + if (IS_ENABLED(CONFIG_LOG_BACKEND_FORMAT_TIMESTAMP)) + flags |= LOG_OUTPUT_FLAG_FORMAT_TIMESTAMP; + + return flags; +} + +static void probe_log_panic(struct log_backend const *const backend) +{ + k_spinlock_key_t key = k_spin_lock(&probe_lock); + + log_backend_std_panic(&log_output_adsp_probe); + + k_spin_unlock(&probe_lock, key); +} + +static void probe_log_dropped(const struct log_backend *const backend, + uint32_t cnt) +{ + log_output_dropped_process(&log_output_adsp_probe, cnt); +} + +static void probe_log_process(const struct log_backend *const backend, + union log_msg_generic *msg) +{ + log_format_func_t log_output_func = log_format_func_t_get(probe_log_format_current); + + k_spinlock_key_t key = k_spin_lock(&probe_lock); + + log_output_func(&log_output_adsp_probe, &msg->log, format_flags()); + + k_spin_unlock(&probe_lock, key); +} + +static int probe_log_format_set(const struct log_backend *const backend, uint32_t log_type) +{ + probe_log_format_current = log_type; + return 0; +} + +/** + * Lazily initialized, while the DMA may not be setup we continue + * to buffer log messages untilt he buffer is full. + */ +static void probe_log_init(const struct log_backend *const backend) +{ + ARG_UNUSED(backend); +} + +const struct log_backend_api log_backend_adsp_probe_api = { + .process = probe_log_process, + .dropped = IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE) ? NULL : probe_log_dropped, + .panic = probe_log_panic, + .format_set = probe_log_format_set, + .init = probe_log_init, +}; + +LOG_BACKEND_DEFINE(log_backend_adsp_probe, log_backend_adsp_probe_api, true); + +void probe_logging_init(probe_logging_hook_t fn) +{ + probe_hook = fn; +} diff --git a/src/probe/probe.c b/src/probe/probe.c index f3b69c6a8d2e..cc334647c9c2 100644 --- a/src/probe/probe.c +++ b/src/probe/probe.c @@ -523,6 +523,10 @@ static int copy_to_pbuffer(struct probe_dma_buf *pbuf, void *data, if (bytes == 0) return 0; + /* check if there is free room in probe buffer */ + if (pbuf->size - pbuf->avail < bytes) + return -EINVAL; + /* check if it will not exceed end_addr */ if ((char *)pbuf->end_addr - (char *)pbuf->w_ptr < bytes) { head = (char *)pbuf->end_addr - (char *)pbuf->w_ptr; @@ -754,6 +758,36 @@ static uint32_t probe_gen_format(uint32_t frame_fmt, uint32_t rate, return format; } +/* + * Check if more than 75% of buffer is already used, + * and if yes, rescheduled the probe task immediately. + */ +static void kick_probe_task(struct probe_pdata *_probe) +{ + if (_probe->ext_dma.dmapb.size - _probe->ext_dma.dmapb.avail < + _probe->ext_dma.dmapb.size >> 2) + reschedule_task(&_probe->dmap_work, 0); +} + +#if CONFIG_LOG_BACKEND_SOF_PROBE +static void probe_logging_hook(uint8_t *buffer, size_t length) +{ + struct probe_pdata *_probe = probe_get(); + int ret; + + ret = probe_gen_header(PROBE_LOGGING_BUFFER_ID, length, 0); + if (ret < 0) + return; + + ret = copy_to_pbuffer(&_probe->ext_dma.dmapb, + buffer, length); + if (ret < 0) + return; + + kick_probe_task(_probe); +} +#endif + /** * \brief General extraction probe callback, called from buffer produce. * It will search for probe point connected to this buffer. @@ -825,10 +859,8 @@ static void probe_cb_produce(void *arg, enum notify_id type, void *data) if (ret < 0) goto err; } - /* check if more than 75% of buffer size is already used */ - if (_probe->ext_dma.dmapb.size - _probe->ext_dma.dmapb.avail < - _probe->ext_dma.dmapb.size >> 2) - probe_task(NULL); + + kick_probe_task(_probe); } else { /* search for DMA used by this probe point */ for (j = 0; j < CONFIG_PROBE_DMA_MAX; j++) { @@ -927,6 +959,11 @@ static void probe_cb_free(void *arg, enum notify_id type, void *data) tr_err(&pr_tr, "probe_cb_free(): probe_point_remove() failed"); } +static bool probe_purpose_needs_ext_dma(uint32_t purpose) +{ + return purpose == PROBE_PURPOSE_EXTRACTION || purpose == PROBE_PURPOSE_LOGGING; +} + int probe_point_add(uint32_t count, struct probe_point *probe) { struct probe_pdata *_probe = probe_get(); @@ -935,7 +972,7 @@ int probe_point_add(uint32_t count, struct probe_point *probe) uint32_t buffer_id; uint32_t first_free; uint32_t dma_found; - struct ipc_comp_dev *dev; + struct ipc_comp_dev *dev = NULL; tr_dbg(&pr_tr, "probe_point_add() count = %u", count); @@ -952,34 +989,36 @@ int probe_point_add(uint32_t count, struct probe_point *probe) probe[i].stream_tag); if (probe[i].purpose != PROBE_PURPOSE_EXTRACTION && - probe[i].purpose != PROBE_PURPOSE_INJECTION) { + probe[i].purpose != PROBE_PURPOSE_INJECTION && + probe[i].purpose != PROBE_PURPOSE_LOGGING) { tr_err(&pr_tr, "probe_point_add() error: invalid purpose %d", probe[i].purpose); return -EINVAL; } - if (probe[i].purpose == PROBE_PURPOSE_EXTRACTION && - _probe->ext_dma.stream_tag == PROBE_DMA_INVALID) { - tr_err(&pr_tr, "probe_point_add(): Setting probe for extraction, while extraction DMA not enabled."); - + if (_probe->ext_dma.stream_tag == PROBE_DMA_INVALID && + probe_purpose_needs_ext_dma(probe[i].purpose)) { + tr_err(&pr_tr, "probe_point_add(): extraction DMA not enabled."); return -EINVAL; } - /* check if buffer exists */ - dev = ipc_get_comp_by_id(ipc_get(), probe[i].buffer_id); - if (!dev) { - tr_err(&pr_tr, "probe_point_add(): No device with ID %u found.", - probe[i].buffer_id); + if (probe[i].purpose == PROBE_PURPOSE_EXTRACTION) { + /* check if buffer exists */ + dev = ipc_get_comp_by_id(ipc_get(), probe[i].buffer_id); + if (!dev) { + tr_err(&pr_tr, "probe_point_add(): No device with ID %u found.", + probe[i].buffer_id); - return -EINVAL; - } + return -EINVAL; + } - if (dev->type != COMP_TYPE_BUFFER) { - tr_err(&pr_tr, "probe_point_add(): Device ID %u is not a buffer.", - probe[i].buffer_id); + if (dev->type != COMP_TYPE_BUFFER) { + tr_err(&pr_tr, "probe_point_add(): Device ID %u is not a buffer.", + probe[i].buffer_id); - return -EINVAL; + return -EINVAL; + } } first_free = CONFIG_PROBE_POINTS_MAX; @@ -1039,10 +1078,11 @@ int probe_point_add(uint32_t count, struct probe_point *probe) return -EBUSY; } - } else if (probe[i].purpose == PROBE_PURPOSE_EXTRACTION) { + } else { + /* prepare extraction DMA */ for (j = 0; j < CONFIG_PROBE_POINTS_MAX; j++) { if (_probe->probe_points[j].stream_tag != PROBE_DMA_INVALID && - _probe->probe_points[j].purpose == PROBE_PURPOSE_EXTRACTION) + probe_purpose_needs_ext_dma(_probe->probe_points[j].purpose)) break; } if (j == CONFIG_PROBE_POINTS_MAX) { @@ -1059,10 +1099,18 @@ int probe_point_add(uint32_t count, struct probe_point *probe) _probe->probe_points[first_free].stream_tag = probe[i].stream_tag; - notifier_register(_probe, dev->cb, NOTIFIER_ID_BUFFER_PRODUCE, - &probe_cb_produce, 0); - notifier_register(_probe, dev->cb, NOTIFIER_ID_BUFFER_FREE, - &probe_cb_free, 0); + if (probe[i].purpose == PROBE_PURPOSE_LOGGING) { +#if CONFIG_LOG_BACKEND_SOF_PROBE + probe_logging_init(probe_logging_hook); +#else + return -EINVAL; +#endif + } else { + notifier_register(_probe, dev->cb, NOTIFIER_ID_BUFFER_PRODUCE, + &probe_cb_produce, 0); + notifier_register(_probe, dev->cb, NOTIFIER_ID_BUFFER_FREE, + &probe_cb_free, 0); + } } return 0; diff --git a/src/trace/Kconfig b/src/trace/Kconfig index 762318b7590a..e691bc9e3cd3 100644 --- a/src/trace/Kconfig +++ b/src/trace/Kconfig @@ -94,4 +94,33 @@ config TRACE_BURST_COUNT Amount of messages that will pass through the filter even if sent in rapid succession. Allowed message burst size before filter suppresses the message. +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 diff --git a/zephyr/CMakeLists.txt b/zephyr/CMakeLists.txt index a59d69c4aa07..39c199a367df 100644 --- a/zephyr/CMakeLists.txt +++ b/zephyr/CMakeLists.txt @@ -599,8 +599,10 @@ zephyr_library_sources_ifdef(CONFIG_IPC_MAJOR_4 zephyr_library_sources_ifdef(CONFIG_TRACE ${SOF_SRC_PATH}/trace/dma-trace.c - ${SOF_SRC_PATH}/trace/trace.c -) + ${SOF_SRC_PATH}/trace/trace.c) + +zephyr_library_sources_ifdef(CONFIG_LOG_BACKEND_SOF_PROBE + ${SOF_SRC_PATH}/logging/log_backend_probe.c) # Optional SOF sources - depends on Kconfig - WIP