trace: move CONFIG_TRACEM implementation up a couple levels

From deep down trace.c:va_tracelog() up to the _log_message() level.

Also rename va_tracelog() to the more specific dma_tracelog()

Preparation to support the DMA trace in Zephyr.

The only functional change in this commit is that DMA messages copied to
the shared memory are not de-duplicated any more (a.k.a "adaptive rate
limiting" or CONFIG_TRACE_FILTERING_ADAPTIVE). These are generally
supposed to be high level hence rare enough; otherwise there is probably
a "bigger problem".

Signed-off-by: Marc Herbert <marc.herbert@intel.com>

Author: marc-hb

src/include/sof/trace/trace.h

@@ -97,6 +97,9 @@ struct trace_filter {
 
 #if CONFIG_TRACE
 
+#include <stdarg.h>
+#include <user/trace.h> /* LOG_LEVEL_... */
+
 /*
  * trace_event macro definition
  *
@@ -144,10 +147,13 @@ void trace_off(void);
 void trace_init(struct sof *sof);
 
 /* All tracing macros in this file end up calling these functions in the end. */
+typedef void (*log_func_t)(bool send_atomic, const void *log_entry, const struct tr_ctx *ctx,
+			   uint32_t lvl, uint32_t id_1, uint32_t id_2, int arg_count, va_list args);
+
 void trace_log_filtered(bool send_atomic, const void *log_entry, const struct tr_ctx *ctx,
-			uint32_t lvl, uint32_t id_1, uint32_t id_2, int arg_count, ...);
+			uint32_t lvl, uint32_t id_1, uint32_t id_2, int arg_count, va_list args);
 void trace_log_unfiltered(bool send_atomic, const void *log_entry, const struct tr_ctx *ctx,
-			  uint32_t lvl, uint32_t id_1, uint32_t id_2, int arg_count, ...);
+			  uint32_t lvl, uint32_t id_1, uint32_t id_2, int arg_count, va_list args);
 struct sof_ipc_trace_filter_elem *trace_filter_fill(struct sof_ipc_trace_filter_elem *elem,
 						    struct sof_ipc_trace_filter_elem *end,
 						    struct trace_filter *filter);
@@ -198,6 +204,17 @@ void mtrace_event(const char *complete_packet, uint32_t length);
 		format						\
 	}
 
+#ifdef CONFIG_TRACEM /* Send everything to shared memory too */
+#  define MTRACE_DUPLICATION_LEVEL LOG_LEVEL_DEBUG
+#else /* copy only ERRORS */
+#  define MTRACE_DUPLICATION_LEVEL LOG_LEVEL_ERROR
+#endif /* CONFIG_TRACEM */
+
+/* This function is _not_ passed the format string to save space */
+void _log_sofdict(log_func_t sofdict_logf, bool atomic, const void *log_entry,
+		  const struct tr_ctx *ctx, const uint32_t lvl,
+		  uint32_t id_1, uint32_t id_2, int arg_count, ...);
+
 /* _log_message() */
 
 #ifdef CONFIG_LIBRARY
@@ -237,7 +254,8 @@ _thrown_from_macro_BASE_LOG_in_trace_h
 
 /** _log_message is where the memory-saving dictionary magic described
  * above happens: the "format" string argument is moved to a special
- * linker section and replaced by a &log_entry pointer to it.
+ * linker section and replaced by a &log_entry pointer to it. This must
+ * be a macro for the source location to be meaningful.
  */
 #define _log_message(log_func, atomic, lvl, comp_class, ctx, id_1, id_2, format, ...)	\
 do {											\
@@ -248,8 +266,8 @@ do {											\
 			META_COUNT_VARAGS_BEFORE_COMPILE(__VA_ARGS__),			\
 		BASE_LOG_ASSERT_FAIL_MSG						\
 	);										\
-	log_func(atomic, &log_entry, ctx, lvl, id_1, id_2,				\
-		 META_COUNT_VARAGS_BEFORE_COMPILE(__VA_ARGS__), ##__VA_ARGS__);		\
+	_log_sofdict(log_func, atomic, &log_entry, ctx, lvl, id_1, id_2, \
+		     META_COUNT_VARAGS_BEFORE_COMPILE(__VA_ARGS__), ##__VA_ARGS__); \
 } while (0)
 
 #endif /* CONFIG_LIBRARY */

src/trace/trace.c

@@ -222,21 +222,15 @@ static bool trace_filter_flood(uint32_t log_level, uint32_t entry, uint64_t mess
 
 /** Implementation shared and invoked by both adaptive filtering and
  * not. Serializes events into trace messages and passes them to
- * dtrace_event() or to mtrace_event() or to both depending on the log
- * lvl and the Kconfiguration.
+ * dtrace_event()
  */
-static void vatrace_log(bool send_atomic, uint32_t log_entry, const struct tr_ctx *ctx,
-			uint32_t lvl, uint32_t id_1, uint32_t id_2, int arg_count, va_list vargs)
+static void dma_trace_log(bool send_atomic, uint32_t log_entry, const struct tr_ctx *ctx,
+			  uint32_t lvl, uint32_t id_1, uint32_t id_2, int arg_count, va_list vargs)
 {
 	uint32_t data[MESSAGE_SIZE_DWORDS(_TRACE_EVENT_MAX_ARGUMENT_COUNT)];
 	const int message_size = MESSAGE_SIZE(arg_count);
 	int i;
 
-#if CONFIG_TRACEM
-	unsigned long flags;
-	struct trace *trace = trace_get();
-#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_safe_get_time(timer_get()));
@@ -250,42 +244,25 @@ static void vatrace_log(bool send_atomic, uint32_t log_entry, const struct tr_ct
 	else
 		dtrace_event((const char *)data, message_size);
 
-#if CONFIG_TRACEM
-	/* send event by mail box too. */
-	if (send_atomic) {
-		mtrace_event((const char *)data, MESSAGE_SIZE(arg_count));
-	} else {
-		spin_lock_irq(&trace->lock, flags);
-		mtrace_event((const char *)data, MESSAGE_SIZE(arg_count));
-		spin_unlock_irq(&trace->lock, flags);
-	}
-#else
-	/* send event by mail box if level is LOG_LEVEL_CRITICAL. */
-	if (lvl == LOG_LEVEL_CRITICAL)
-		mtrace_event((const char *)data, MESSAGE_SIZE(arg_count));
-#endif /* CONFIG_TRACEM */
 }
 
 void trace_log_unfiltered(bool send_atomic, const void *log_entry, const struct tr_ctx *ctx,
-			  uint32_t lvl, uint32_t id_1, uint32_t id_2, int arg_count, ...)
+			  uint32_t lvl, uint32_t id_1, uint32_t id_2, int arg_count, va_list vl)
 {
 	struct trace *trace = trace_get();
-	va_list vl;
 
 	if (!trace->enable) {
 		return;
 	}
 
-	va_start(vl, arg_count);
-	vatrace_log(send_atomic, (uint32_t)log_entry, ctx, lvl, id_1, id_2, arg_count, vl);
-	va_end(vl);
+	dma_trace_log(send_atomic, (uint32_t)log_entry, ctx, lvl, id_1, id_2, arg_count, vl);
 }
 
 void trace_log_filtered(bool send_atomic, const void *log_entry, const struct tr_ctx *ctx,
-			uint32_t lvl, uint32_t id_1, uint32_t id_2, int arg_count, ...)
+			uint32_t lvl, uint32_t id_1, uint32_t id_2, int arg_count, va_list vl)
 {
 	struct trace *trace = trace_get();
-	va_list vl;
+
 #if CONFIG_TRACE_FILTERING_ADAPTIVE
 	uint64_t current_ts;
 #endif /* CONFIG_TRACE_FILTERING_ADAPTIVE */
@@ -310,9 +287,7 @@ void trace_log_filtered(bool send_atomic, const void *log_entry, const struct tr
 	}
 #endif /* CONFIG_TRACE_FILTERING_ADAPTIVE */
 
-	va_start(vl, arg_count);
-	vatrace_log(send_atomic, (uint32_t)log_entry, ctx, lvl, id_1, id_2, arg_count, vl);
-	va_end(vl);
+	dma_trace_log(send_atomic, (uint32_t)log_entry, ctx, lvl, id_1, id_2, arg_count, vl);
 }
 
 struct sof_ipc_trace_filter_elem *trace_filter_fill(struct sof_ipc_trace_filter_elem *elem,
@@ -532,9 +507,9 @@ void trace_init(struct sof *sof)
 	dma_trace_init_early(sof);
 }
 
-void mtrace_dict_entry(bool atomic_context, uint32_t dict_entry_address, int n_args, ...)
+static void mtrace_dict_entry_vl(bool atomic_context, uint32_t dict_entry_address,
+				 int n_args, va_list ap)
 {
-	va_list ap;
 	int i;
 	char packet[MESSAGE_SIZE(_TRACE_EVENT_MAX_ARGUMENT_COUNT)];
 	uint32_t *args = (uint32_t *)&packet[MESSAGE_SIZE(0)];
@@ -543,10 +518,8 @@ void mtrace_dict_entry(bool atomic_context, uint32_t dict_entry_address, int n_a
 	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 < MIN(n_args, _TRACE_EVENT_MAX_ARGUMENT_COUNT); i++)
 		args[i] = va_arg(ap, uint32_t);
-	va_end(ap);
 
 	if (atomic_context) {
 		mtrace_event(packet, MESSAGE_SIZE(n_args));
@@ -559,3 +532,28 @@ void mtrace_dict_entry(bool atomic_context, uint32_t dict_entry_address, int n_a
 		spin_unlock_irq(&trace->lock, saved_flags);
 	}
 }
+
+void mtrace_dict_entry(bool atomic_context, uint32_t dict_entry_address, int n_args, ...)
+{
+	va_list ap;
+
+	va_start(ap, n_args);
+	mtrace_dict_entry_vl(atomic_context, dict_entry_address, n_args, ap);
+	va_end(ap);
+}
+
+void _log_sofdict(log_func_t sofdict_logf, bool atomic, const void *log_entry,
+		  const struct tr_ctx *ctx, const uint32_t lvl,
+		  uint32_t id_1, uint32_t id_2, int arg_count, ...)
+{
+	va_list ap;
+
+	if (lvl <= MTRACE_DUPLICATION_LEVEL) {
+		va_start(ap, arg_count);
+		mtrace_dict_entry_vl(atomic, (uint32_t)log_entry, arg_count, ap);
+		va_end(ap);
+	}
+	va_start(ap, arg_count);
+	sofdict_logf(atomic, log_entry, ctx, lvl, id_1, id_2, arg_count, ap);
+	va_end(ap);
+}

test/cmocka/src/common_mocks.c

@@ -102,7 +102,8 @@ void WEAK __panic(uint32_t p, char *filename, uint32_t linenum)
 
 #if CONFIG_TRACE
 void WEAK trace_log_filtered(bool send_atomic, const void *log_entry, const struct tr_ctx *ctx,
-			     uint32_t lvl, uint32_t id_1, uint32_t id_2, int arg_count, ...)
+			     uint32_t lvl, uint32_t id_1, uint32_t id_2, int arg_count,
+			     va_list args)
 {
 	(void) send_atomic;
 	(void) log_entry;
@@ -111,6 +112,13 @@ void WEAK trace_log_filtered(bool send_atomic, const void *log_entry, const stru
 	(void) id_1;
 	(void) id_2;
 	(void) arg_count;
+	(void) args;
+}
+
+void WEAK _log_sofdict(log_func_t sofdict_logf, bool atomic, const void *log_entry,
+		       const struct tr_ctx *ctx, const uint32_t lvl,
+		       uint32_t id_1, uint32_t id_2, int arg_count, ...)
+{
 }
 
 void WEAK trace_flush_dma_to_mbox(void)