Add new mtrace_printf() and use it for DMA init error handling and demoting banner to INFO level

scripts/checkpatch.pl

@@ -4129,6 +4129,8 @@ sub process {
 			     "LINUX_VERSION_CODE should be avoided, code should be for the version to which it is merged\n" . $herecurr);
 		}
 
+		if(!$SOF) {
+
 # check for uses of printk_ratelimit
 		if ($line =~ /\bprintk_ratelimit\s*\(/) {
 			WARN("PRINTK_RATELIMITED",
@@ -4169,6 +4171,8 @@ sub process {
 			     "Prefer dev_$level(... to dev_printk(KERN_$orig, ...\n" . $herecurr);
 		}
 
+		} # !$SOF
+
 # ENOSYS means "bad syscall nr" and nothing else.  This will have a small
 # number of false positives, but assembly files are not checked, so at
 # least the arch entry code will not trigger this warning.

src/include/sof/drivers/timer.h

@@ -62,6 +62,17 @@ int64_t platform_timer_set(struct timer *timer, uint64_t ticks);
 void platform_timer_clear(struct timer *timer);
 uint64_t platform_timer_get(struct timer *timer);
 uint64_t platform_timer_get_atomic(struct timer *timer);
+
+static inline uint64_t platform_safe_get_time(struct timer *timer)
+{
+	/* Default to something small but at least 1.0 microsecond so it
+	 * does not look like an uninitialized zero; not even when the
+	 * user does not request any microseconds decimals. See
+	 * DEFAULT_CLOCK constant in logger.c
+	 */
+	return timer ? platform_timer_get(timer) : 50;
+}
+
 void platform_timer_start(struct timer *timer);
 void platform_timer_stop(struct timer *timer);
 

src/include/sof/trace/trace.h

@@ -413,4 +413,31 @@ struct tr_ctx {
 				     _TRACE_INV_ID, _TRACE_INV_ID, \
 				     fmt, ##__VA_ARGS__)
 
+/** Direct, low-level access to mbox / shared memory logging when DMA
+ * tracing is either not initialized yet or disabled or found broken for
+ * any reason.
+ * To keep it simpler than and with minimal dependencies on
+ * the huge number of lines above, this does not check arguments at compile
+ * time.
+ * There is neither log level filtering, throttling or any other
+ * advanced feature.
+ */
+#define mtrace_printf(log_level, format_str, ...)			\
+	do {								\
+		STATIC_ASSERT(META_COUNT_VARAGS_BEFORE_COMPILE(__VA_ARGS__)  \
+			      <= _TRACE_EVENT_MAX_ARGUMENT_COUNT,	\
+			      too_many_mtrace_printf_arguments);	\
+		_DECLARE_LOG_ENTRY(log_level, format_str, _TRACE_INV_CLASS, \
+				   META_COUNT_VARAGS_BEFORE_COMPILE(__VA_ARGS__)); \
+		mtrace_dict_entry((uint32_t)&log_entry,			\
+				  META_COUNT_VARAGS_BEFORE_COMPILE(__VA_ARGS__), \
+				  ##__VA_ARGS__);			\
+	} while (0)
+
+/** Adds log_header prefix and appends  arguments before sending */
+void mtrace_dict_entry(uint32_t log_entry_pointer, int n_args, ...);
+
+/** Posts a fully prepared log header + log entry */
+void mtrace_event(const char *complete_packet, uint32_t length);
+
 #endif /* __SOF_TRACE_TRACE_H__ */

src/ipc/ipc3/handler.c

@@ -742,6 +742,12 @@ static int ipc_dma_trace_config(uint32_t header)
 	struct timer *timer = timer_get();
 	int err;
 
+	if (!dmat) {
+		mtrace_printf(LOG_LEVEL_ERROR,
+			      "ipc_dma_trace_config failed: dmat not initialized");
+		return -ENOMEM;
+	}
+
 	/* copy message with ABI safe method */
 	IPC_COPY_CMD(params, ipc->comp_data);
 

src/trace/dma-trace.c

@@ -126,17 +126,42 @@ static enum task_state trace_work(void *data)
  */
 int dma_trace_init_early(struct sof *sof)
 {
+	int ret;
+
+	/* If this assert is wrong then traces have been corrupting
+	 * random parts of memory. Some functions run before _and_ after
+	 * DMA trace initialization and we don't want to ask them to
+	 * never trace. So dma_trace_initialized() must be either
+	 * clearly false/NULL or clearly true, we can't tolerate random
+	 * uninitialized values in sof->dmat etc.
+	 */
+	assert(!dma_trace_initialized(sof->dmat));
+
 	sof->dmat = rzalloc(SOF_MEM_ZONE_SYS_SHARED, 0, SOF_MEM_CAPS_RAM, sizeof(*sof->dmat));
+
 	dma_sg_init(&sof->dmat->config.elem_array);
 	spinlock_init(&sof->dmat->lock);
 
 	ipc_build_trace_posn(&sof->dmat->posn);
 	sof->dmat->msg = ipc_msg_init(sof->dmat->posn.rhdr.hdr.cmd,
 				      sizeof(sof->dmat->posn));
-	if (!sof->dmat->msg)
-		return -ENOMEM;
+	if (!sof->dmat->msg) {
+		ret = -ENOMEM;
+		goto err;
+	}
 
 	return 0;
+
+err:
+	mtrace_printf(LOG_LEVEL_ERROR,
+		      "dma_trace_init_early() failed: %d", ret);
+
+	/* Cannot rfree(sof->dmat) from the system memory pool, see
+	 * comments in lib/alloc.c
+	 */
+	sof->dmat = NULL;
+
+	return ret;
 }
 
 /** Run after dma_trace_init_early() and before dma_trace_enable() */
@@ -146,18 +171,26 @@ int dma_trace_init_complete(struct dma_trace_data *d)
 
 	tr_info(&dt_tr, "dma_trace_init_complete()");
 
+	if (!d) {
+		mtrace_printf(LOG_LEVEL_ERROR,
+			      "dma_trace_init_complete(): failed, no dma_trace_data");
+		return -ENOMEM;
+	}
+
 	/* init DMA copy context */
 	ret = dma_copy_new(&d->dc);
 	if (ret < 0) {
-		tr_err(&dt_tr, "dma_trace_init_complete(): dma_copy_new() failed");
+		mtrace_printf(LOG_LEVEL_ERROR,
+			      "dma_trace_init_complete(): dma_copy_new() failed: %d", ret);
 		goto out;
 	}
 
 	ret = dma_get_attribute(d->dc.dmac, DMA_ATTR_COPY_ALIGNMENT,
 				&d->dma_copy_align);
 
 	if (ret < 0) {
-		tr_err(&dt_tr, "dma_trace_init_complete(): dma_get_attribute()");
+		mtrace_printf(LOG_LEVEL_ERROR,
+			      "dma_trace_init_complete(): dma_get_attribute() failed: %d", ret);
 
 		goto out;
 	}
@@ -331,16 +364,23 @@ int dma_trace_enable(struct dma_trace_data *d)
 
 	/* initialize dma trace buffer */
 	err = dma_trace_buffer_init(d);
-	if (err < 0)
+
+	if (err < 0) {
+		mtrace_printf(LOG_LEVEL_ERROR, "dma_trace_enable: buffer_init failed");
 		goto out;
+	}
 
-	/*
-	 * It should be the very first sent log for easily identification.
-	 * Use tr_err to have this initial message also in error logs and assert
-	 * traces works well.
-	 */
-	tr_err(&dt_tr, "FW ABI 0x%x DBG ABI 0x%x tag " SOF_GIT_TAG " src hash 0x%08x (ldc hash " META_QUOTE(SOF_SRC_HASH) ")",
-	       SOF_ABI_VERSION, SOF_ABI_DBG_VERSION, SOF_SRC_HASH);
+	/* It should be the very first sent log for easy identification. */
+	mtrace_printf(LOG_LEVEL_INFO,
+		      "SHM: FW ABI 0x%x DBG ABI 0x%x tag " SOF_GIT_TAG " src hash 0x%08x (ldc hash "
+		      META_QUOTE(SOF_SRC_HASH) ")",
+		      SOF_ABI_VERSION, SOF_ABI_DBG_VERSION, SOF_SRC_HASH);
+
+	/* Use a different, DMA: prefix to ease identification of log files */
+	tr_info(&dt_tr,
+		"DMA: FW ABI 0x%x DBG ABI 0x%x tag " SOF_GIT_TAG " src hash 0x%08x (ldc hash "
+		META_QUOTE(SOF_SRC_HASH) ")",
+		SOF_ABI_VERSION, SOF_ABI_DBG_VERSION, SOF_SRC_HASH);
 
 #if CONFIG_DMA_GW
 	/*

src/trace/trace.c

@@ -70,7 +70,7 @@ struct trace {
 
 #define TRACE_ID_MASK ((1 << TRACE_ID_LENGTH) - 1)
 
-static void put_header(uint32_t *dst, const struct sof_uuid_entry *uid,
+static void put_header(void *dst, const struct sof_uuid_entry *uid,
 		       uint32_t id_1, uint32_t id_2,
 		       uint32_t entry, uint64_t timestamp)
 {
@@ -93,7 +93,7 @@ static void put_header(uint32_t *dst, const struct sof_uuid_entry *uid,
 }
 
 /** Ring buffer for the mailbox trace */
-static inline void mtrace_event(const char *data, uint32_t length)
+void mtrace_event(const char *data, uint32_t length)
 {
 	struct trace *trace = trace_get();
 	char *t = (char *)MAILBOX_TRACE_BASE;
@@ -105,7 +105,7 @@ static inline void mtrace_event(const char *data, uint32_t length)
 		trace->pos = 0;
 	}
 
-	memcpy_s(t + trace->pos, MAILBOX_TRACE_SIZE,
+	memcpy_s(t + trace->pos, MAILBOX_TRACE_SIZE - trace->pos,
 		 data, length);
 	dcache_writeback_region(t + trace->pos, length);
 	trace->pos += length;
@@ -238,7 +238,8 @@ static void vatrace_log(bool send_atomic, uint32_t log_entry, const struct tr_ct
 #endif /* CONFIG TRACEM */
 
 	/* fill log content. arg_count is in the dictionary. */
-	put_header(data, ctx->uuid_p, id_1, id_2, log_entry, platform_timer_get(timer_get()));
+	put_header(data, ctx->uuid_p, id_1, id_2, log_entry,
+		   platform_safe_get_time(timer_get()));
 
 	for (i = 0; i < arg_count; ++i)
 		data[PAYLOAD_OFFSET(i)] = va_arg(vargs, uint32_t);
@@ -300,7 +301,7 @@ void trace_log_filtered(bool send_atomic, const void *log_entry, const struct tr
 
 #if CONFIG_TRACE_FILTERING_ADAPTIVE
 	if (!trace->user_filter_override) {
-		current_ts = platform_timer_get(timer_get());
+		current_ts = platform_safe_get_time(timer_get());
 
 		emit_recent_entries(current_ts);
 
@@ -524,3 +525,22 @@ void trace_init(struct sof *sof)
 
 	dma_trace_init_early(sof);
 }
+
+void mtrace_dict_entry(uint32_t dict_entry_address, int n_args, ...)
+{
+	va_list ap;
+	int i;
+	char packet[MESSAGE_SIZE(_TRACE_EVENT_MAX_ARGUMENT_COUNT)];
+	uint32_t *args = (uint32_t *)&packet[MESSAGE_SIZE(0)];
+	const uint64_t tstamp = platform_safe_get_time(timer_get());
+
+	put_header(packet, dt_tr.uuid_p, _TRACE_INV_ID, _TRACE_INV_ID,
+		   dict_entry_address, tstamp);
+
+	va_start(ap, n_args);
+	for (i = 0; i < n_args; i++)
+		args[i] = va_arg(ap, uint32_t);
+	va_end(ap);
+
+	mtrace_event(packet, MESSAGE_SIZE(n_args));
+}

zephyr/include/sof/trace/trace.h

@@ -25,18 +25,26 @@ struct timer;
 uint64_t platform_timer_get(struct timer *timer);
 
 /*
- * Use SOF macros, but let Zephyr take care of the physical log IO.
+ * Override SOF dictionary macros for now and let Zephyr take care of
+ * the physical log IO.
  */
 #undef _log_message
+#undef mtrace_printf
 
 #if USE_PRINTK
+#define mtrace_printf(level, format, ...)				\
+	do {								        \
+		if ((level) <= SOF_ZEPHYR_TRACE_LEVEL)                          \
+			printk("%llu: " format "\n", platform_timer_get(NULL),	\
+				##__VA_ARGS__);					\
+	} while (0)
 #define _log_message(log_func, atomic, level, comp_class, ctx, id1, id2, format, ...)	\
 	do {								        \
 		if ((level) <= SOF_ZEPHYR_TRACE_LEVEL)                          \
 			printk("%llu: " format "\n", platform_timer_get(NULL),	\
 				##__VA_ARGS__);					\
 	} while (0)
-#else
+#else /* not tested */
 #define _log_message(log_func, atomic, level, comp_class, ctx, id1, id2, format, ...)	\
 	do {								        \
 		Z_LOG(level, "%u: " format, (uint32_t)platform_timer_get(NULL),	\