Tracing fixes

src/debug/panic.c

@@ -81,9 +81,8 @@ void panic_dump(uint32_t p, struct sof_ipc_panic_info *panic_info,
 	count = MAILBOX_EXCEPTION_SIZE -
 		(size_t)(ext_offset - (char *)mailbox_get_exception_base());
 
-	/* flush last trace messages */
 #if CONFIG_TRACE
-	trace_flush();
+	trace_flush_dma_to_mbox();
 #endif
 
 	/* dump stack frames */

src/include/sof/trace/dma-trace.h

@@ -52,13 +52,18 @@ int dma_trace_host_buffer(struct dma_trace_data *d,
 			  struct dma_sg_elem_array *elem_array,
 			  uint32_t host_size);
 int dma_trace_enable(struct dma_trace_data *d);
-void dma_trace_flush(void *t);
+void dma_trace_flush(void *destination);
 void dma_trace_on(void);
 void dma_trace_off(void);
 
 void dtrace_event(const char *e, uint32_t size);
 void dtrace_event_atomic(const char *e, uint32_t length);
 
+static inline bool dma_trace_initialized(const struct dma_trace_data *d)
+{
+	return d && d->dmatb.addr;
+}
+
 static inline struct dma_trace_data *dma_trace_data_get(void)
 {
 	return sof_get()->dmat;

src/include/sof/trace/trace.h

@@ -137,7 +137,7 @@ struct trace_filter {
 				     ctx, id_1, id_2,			\
 				     format, ##__VA_ARGS__)
 
-void trace_flush(void);
+void trace_flush_dma_to_mbox(void);
 void trace_on(void);
 void trace_off(void);
 void trace_init(struct sof *sof);
@@ -161,7 +161,7 @@ int trace_filter_update(const struct trace_filter *elem);
 /** The start of this linker output MUST match the 'ldc_entry_header'
  *  struct defined in the logger program running in user space.
  */
-#define _DECLARE_LOG_ENTRY(lvl, format, comp_class, params)	\
+#define _DECLARE_LOG_ENTRY(lvl, format, comp_class, n_params)	\
 	__section(".static_log." #lvl)				\
 	static const struct {					\
 		uint32_t level;					\
@@ -175,7 +175,7 @@ int trace_filter_update(const struct trace_filter *elem);
 	} log_entry = {						\
 		lvl,						\
 		comp_class,					\
-		params,						\
+		n_params,						\
 		__LINE__,					\
 		sizeof(RELATIVE_FILE),				\
 		sizeof(format),					\
@@ -253,7 +253,7 @@ do {											\
 
 #define trace_point(x)  do {} while (0)
 
-static inline void trace_flush(void) { }
+static inline void trace_flush_dma_to_mbox(void) { }
 static inline void trace_on(void) { }
 static inline void trace_off(void) { }
 static inline void trace_init(struct sof *sof) { }
@@ -306,9 +306,13 @@ static inline int trace_filter_update(const struct trace_filter *filter)
 
 #endif /* CONFIG_TRACEE, CONFIG_TRACE */
 
+/** Default value when there is no specific pipeline, dev, dai, etc. */
+#define _TRACE_INV_ID		-1
 
+/** This has been replaced in commits 6ce635aa82 and earlier by the
+ * DECLARE_TR_CTX, tr_ctx and component UUID system below
+ */
 #define _TRACE_INV_CLASS	TRACE_CLASS_DEPRECATED
-#define _TRACE_INV_ID		-1
 
 /**
  * Trace context.

src/trace/dma-trace.c

@@ -120,6 +120,10 @@ static enum task_state trace_work(void *data)
 	return SOF_TASK_STATE_RESCHEDULE;
 }
 
+/** Do this early so we can log at initialization time even before the
+ * DMA runs. The rest happens later in dma_trace_init_complete() and
+ * dma_trace_enable()
+ */
 int dma_trace_init_early(struct sof *sof)
 {
 	sof->dmat = rzalloc(SOF_MEM_ZONE_SYS_SHARED, 0, SOF_MEM_CAPS_RAM, sizeof(*sof->dmat));
@@ -135,6 +139,7 @@ int dma_trace_init_early(struct sof *sof)
 	return 0;
 }
 
+/** Run after dma_trace_init_early() and before dma_trace_enable() */
 int dma_trace_init_complete(struct dma_trace_data *d)
 {
 	int ret = 0;
@@ -317,6 +322,9 @@ static int dma_trace_get_avail_data(struct dma_trace_data *d,
 
 #endif  /* CONFIG_DMA_GW */
 
+/** Invoked remotely by SOF_IPC_TRACE_DMA_PARAMS* Depends on
+ * dma_trace_init_complete()
+ */
 int dma_trace_enable(struct dma_trace_data *d)
 {
 	int err;
@@ -344,9 +352,6 @@ int dma_trace_enable(struct dma_trace_data *d)
 		goto out;
 #endif
 
-	/* flush fw description message */
-	trace_flush();
-
 	/* validate DMA context */
 	if (!d->dc.dmac || !d->dc.chan) {
 		tr_err_atomic(&dt_tr, "dma_trace_enable(): not valid");
@@ -374,9 +379,8 @@ void dma_trace_flush(void *t)
 	int32_t wrap_count;
 	int ret;
 
-	if (!trace_data || !trace_data->dmatb.addr) {
+	if (!dma_trace_initialized(trace_data))
 		return;
-	}
 
 	buffer = &trace_data->dmatb;
 	avail = buffer->avail;
@@ -548,7 +552,7 @@ void dtrace_event(const char *e, uint32_t length)
 	struct dma_trace_buf *buffer = NULL;
 	unsigned long flags;
 
-	if (!trace_data || !trace_data->dmatb.addr ||
+	if (!dma_trace_initialized(trace_data) ||
 	    length > DMA_TRACE_LOCAL_SIZE / 8 || length == 0) {
 		return;
 	}
@@ -586,7 +590,7 @@ void dtrace_event_atomic(const char *e, uint32_t length)
 {
 	struct dma_trace_data *trace_data = dma_trace_data_get();
 
-	if (!trace_data || !trace_data->dmatb.addr ||
+	if (!dma_trace_initialized(trace_data) ||
 	    length > DMA_TRACE_LOCAL_SIZE / 8 || length == 0) {
 		return;
 	}

src/trace/trace.c

@@ -75,14 +75,16 @@ static void put_header(uint32_t *dst, const struct sof_uuid_entry *uid,
 		       uint32_t entry, uint64_t timestamp)
 {
 	struct timer *timer = timer_get();
+	/* Support very early tracing */
+	uint64_t delta = timer ? timer->delta : 0;
 	struct log_entry_header header;
 	int ret;
 
 	header.uid = (uintptr_t)uid;
 	header.id_0 = id_1 & TRACE_ID_MASK;
 	header.id_1 = id_2 & TRACE_ID_MASK;
 	header.core_id = cpu_get_id();
-	header.timestamp = timestamp + timer->delta;
+	header.timestamp = timestamp + delta;
 	header.log_entry_address = entry;
 
 	ret = memcpy_s(dst, sizeof(header), &header, sizeof(header));
@@ -463,7 +465,7 @@ int trace_filter_update(const struct trace_filter *filter)
 }
 
 /** Sends all pending DMA messages to mailbox (for emergencies) */
-void trace_flush(void)
+void trace_flush_dma_to_mbox(void)
 {
 	struct trace *trace = trace_get();
 	volatile uint64_t *t;
@@ -508,8 +510,6 @@ void trace_off(void)
 
 void trace_init(struct sof *sof)
 {
-	dma_trace_init_early(sof);
-
 	sof->trace = rzalloc(SOF_MEM_ZONE_SYS_SHARED, 0, SOF_MEM_CAPS_RAM, sizeof(*sof->trace));
 	sof->trace->enable = 1;
 	sof->trace->pos = 0;
@@ -521,4 +521,6 @@ void trace_init(struct sof *sof)
 	bzero((void *)MAILBOX_TRACE_BASE, MAILBOX_TRACE_SIZE);
 	dcache_writeback_invalidate_region((void *)MAILBOX_TRACE_BASE,
 					   MAILBOX_TRACE_SIZE);
+
+	dma_trace_init_early(sof);
 }

test/cmocka/src/common_mocks.c

@@ -111,7 +111,7 @@ void WEAK trace_log_filtered(bool send_atomic, const void *log_entry, const stru
 	(void) arg_count;
 }
 
-void WEAK trace_flush(void)
+void WEAK trace_flush_dma_to_mbox(void)
 {
 }
 

tools/logger/convert.c

@@ -60,7 +60,7 @@ struct proc_ldc_entry {
 	uintptr_t params[TRACE_MAX_PARAMS_COUNT];
 };
 
-static const char *BAD_PTR_STR = "<bad uid ptr %x>";
+static const char *BAD_PTR_STR = "<bad uid ptr 0x%.8x>";
 
 #define UUID_LOWER "%s%s%s<%08x-%04x-%04x-%02x%02x-%02x%02x%02x%02x%02x%02x>%s%s%s"
 #define UUID_UPPER "%s%s%s<%08X-%04X-%04X-%02X%02X-%02X%02X%02X%02X%02X%02X>%s%s%s"
@@ -198,7 +198,7 @@ static const char *asprintf_entry_text(uint32_t entry_address)
  *  ldc_entry_header from input to output.
  *
  * @param[out] pe copy of the header + formatted output
- * @param[in] e copy of the dictionary entry with unformatted,
+ * @param[in] e copy of the dictionary entry where unformatted,
     uint32_t params have been inserted.
    @param[in] use_colors whether to use ANSI terminal codes
 */
@@ -223,9 +223,19 @@ static void process_params(struct proc_ldc_entry *pe,
 	 * For decoding log entry text from pointer %pQ is used.
 	 */
 	while ((p = strchr(p, '%'))) {
+		uint32_t raw_param;
+
+		if (i >= e->header.params_num) {
+			/* Don't read e->params[] out of bounds. */
+			log_err("Too many %% conversion specifiers in '%s'\n",
+				e->text);
+			break;
+		}
+		raw_param = e->params[i];
+
 		/* % can't be the last char */
 		if (p + 1 >= t_end) {
-			log_err("Invalid format string");
+			log_err("Invalid format string\n");
 			break;
 		}
 
@@ -237,14 +247,14 @@ static void process_params(struct proc_ldc_entry *pe,
 			/* %s format specifier */
 			/* check for string printing, because it leads to logger crash */
 			log_err("String printing is not supported\n");
-			pe->params[i] = (uintptr_t)asprintf("<String @ 0x%08x>", e->params[i]);
+			pe->params[i] = (uintptr_t)asprintf("<String @ 0x%08x>", raw_param);
 			pe->subst_mask |= 1 << i;
 			++i;
 			p += 2;
 		} else if (p + 2 < t_end && p[1] == 'p' && p[2] == 'U') {
 			/* %pUx format specifier */
 			/* substitute UUID entry address with formatted string pointer from heap */
-			pe->params[i] = (uintptr_t)asprintf_uuid(p, e->params[i], use_colors,
+			pe->params[i] = (uintptr_t)asprintf_uuid(p, raw_param, use_colors,
 								 &uuid_fmt_len);
 			pe->subst_mask |= 1 << i;
 			++i;
@@ -256,7 +266,7 @@ static void process_params(struct proc_ldc_entry *pe,
 		} else if (p + 2 < t_end && p[1] == 'p' && p[2] == 'Q') {
 			/* %pQ format specifier */
 			/* substitute log entry address with formatted entry text */
-			pe->params[i] = (uintptr_t)asprintf_entry_text(e->params[i]);
+			pe->params[i] = (uintptr_t)asprintf_entry_text(raw_param);
 			pe->subst_mask |= 1 << i;
 			++i;
 
@@ -269,11 +279,13 @@ static void process_params(struct proc_ldc_entry *pe,
 			/* arguments different from %pU and %pQ should be passed without
 			 * modification
 			 */
-			pe->params[i] = e->params[i];
+			pe->params[i] = raw_param;
 			++i;
 			p += 2;
 		}
 	}
+	if (i < e->header.params_num)
+		log_err("Too few %% conversion specifiers in '%s'\n", e->text);
 }
 
 static void free_proc_ldc_entry(struct proc_ldc_entry *pe)
@@ -374,8 +386,12 @@ static const char *get_level_name(uint32_t level)
 		return "ERROR ";
 	case LOG_LEVEL_WARNING:
 		return "WARN ";
+	case LOG_LEVEL_INFO:
+		return "INFO ";
+	case LOG_LEVEL_DEBUG:
+		return "DEBUG ";
 	default:
-		return ""; /* info is usual, do not print anything */
+		return "UNKNOWN ";
 	}
 }