trace: avoid passing va_list

Passing va_list seems to result in issues with stopping
the DMA. Call log_func() and mtrace_dict_entry() in the
_log_message() macro instead to prevent this.

Signed-off-by: Ranjani Sridharan <ranjani.sridharan@linux.intel.com>

Author: ranj063

src/include/sof/trace/trace.h

@@ -147,13 +147,10 @@ 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, va_list args);
+			uint32_t lvl, uint32_t id_1, uint32_t id_2, int arg_count, ...);
 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, va_list args);
+			  uint32_t lvl, uint32_t id_1, uint32_t id_2, int arg_count, ...);
 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);
@@ -217,11 +214,6 @@ void mtrace_event(const char *complete_packet, uint32_t length);
 #  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
@@ -264,6 +256,26 @@ _thrown_from_macro_BASE_LOG_in_trace_h
  * linker section and replaced by a &log_entry pointer to it. This must
  * be a macro for the source location to be meaningful.
  */
+#ifndef __ZEPHYR__
+#define _log_message(log_func, atomic, lvl, comp_class, ctx, id_1, id_2, format, ...)	\
+do {											\
+	_DECLARE_LOG_ENTRY(lvl, format, comp_class,					\
+			   META_COUNT_VARAGS_BEFORE_COMPILE(__VA_ARGS__));		\
+	STATIC_ASSERT_ARG_SIZE(__VA_ARGS__);						\
+	STATIC_ASSERT(_TRACE_EVENT_MAX_ARGUMENT_COUNT >=				\
+			META_COUNT_VARAGS_BEFORE_COMPILE(__VA_ARGS__),			\
+		BASE_LOG_ASSERT_FAIL_MSG						\
+	);										\
+	(lvl <= MTRACE_DUPLICATION_LEVEL ? \
+		mtrace_dict_entry(true, (uint32_t)&log_entry, \
+				  META_COUNT_VARAGS_BEFORE_COMPILE(__VA_ARGS__), \
+				  ##__VA_ARGS__) : 0); \
+	log_func(atomic, &log_entry, ctx, lvl, id_1, id_2, \
+		     META_COUNT_VARAGS_BEFORE_COMPILE(__VA_ARGS__), ##__VA_ARGS__); \
+	_log_nodict(atomic, META_COUNT_VARAGS_BEFORE_COMPILE(__VA_ARGS__), \
+		    lvl, format, ##__VA_ARGS__);			\
+} while (0)
+#else
 #define _log_message(log_func, atomic, lvl, comp_class, ctx, id_1, id_2, format, ...)	\
 do {											\
 	_DECLARE_LOG_ENTRY(lvl, format, comp_class,					\
@@ -273,11 +285,12 @@ do {											\
 			META_COUNT_VARAGS_BEFORE_COMPILE(__VA_ARGS__),			\
 		BASE_LOG_ASSERT_FAIL_MSG						\
 	);										\
-	_log_sofdict(log_func, atomic, &log_entry, ctx, lvl, id_1, id_2, \
+	log_func(atomic, &log_entry, ctx, lvl, id_1, id_2, \
 		     META_COUNT_VARAGS_BEFORE_COMPILE(__VA_ARGS__), ##__VA_ARGS__); \
 	_log_nodict(atomic, META_COUNT_VARAGS_BEFORE_COMPILE(__VA_ARGS__), \
 		    lvl, format, ##__VA_ARGS__);			\
 } while (0)
+#endif
 
 #ifdef __ZEPHYR__
 /* Just like XTOS, only the most urgent messages go to limited

src/trace/trace.c

@@ -249,21 +249,25 @@ static void dma_trace_log(bool send_atomic, uint32_t log_entry, const struct tr_
 }
 
 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, va_list vl)
+			  uint32_t lvl, uint32_t id_1, uint32_t id_2, int arg_count, ...)
 {
 	struct trace *trace = trace_get();
+	va_list vl;
 
 	if (!trace->enable) {
 		return;
 	}
 
+	va_start(vl, arg_count);
 	dma_trace_log(send_atomic, (uint32_t)log_entry, ctx, lvl, id_1, id_2, arg_count, vl);
+	va_end(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, va_list vl)
+			uint32_t lvl, uint32_t id_1, uint32_t id_2, int arg_count, ...)
 {
 	struct trace *trace = trace_get();
+	va_list vl;
 
 #if CONFIG_TRACE_FILTERING_ADAPTIVE
 	uint64_t current_ts;
@@ -289,7 +293,9 @@ void trace_log_filtered(bool send_atomic, const void *log_entry, const struct tr
 	}
 #endif /* CONFIG_TRACE_FILTERING_ADAPTIVE */
 
+	va_start(vl, arg_count);
 	dma_trace_log(send_atomic, (uint32_t)log_entry, ctx, lvl, id_1, id_2, arg_count, vl);
+	va_end(vl);
 }
 
 struct sof_ipc_trace_filter_elem *trace_filter_fill(struct sof_ipc_trace_filter_elem *elem,
@@ -509,9 +515,9 @@ void trace_init(struct sof *sof)
 	dma_trace_init_early(sof);
 }
 
-static void mtrace_dict_entry_vl(bool atomic_context, uint32_t dict_entry_address,
-				 int n_args, va_list ap)
+void mtrace_dict_entry(bool atomic_context, 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)];
@@ -520,8 +526,10 @@ static void mtrace_dict_entry_vl(bool atomic_context, uint32_t dict_entry_addres
 	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));
@@ -534,31 +542,3 @@ static void mtrace_dict_entry_vl(bool atomic_context, uint32_t dict_entry_addres
 		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;
-
-#ifndef __ZEPHYR__ /* for Zephyr see _log_nodict() in trace.h */
-	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);
-	}
-#endif
-
-	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,8 +102,7 @@ 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,
-			     va_list args)
+			     uint32_t lvl, uint32_t id_1, uint32_t id_2, int arg_count, ...)
 {
 	(void) send_atomic;
 	(void) log_entry;
@@ -112,13 +111,6 @@ 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)