From 4f9ad88a274ee2a04cf8dd85eefcd17c290085d2 Mon Sep 17 00:00:00 2001 From: Marc Herbert Date: Sun, 27 Jun 2021 20:20:55 +0000 Subject: [PATCH 1/6] check patch: turn off printk warnings Zephyr's printk does not work like Linuxs printk Signed-off-by: Marc Herbert --- scripts/checkpatch.pl | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/scripts/checkpatch.pl b/scripts/checkpatch.pl index ce33a3b0ac98..609dc9d16ed2 100755 --- a/scripts/checkpatch.pl +++ b/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. From 12ff9018b29468b4054710b576877900a93ed3dd Mon Sep 17 00:00:00 2001 From: Marc Herbert Date: Sat, 19 Jun 2021 01:17:47 +0000 Subject: [PATCH 2/6] trace.c: mtrace_event: fix memcpy_s( dest_size ) argument Found by chance while looking for something else. This makes no difference right now because we checked the "length" in the line immediately before but let's do the right thing anyway, at the very least it's more readable. Signed-off-by: Marc Herbert --- src/trace/trace.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/trace/trace.c b/src/trace/trace.c index f62c554e9186..12f4548fe6a0 100644 --- a/src/trace/trace.c +++ b/src/trace/trace.c @@ -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; From 930b81375460118b8d633fc6cf6693ab29f1648c Mon Sep 17 00:00:00 2001 From: Marc Herbert Date: Fri, 18 Jun 2021 00:30:11 +0000 Subject: [PATCH 3/6] timer.h: add platform_safe_get_time(timer) and use it in trace.c Returns a small constant instead of crashing platform_timer_get() when timer is NULL. This is required to restore early tracing before sof->timer is initialized. Signed-off-by: Marc Herbert --- src/include/sof/drivers/timer.h | 11 +++++++++++ src/trace/trace.c | 5 +++-- 2 files changed, 14 insertions(+), 2 deletions(-) diff --git a/src/include/sof/drivers/timer.h b/src/include/sof/drivers/timer.h index 3780cc536b82..f016a12822de 100644 --- a/src/include/sof/drivers/timer.h +++ b/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); diff --git a/src/trace/trace.c b/src/trace/trace.c index 12f4548fe6a0..add5cc120290 100644 --- a/src/trace/trace.c +++ b/src/trace/trace.c @@ -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); From c9c177bd5b054873c24fbe52dcf78ebea2ee3649 Mon Sep 17 00:00:00 2001 From: Marc Herbert Date: Thu, 27 May 2021 02:23:34 +0000 Subject: [PATCH 4/6] trace.c: add mtrace_printf() low-level shortcut Direct access to mbox shared memory logging when DMA tracing is either not initialized yet or disabled or found broken for any reason. Signed-off-by: Marc Herbert --- src/include/sof/trace/trace.h | 27 +++++++++++++++++++++++++++ src/trace/trace.c | 23 +++++++++++++++++++++-- zephyr/include/sof/trace/trace.h | 12 ++++++++++-- 3 files changed, 58 insertions(+), 4 deletions(-) diff --git a/src/include/sof/trace/trace.h b/src/include/sof/trace/trace.h index 7e7fb4eafe14..36fea9f391fa 100644 --- a/src/include/sof/trace/trace.h +++ b/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__ */ diff --git a/src/trace/trace.c b/src/trace/trace.c index add5cc120290..ae56fcbc9694 100644 --- a/src/trace/trace.c +++ b/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; @@ -525,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)); +} diff --git a/zephyr/include/sof/trace/trace.h b/zephyr/include/sof/trace/trace.h index 296c477c779b..7d24708c8845 100644 --- a/zephyr/include/sof/trace/trace.h +++ b/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), \ From 3bb5060ae796a957adccdebdc556347d05a4d6f7 Mon Sep 17 00:00:00 2001 From: Marc Herbert Date: Thu, 27 May 2021 00:12:11 +0000 Subject: [PATCH 5/6] dma-trace.c: use new mtrace_printf() to add some error handling Replace some tr_err() too. Signed-off-by: Marc Herbert --- src/ipc/ipc3/handler.c | 6 ++++++ src/trace/dma-trace.c | 46 +++++++++++++++++++++++++++++++++++++----- 2 files changed, 47 insertions(+), 5 deletions(-) diff --git a/src/ipc/ipc3/handler.c b/src/ipc/ipc3/handler.c index ee84e05ac9a8..c8980691f7ac 100644 --- a/src/ipc/ipc3/handler.c +++ b/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); diff --git a/src/trace/dma-trace.c b/src/trace/dma-trace.c index 5313a1346aa4..97305ccfdf9c 100644 --- a/src/trace/dma-trace.c +++ b/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,10 +171,17 @@ 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; } @@ -157,7 +189,8 @@ int dma_trace_init_complete(struct dma_trace_data *d) &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,8 +364,11 @@ 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. From 8d26d43d088dc4ee4f419d3ca25c5f8d4f3e1391 Mon Sep 17 00:00:00 2001 From: Marc Herbert Date: Wed, 23 Jun 2021 02:47:15 +0000 Subject: [PATCH 6/6] dma-trace.c: use new mtrace_printf() to demote FW ABI banner to INFO ... down from ERROR. It was never an error, this was a hack to be duplicated to both trace and etrace. This will make it easier to search for actual errors. Also make the banners slightly different between etrace and trace thanks to new SHM: and DMA: prefixes. This makes identification of log files easier. Signed-off-by: Marc Herbert --- src/trace/dma-trace.c | 18 +++++++++++------- 1 file changed, 11 insertions(+), 7 deletions(-) diff --git a/src/trace/dma-trace.c b/src/trace/dma-trace.c index 97305ccfdf9c..1787a9f5d45e 100644 --- a/src/trace/dma-trace.c +++ b/src/trace/dma-trace.c @@ -370,13 +370,17 @@ int dma_trace_enable(struct dma_trace_data *d) 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 /*