From 3a4864bdd2dd07c2a5e7991d15d79aa6f87a2405 Mon Sep 17 00:00:00 2001 From: Tom Burdick Date: Wed, 24 Aug 2022 16:10:23 -0500 Subject: [PATCH] logging: adsp hda backend improvements * Adds a default hook and init function for cavstool. * Adds an optional padding on flush feature to ensure all data is written. * Fixes an error in cavstool.py for correctly wrapping the ring buffer. * The test case now ensures wraps and flushes occur numerous times. Signed-off-by: Tom Burdick --- soc/xtensa/intel_adsp/tools/cavstool.py | 27 +++- subsys/logging/Kconfig.backends | 14 ++ subsys/logging/log_backend_adsp_hda.c | 128 ++++++++++++++++--- tests/boards/intel_adsp/hda_log/prj.conf | 6 +- tests/boards/intel_adsp/hda_log/src/logger.c | 53 +------- 5 files changed, 156 insertions(+), 72 deletions(-) diff --git a/soc/xtensa/intel_adsp/tools/cavstool.py b/soc/xtensa/intel_adsp/tools/cavstool.py index 2d501958285..f3896edd32b 100755 --- a/soc/xtensa/intel_adsp/tools/cavstool.py +++ b/soc/xtensa/intel_adsp/tools/cavstool.py @@ -117,6 +117,7 @@ class HDAStream: self.regs.BDPL = self.buf_list_addr & 0xffffffff self.regs.CBL = buf_len self.regs.LVI = self.n_bufs - 1 + self.mem.seek(0) self.debug() log.info(f"Configured stream {self.stream_id}") @@ -620,17 +621,29 @@ def ipc_command(data, ext_data): buf[i] = i hda_streams[stream_id].write(buf) elif data == 12: # HDA PRINT - log.info("Doing HDA Print") stream_id = ext_data & 0xFF buf_len = ext_data >> 8 & 0xFFFF hda_str = hda_streams[stream_id] + # check for wrap here pos = hda_str.mem.tell() - buf_data = hda_str.mem.read(buf_len).decode("utf-8", "replace") - log.info(f"DSP LOG MSG (idx: {pos}, len: {buf_len}): {buf_data}") - pos = hda_str.mem.tell() - if pos >= hda_str.buf_len*2: - log.info(f"Wrapping log reader, pos {pos} len {hda_str.buf_len}") + read_lens = [buf_len, 0] + if pos + buf_len >= hda_str.buf_len*2: + read_lens[0] = hda_str.buf_len*2 - pos + read_lens[1] = buf_len - read_lens[0] + # validate the read lens + assert (read_lens[0] + pos) <= (hda_str.buf_len*2) + assert read_lens[0] % 128 == 0 + assert read_lens[1] % 128 == 0 + buf_data0 = hda_str.mem.read(read_lens[0]) + hda_msg0 = buf_data0.decode("utf-8", "replace") + sys.stdout.write(hda_msg0) + if read_lens[1] != 0: hda_str.mem.seek(0) + buf_data1 = hda_str.mem.read(read_lens[1]) + hda_msg1 = buf_data1.decode("utf-8", "replace") + sys.stdout.write(hda_msg1) + pos = hda_str.mem.tell() + sys.stdout.flush() else: log.warning(f"cavstool: Unrecognized IPC command 0x{data:x} ext 0x{ext_data:x}") if not fw_is_alive(): @@ -887,6 +900,8 @@ if __name__ == "__main__": asyncio.get_event_loop().run_until_complete(_main(None)) except KeyboardInterrupt: start_output = False + except Exception as e: + log.error(e) finally: sys.exit(0) diff --git a/subsys/logging/Kconfig.backends b/subsys/logging/Kconfig.backends index 39724ccc422..a081c4de3c9 100644 --- a/subsys/logging/Kconfig.backends +++ b/subsys/logging/Kconfig.backends @@ -367,6 +367,20 @@ config LOG_BACKEND_ADSP_HDA_FLUSH_TIME to hardware by informing the DMA hardware the contents of the ring buffer. +config LOG_BACKEND_ADSP_HDA_CAVSTOOL + bool "Log backend is to be used with cavstool" + help + Use cavstool understood IPC messages to inform setup and logging of + HDA messages. + +config LOG_BACKEND_ADSP_HDA_PADDING + bool "Log backend should pad the buffer with \0 characters when flushing" + help + HDA requires transfers be 128 byte aligned such that a partial message may + never make it across unless padded with \0 characters to the next 128 byte + aligned address. This may or may not work depending on the log format + being used but should certainly work with text based logging. + endif # LOG_BACKEND_ADSP_HDA config LOG_BACKEND_FS diff --git a/subsys/logging/log_backend_adsp_hda.c b/subsys/logging/log_backend_adsp_hda.c index 81599347992..007acc56a53 100644 --- a/subsys/logging/log_backend_adsp_hda.c +++ b/subsys/logging/log_backend_adsp_hda.c @@ -25,31 +25,58 @@ static uint32_t hda_log_chan; #define ALIGNMENT DMA_BUF_ALIGNMENT(DT_NODELABEL(hda_host_in)) static __aligned(ALIGNMENT) uint8_t hda_log_buf[CONFIG_LOG_BACKEND_ADSP_HDA_SIZE]; static volatile uint32_t hda_log_buffered; -static struct k_spinlock hda_log_lock; static struct k_timer hda_log_timer; static adsp_hda_log_hook_t hook; +static uint32_t write_idx; +static struct k_spinlock hda_log_lock; /* atomic bit flags for state */ #define HDA_LOG_DMA_READY 0 #define HDA_LOG_PANIC_MODE 1 static atomic_t hda_log_flags; + +/** + * Flush the buffered log to the HDA stream + * + * If @kconfig{CONFIG_LOG_BACKEND_ADSP_HDA_PADDING} is enabled + * the buffer is extended with '\0' characters to align the buffer + * to 128 bytes. + */ static uint32_t hda_log_flush(void) { + if (hda_log_buffered == 0) { + return 0; + } + uint32_t nearest128 = hda_log_buffered & ~((128) - 1); - if (nearest128 > 0) { - hda_log_buffered = hda_log_buffered - nearest128; -#if !(IS_ENABLED(CONFIG_KERNEL_COHERENCE)) - z_xtensa_cache_flush(hda_log_buf, CONFIG_LOG_BACKEND_ADSP_HDA_SIZE); -#endif - dma_reload(hda_log_dev, hda_log_chan, 0, 0, nearest128); +#ifdef CONFIG_LOG_BACKEND_ADSP_HDA_PADDING + if (nearest128 != hda_log_buffered) { + uint32_t next128 = nearest128 + 128; + uint32_t padding = next128 - hda_log_buffered; + + for (int i = 0; i < padding; i++) { + hda_log_buf[write_idx] = '\0'; + hda_log_buffered++; + write_idx++; + } + nearest128 = hda_log_buffered & ~((128) - 1); } + __ASSERT(hda_log_buffered == nearest128, + "Expected flush length to be 128 byte aligned"); +#endif + +#if !(IS_ENABLED(CONFIG_KERNEL_COHERENCE)) + z_xtensa_cache_flush(hda_log_buf, CONFIG_LOG_BACKEND_ADSP_HDA_SIZE); +#endif + dma_reload(hda_log_dev, hda_log_chan, 0, 0, nearest128); + + hda_log_buffered = hda_log_buffered - nearest128; return nearest128; } - static int hda_log_out(uint8_t *data, size_t length, void *ctx) { int ret; @@ -97,26 +124,29 @@ static int hda_log_out(uint8_t *data, size_t length, void *ctx) /* If there isn't enough space for the message there's an overflow */ if (available < length) { - ret = length; + ret = 0; goto out; } /* Copy over the message to the buffer */ - uint32_t idx = write_pos + hda_log_buffered; + write_idx = write_pos + hda_log_buffered; - if (idx > sizeof(hda_log_buf)) { - idx -= sizeof(hda_log_buf); + if (write_idx > sizeof(hda_log_buf)) { + write_idx -= sizeof(hda_log_buf); } - size_t copy_len = (idx + length) < sizeof(hda_log_buf) ? length : sizeof(hda_log_buf) - idx; + size_t copy_len = (write_idx + length) < sizeof(hda_log_buf) ? length + : sizeof(hda_log_buf) - write_idx; - memcpy(&hda_log_buf[idx], data, copy_len); + memcpy(&hda_log_buf[write_idx], data, copy_len); + write_idx += copy_len; /* There may be a wrapped copy */ size_t wrap_copy_len = length - copy_len; if (wrap_copy_len != 0) { memcpy(&hda_log_buf[0], &data[copy_len], wrap_copy_len); + write_idx = wrap_copy_len; } ret = length; @@ -133,7 +163,8 @@ out: atomic_test_bit(&hda_log_flags, HDA_LOG_PANIC_MODE)) && atomic_test_bit(&hda_log_flags, HDA_LOG_DMA_READY); - if (do_log_flush) { + /* Flush if there's a hook set AND dma is ready */ + if (do_log_flush && hook != NULL) { written = hda_log_flush(); } @@ -162,11 +193,14 @@ static void hda_log_periodic(struct k_timer *tm) { ARG_UNUSED(tm); + uint32_t written = 0; k_spinlock_key_t key = k_spin_lock(&hda_log_lock); - uint32_t written = hda_log_flush(); - k_spin_unlock(&hda_log_lock, key); + if (hook != NULL) { + written = hda_log_flush(); + } + /* The hook may have log calls and needs to be done outside of the spin * lock to avoid recursion on the spin lock (deadlocks) in cases of @@ -175,6 +209,8 @@ static void hda_log_periodic(struct k_timer *tm) if (hook != NULL && written > 0) { hook(written); } + + k_spin_unlock(&hda_log_lock, key); } static inline void dropped(const struct log_backend *const backend, @@ -283,5 +319,61 @@ void adsp_hda_log_init(adsp_hda_log_hook_t fn, uint32_t channel) K_MSEC(CONFIG_LOG_BACKEND_ADSP_HDA_FLUSH_TIME), K_MSEC(CONFIG_LOG_BACKEND_ADSP_HDA_FLUSH_TIME)); - printk("hda log initialized\n"); } + +#ifdef CONFIG_LOG_BACKEND_ADSP_HDA_CAVSTOOL + +#include +#include + +#define CHANNEL 6 +#define HOST_BUF_SIZE 8192 +#define IPC_TIMEOUT K_MSEC(1500) + +static inline void hda_ipc_msg(const struct device *dev, uint32_t data, + uint32_t ext, k_timeout_t timeout) +{ + __ASSERT(cavs_ipc_send_message_sync(dev, data, ext, timeout), + "Unexpected ipc send message failure, try increasing IPC_TIMEOUT"); +} + + +void adsp_hda_log_cavstool_hook(uint32_t written) +{ + /* We *must* send this, but we may be in a timer ISR, so we are + * forced into a retry loop without timeouts and such. + */ + bool done = false; + + /* Send IPC message notifying log data has been written */ + do { + done = cavs_ipc_send_message(CAVS_HOST_DEV, IPCCMD_HDA_PRINT, + (written << 8) | CHANNEL); + } while (!done); + + + /* Wait for confirmation log data has been received */ + do { + done = cavs_ipc_is_complete(CAVS_HOST_DEV); + } while (!done); + +} + +int adsp_hda_log_cavstool_init(const struct device *dev) +{ + ARG_UNUSED(dev); + + hda_ipc_msg(CAVS_HOST_DEV, IPCCMD_HDA_RESET, CHANNEL, IPC_TIMEOUT); + hda_ipc_msg(CAVS_HOST_DEV, IPCCMD_HDA_CONFIG, + CHANNEL | (HOST_BUF_SIZE << 8), IPC_TIMEOUT); + adsp_hda_log_init(adsp_hda_log_cavstool_hook, CHANNEL); + hda_ipc_msg(CAVS_HOST_DEV, IPCCMD_HDA_START, CHANNEL, IPC_TIMEOUT); + hda_ipc_msg(CAVS_HOST_DEV, IPCCMD_HDA_PRINT, + ((HOST_BUF_SIZE*2) << 8) | CHANNEL, IPC_TIMEOUT); + + return 0; +} + +SYS_INIT(adsp_hda_log_cavstool_init, POST_KERNEL, 99); + +#endif /* CONFIG_LOG_BACKEND_ADSP_HDA_CAVSTOOL */ diff --git a/tests/boards/intel_adsp/hda_log/prj.conf b/tests/boards/intel_adsp/hda_log/prj.conf index 6012f028f3d..2ef43bac8ad 100644 --- a/tests/boards/intel_adsp/hda_log/prj.conf +++ b/tests/boards/intel_adsp/hda_log/prj.conf @@ -3,9 +3,11 @@ CONFIG_ZTEST_NEW_API=y CONFIG_DMA=y CONFIG_ASSERT=y CONFIG_LOG=y -CONFIG_LOG_MODE_DEFERRED=y +CONFIG_LOG_MODE_IMMEDIATE=y CONFIG_LOG_BACKEND_ADSP=n CONFIG_LOG_BACKEND_ADSP_HDA=y -CONFIG_LOG_BACKEND_ADSP_HDA_SIZE=512 +CONFIG_LOG_BACKEND_ADSP_HDA_SIZE=8192 +CONFIG_LOG_BACKEND_ADSP_HDA_PADDING=y +CONFIG_LOG_BACKEND_ADSP_HDA_CAVSTOOL=y CONFIG_LOG_BACKEND_ADSP_HDA_FLUSH_TIME=100 CONFIG_XTENSA_ENABLE_BACKTRACE=n diff --git a/tests/boards/intel_adsp/hda_log/src/logger.c b/tests/boards/intel_adsp/hda_log/src/logger.c index e04a2d1b8f0..f7cb9332aa2 100644 --- a/tests/boards/intel_adsp/hda_log/src/logger.c +++ b/tests/boards/intel_adsp/hda_log/src/logger.c @@ -11,62 +11,23 @@ #include #include "tests.h" -#define CHANNEL 6 -#define HOST_BUF_SIZE 512 - #include LOG_MODULE_REGISTER(hda_test, LOG_LEVEL_DBG); -#define IPC_TIMEOUT K_MSEC(1500) - -static void hda_log_hook(uint32_t written) -{ - /* We *must* send this, but we may be in a timer ISR, so we are - * forced into a retry loop without timeouts and such. - */ - bool done = false; - - /* Now send the next one */ - do { - done = cavs_ipc_send_message(CAVS_HOST_DEV, IPCCMD_HDA_PRINT, - (written << 8) | CHANNEL); - } while (!done); - - - /* Previous message may not be done yet, wait for that */ - do { - done = cavs_ipc_is_complete(CAVS_HOST_DEV); - } while (!done); - - -} - - ZTEST(intel_adsp_hda_log, test_hda_logger) { - const struct log_backend *hda_log_backend = log_backend_get(0); + TC_PRINT("Testing hda log backend\n"); - zassert_not_null(hda_log_backend, "Expected hda log backend"); + /* Wait a moment so the output isn't mangled */ + k_msleep(100); - hda_ipc_msg(CAVS_HOST_DEV, IPCCMD_HDA_RESET, CHANNEL, IPC_TIMEOUT); - hda_ipc_msg(CAVS_HOST_DEV, IPCCMD_HDA_CONFIG, - CHANNEL | (HOST_BUF_SIZE << 8), IPC_TIMEOUT); - adsp_hda_log_init(hda_log_hook, CHANNEL); - hda_ipc_msg(CAVS_HOST_DEV, IPCCMD_HDA_START, CHANNEL, IPC_TIMEOUT); - hda_ipc_msg(CAVS_HOST_DEV, IPCCMD_HDA_PRINT, - ((HOST_BUF_SIZE*2) << 8) | CHANNEL, IPC_TIMEOUT); - - printk("Testing log backend\n"); - - for (int i = 0; i < 512; i++) { + /* Ensure multiple wraps and many many logs are written */ + for (int i = 0; i < 4096; i++) { LOG_DBG("test hda log message %d", i); } - printk("Sleeping to let the log flush\n"); - - k_sleep(K_MSEC(500)); - - printk("Done\n"); + /* Wait another moment so dma may flush */ + k_sleep(K_MSEC(100)); } ZTEST_SUITE(intel_adsp_hda_log, NULL, NULL, NULL, NULL, NULL);