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 09a6c062d941..cc334647c9c2 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; } @@ -506,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; @@ -737,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. @@ -808,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++) { @@ -910,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(); @@ -918,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); @@ -935,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; @@ -1022,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) { @@ -1042,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