diff --git a/src/debug/panic.c b/src/debug/panic.c index b866f5991c37..22c6003ac2ee 100644 --- a/src/debug/panic.c +++ b/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 */ diff --git a/src/include/sof/trace/dma-trace.h b/src/include/sof/trace/dma-trace.h index bb47133506f0..53cd8bac2fb8 100644 --- a/src/include/sof/trace/dma-trace.h +++ b/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; diff --git a/src/include/sof/trace/trace.h b/src/include/sof/trace/trace.h index d0c2df28a173..7e7fb4eafe14 100644 --- a/src/include/sof/trace/trace.h +++ b/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. diff --git a/src/trace/dma-trace.c b/src/trace/dma-trace.c index efabc75c00c3..5313a1346aa4 100644 --- a/src/trace/dma-trace.c +++ b/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; } diff --git a/src/trace/trace.c b/src/trace/trace.c index 9c17cf982cd8..f62c554e9186 100644 --- a/src/trace/trace.c +++ b/src/trace/trace.c @@ -75,6 +75,8 @@ 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; @@ -82,7 +84,7 @@ static void put_header(uint32_t *dst, const struct sof_uuid_entry *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); } diff --git a/test/cmocka/src/common_mocks.c b/test/cmocka/src/common_mocks.c index 5607db0caf54..05a168575aa4 100644 --- a/test/cmocka/src/common_mocks.c +++ b/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) { } diff --git a/tools/logger/convert.c b/tools/logger/convert.c index c181b4b26012..3fee8d7c20eb 100644 --- a/tools/logger/convert.c +++ b/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 = ""; +static const char *BAD_PTR_STR = ""; #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("", e->params[i]); + pe->params[i] = (uintptr_t)asprintf("", 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 "; } }