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 <thomas.burdick@intel.com>

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")
+        read_lens = [buf_len, 0]
-        log.info(f"DSP LOG MSG (idx: {pos}, len: {buf_len}): {buf_data}")
+        if pos + buf_len >= hda_str.buf_len*2:
-        pos = hda_str.mem.tell()
+            read_lens[0] = hda_str.buf_len*2 - pos
-        if pos >= hda_str.buf_len*2:
+            read_lens[1] = buf_len - read_lens[0]
-            log.info(f"Wrapping log reader, pos {pos} len {hda_str.buf_len}")
+        # 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)
 

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

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) {
+#ifdef CONFIG_LOG_BACKEND_ADSP_HDA_PADDING
-		hda_log_buffered = hda_log_buffered - nearest128;
+	if (nearest128 != hda_log_buffered) {
-#if !(IS_ENABLED(CONFIG_KERNEL_COHERENCE))
+		uint32_t next128 = nearest128 + 128;
-		z_xtensa_cache_flush(hda_log_buf, CONFIG_LOG_BACKEND_ADSP_HDA_SIZE);
+		uint32_t padding = next128 - hda_log_buffered;
-#endif
+
-		dma_reload(hda_log_dev, hda_log_chan, 0, 0, nearest128);
+		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)) {
+	if (write_idx > sizeof(hda_log_buf)) {
-		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 <cavs_ipc.h>
+#include <cavstool.h>
+
+#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 */

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

tests/boards/intel_adsp/hda_log/src/logger.c

@@ -11,62 +11,23 @@
 #include <cavs_ipc.h>
 #include "tests.h"
 
-#define CHANNEL 6
-#define HOST_BUF_SIZE 512
-
 #include <zephyr/logging/log.h>
 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);
+	/* Ensure multiple wraps and many many logs are written */
-	hda_ipc_msg(CAVS_HOST_DEV, IPCCMD_HDA_CONFIG,
+	for (int i = 0; i < 4096; i++) {
-		    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++) {
 		LOG_DBG("test hda log message %d", i);
 	}
 
-	printk("Sleeping to let the log flush\n");
+	/* Wait another moment so dma may flush */
-
+	k_sleep(K_MSEC(100));
-	k_sleep(K_MSEC(500));
-
-	printk("Done\n");
 }
 
 ZTEST_SUITE(intel_adsp_hda_log, NULL, NULL, NULL, NULL, NULL);