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. 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/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/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..1787a9f5d45e 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,16 +364,23 @@ 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. - * 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 /* diff --git a/src/trace/trace.c b/src/trace/trace.c index f62c554e9186..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; @@ -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; @@ -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); @@ -524,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), \