logging: Intel ADSP mtrace logging backend

Implements a logging backend implementing the mtrace protocol
to relay log messages over SRAM. This protocol is implemented
by the SOF Linux driver ("mtrace" debugfs interface).

This implementation follows example of the ADSP HDA logger implemented
in commit 6913da9ddd ("logging: cAVS HDA based logger").

Cc: Tom Burdick <thomas.burdick@intel.com>
Signed-off-by: Kai Vehmanen <kai.vehmanen@linux.intel.com>

include/zephyr/logging/log_backend_adsp_mtrace.h

@@ -0,0 +1,32 @@
+/*
+ * Copyright (c) 2022 Intel Corporation
+ *
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+#ifndef ZEPHYR_LOG_BACKEND_ADSP_MTRACE_H_
+#define ZEPHYR_LOG_BACKEND_ADSP_MTRACE_H_
+
+#include <stdint.h>
+#include <stddef.h>
+
+/**
+ *@brief mtracelogger requires a hook for IPC messages
+ *
+ * When new log data is added to the SRAM buffer, a IPC message
+ * should be sent to the host. This hook function pointer allows
+ * for that.
+ */
+typedef void(*adsp_mtrace_log_hook_t)(size_t written, size_t space_left);
+
+/**
+ * @brief Initialize the Intel ADSP mtrace logger
+ *
+ * @param hook Function is called after each write to the SRAM buffer
+ *             It is up to the author of the hook to serialize if needed.
+ */
+void adsp_mtrace_log_init(adsp_mtrace_log_hook_t hook);
+
+const struct log_backend *log_backend_adsp_mtrace_get(void);
+
+#endif /* ZEPHYR_LOG_BACKEND_ADSP_MTRACE_H_ */

soc/xtensa/intel_adsp/common/include/adsp_debug_window.h

@@ -0,0 +1,67 @@
+/* Copyright (c) 2021 Intel Corporation
+ * SPDX-License-Identifier: Apache-2.0
+ */
+#ifndef _ZEPHYR_SOC_INTEL_ADSP_DEBUG_WINDOW
+#define _ZEPHYR_SOC_INTEL_ADSP_DEBUG_WINDOW
+
+/*
+ * SRAM window for debug info (window 2) is organized in slots,
+ * described in the descriptors available on page 0.
+ *
+ *	------------------------
+ *	| Page0  - descriptors |
+ *	------------------------
+ *	| Page1  - slot0       |
+ *	------------------------
+ *	| Page2  - slot1       |
+ *	------------------------
+ *	|         ...          |
+ *	------------------------
+ *	| Page14  - slot13     |
+ *	------------------------
+ *	| Page15  - slot14     |
+ *	------------------------
+ *
+ * The slot size == page size
+ *
+ * The first page contains descriptors for the remaining slots.
+ * The overall number of slots can vary based on platform.
+ *
+ * The slot descriptor is:
+ * u32 res_id;
+ * u32 type;
+ * u32 vma;
+ */
+
+#define ADSP_DW_PAGE_SIZE		0x1000
+#define ADSP_DW_SLOT_SIZE		ADSP_DW_PAGE_SIZE
+#define ADSP_DW_SLOT_COUNT		15
+
+/* debug log slot types */
+#define ADSP_DW_SLOT_UNUSED		0x00000000
+#define ADSP_DW_SLOT_CRITICAL_LOG	0x54524300
+#define ADSP_DW_SLOT_DEBUG_LOG		0x474f4c00 /* byte 0: core ID */
+#define ADSP_DW_SLOT_GDB_STUB		0x42444700
+#define ADSP_DW_SLOT_TELEMETRY		0x4c455400
+#define ADSP_DW_SLOT_BROKEN		0x44414544
+
+ /* for debug and critical types */
+#define ADSP_DW_SLOT_CORE_MASK		GENMASK(7, 0)
+#define ADSP_DW_SLOT_TYPE_MASK		GENMASK(31, 8)
+
+struct adsp_dw_desc {
+	uint32_t resource_id;
+	uint32_t type;
+	uint32_t vma;
+} __packed;
+
+struct adsp_debug_window {
+	struct adsp_dw_desc descs[ADSP_DW_SLOT_COUNT];
+	uint8_t reserved[ADSP_DW_SLOT_SIZE - ADSP_DW_SLOT_COUNT * sizeof(struct adsp_dw_desc)];
+	uint8_t slots[ADSP_DW_SLOT_COUNT][ADSP_DW_SLOT_SIZE];
+} __packed;
+
+#define ADSP_DW ((volatile struct adsp_debug_window *) \
+		 (z_soc_uncached_ptr((void *)HP_SRAM_WIN2_BASE)))
+
+#endif

subsys/logging/CMakeLists.txt

@@ -87,6 +87,11 @@ if(NOT CONFIG_LOG_MODE_MINIMAL)
     log_backend_adsp_hda.c
   )
 
+  zephyr_sources_ifdef(
+    CONFIG_LOG_BACKEND_ADSP_MTRACE
+    log_backend_adsp_mtrace.c
+  )
+
   zephyr_sources_ifdef(
     CONFIG_LOG_BACKEND_EFI_CONSOLE
     log_backend_efi_console.c

subsys/logging/Kconfig.backends

@@ -383,6 +383,22 @@ config LOG_BACKEND_ADSP_HDA_PADDING
 
 endif # LOG_BACKEND_ADSP_HDA
 
+config LOG_BACKEND_ADSP_MTRACE
+	bool "Intel ADSP mtrace backend"
+	depends on SOC_FAMILY_INTEL_ADSP
+	select LOG_OUTPUT
+	help
+	  Provide a logging backend which writes to SRAM window
+	  using the SOF Linux driver mtrace buffer layout.
+
+if LOG_BACKEND_ADSP_MTRACE
+
+backend = ADSP_MTRACE
+backend-str = adsp_mtrace
+source "subsys/logging/Kconfig.template.log_format_config"
+
+endif # LOG_BACKEND_ADSP_MTRACE
+
 config LOG_BACKEND_FS
 	bool "File system backend"
 	depends on FILE_SYSTEM

subsys/logging/log_backend_adsp_mtrace.c

@@ -0,0 +1,224 @@
+/*
+ * Copyright (c) 2019,2022 Intel Corporation
+ *
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+#include <zephyr/logging/log_backend_adsp_mtrace.h>
+#include <zephyr/logging/log_backend.h>
+#include <zephyr/logging/log_core.h>
+#include <zephyr/logging/log_output.h>
+#include <zephyr/logging/log_backend_std.h>
+#include <zephyr/zephyr.h>
+#include <soc.h>
+
+#include <adsp_memory.h>
+#include <adsp_debug_window.h>
+
+/*
+ * 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 mtrace_lock;
+
+static uint32_t log_format_current = CONFIG_LOG_BACKEND_ADSP_MTRACE_OUTPUT_DEFAULT;
+
+static adsp_mtrace_log_hook_t mtrace_hook;
+
+static bool mtrace_active;
+
+static bool mtrace_panic_mode;
+
+/*
+ * SRAM window for debug info is organized to equal size slots.
+ * The descriptors on first page describe the layout of slots.
+ * One type of debug info slot is ADSP_DBG_WIN_SLOT_DEBUG_LOG.
+ * These slots (if defined) can be used for mtrace output.
+ *
+ * The log buffer slots have the following layout:
+ *
+ * u32 host_read_ptr;
+ * u32 dsp_write_ptr;
+ * u8 buffer[];
+ *
+ * The two pointers are offsets within the buffer. Buffer is empty
+ * when the two pointers are equal, and full when host read pointer
+ * is one ahead of the DSP writer pointer.
+ */
+
+#define MTRACE_LOG_BUF_SIZE		(ADSP_DW_SLOT_SIZE - 2 * sizeof(uint32_t))
+
+#define MTRACE_LOGGING_SLOT_TYPE(n)	(ADSP_DW_SLOT_DEBUG_LOG | ((n) & ADSP_DW_SLOT_CORE_MASK))
+
+#define MTRACE_CORE		0
+
+struct adsp_debug_slot {
+	uint32_t host_ptr;
+	uint32_t dsp_ptr;
+	uint8_t data[ADSP_DW_SLOT_SIZE - sizeof(uint32_t) * 2];
+} __packed;
+
+static void mtrace_init(void)
+{
+	if (ADSP_DW->descs[0].type == MTRACE_LOGGING_SLOT_TYPE(MTRACE_CORE)) {
+		return;
+	}
+
+	ADSP_DW->descs[0].type = MTRACE_LOGGING_SLOT_TYPE(MTRACE_CORE);
+}
+
+static void mtrace_out(int8_t *str, size_t len, size_t *space_left)
+{
+	struct adsp_debug_slot *slot = (struct adsp_debug_slot *)(ADSP_DW->slots[0]);
+	uint8_t *data = slot->data;
+	uint32_t r = slot->host_ptr;
+	uint32_t w = slot->dsp_ptr;
+	size_t avail, left;
+
+	if (w > r) {
+		avail = MTRACE_LOG_BUF_SIZE - w + r - 1;
+	} else if (w == r) {
+		avail = MTRACE_LOG_BUF_SIZE - 1;
+	} else {
+		avail = r - w - 1;
+	}
+
+	if (len == 0) {
+		goto out;
+	}
+
+	/* data that does not fit is dropped */
+	left = MIN(avail, len);
+
+	if (w + left >= MTRACE_LOG_BUF_SIZE) {
+		size_t tail = MTRACE_LOG_BUF_SIZE - w;
+
+		memcpy(data + w, str, tail);
+		left -= tail;
+		memcpy(data, str + tail, left);
+		w = left;
+	} else {
+		memcpy(data + w, str, left);
+		w += left;
+	}
+
+	slot->dsp_ptr = w;
+
+out:
+	if (space_left) {
+		*space_left = avail > len ? avail - len : 0;
+	}
+}
+
+static int char_out(uint8_t *data, size_t length, void *ctx)
+{
+	size_t space_left = 0;
+	/*
+	 * we handle the data even if mtrace is active. this
+	 * ensures we can capture early boot messages.
+	 */
+	mtrace_out(data, length, &space_left);
+
+	if (mtrace_active && mtrace_hook) {
+
+		/* if we are in panic mode, need to flush out asap */
+		if (unlikely(mtrace_panic_mode))
+			space_left = 0;
+
+		mtrace_hook(length, space_left);
+	}
+
+	return length;
+}
+
+/**
+ * 80 bytes seems to catch most sensibly sized log message lines
+ * in one go letting the trace out call output whole complete
+ * lines. This avoids the overhead of a spin lock in the trace_out
+ * more often as well as avoiding entwined characters from printk if
+ * LOG_PRINTK=n.
+ */
+#define LOG_BUF_SIZE 80
+static uint8_t log_buf[LOG_BUF_SIZE];
+
+LOG_OUTPUT_DEFINE(log_output_adsp_mtrace, 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 panic(struct log_backend const *const backend)
+{
+	mtrace_panic_mode = true;
+}
+
+static void dropped(const struct log_backend *const backend,
+		    uint32_t cnt)
+{
+	log_output_dropped_process(&log_output_adsp_mtrace, cnt);
+}
+
+static void process(const struct log_backend *const backend,
+		    union log_msg_generic *msg)
+{
+	log_format_func_t log_output_func = log_format_func_t_get(log_format_current);
+
+	k_spinlock_key_t key = k_spin_lock(&mtrace_lock);
+
+	log_output_func(&log_output_adsp_mtrace, &msg->log, format_flags());
+
+	k_spin_unlock(&mtrace_lock, key);
+}
+
+static int format_set(const struct log_backend *const backend, uint32_t log_type)
+{
+	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 init(const struct log_backend *const backend)
+{
+	ARG_UNUSED(backend);
+
+	mtrace_init();
+}
+
+const struct log_backend_api log_backend_adsp_mtrace_api = {
+	.process = process,
+	.dropped = IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE) ? NULL : dropped,
+	.panic = panic,
+	.format_set = format_set,
+	.init = init,
+};
+
+LOG_BACKEND_DEFINE(log_backend_adsp_mtrace, log_backend_adsp_mtrace_api, true);
+
+void adsp_mtrace_log_init(adsp_mtrace_log_hook_t hook)
+{
+	mtrace_init();
+
+	mtrace_hook = hook;
+	mtrace_active = true;
+}
+
+const struct log_backend *log_backend_adsp_mtrace_get(void)
+{
+	return &log_backend_adsp_mtrace;
+}