From 2c3fb790f80746039f23b04d1440accf635cad60 Mon Sep 17 00:00:00 2001 From: Marc Herbert Date: Mon, 10 May 2021 23:14:05 +0000 Subject: [PATCH 1/3] logger: don't "return" when failing in the main loop, break instead Set the error code in "ret" and only exit the loop so we don't lose the optional warnings at the end of the loop. Signed-off-by: Marc Herbert --- tools/logger/convert.c | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/tools/logger/convert.c b/tools/logger/convert.c index 5cceb70a92a5..8c87b98ccf3a 100644 --- a/tools/logger/convert.c +++ b/tools/logger/convert.c @@ -836,7 +836,7 @@ static int logger_read(void) log_err("in %s(), fread(..., %s) failed: %s(%d)\n", __func__, global_config->in_file, strerror(-ret), ret); - return ret; + break; } /* for trace mode, try to reopen */ if (global_config->trace) { @@ -851,7 +851,8 @@ static int logger_read(void) log_err("in %s(), freopen(..., %s) failed: %s(%d)\n", __func__, global_config->in_file, strerror(errno), errno); - return -errno; + ret = -errno; + break; } } else { /* EOF */ From 233201edc772a02b32a9d042140f39dcaa9cc1bd Mon Sep 17 00:00:00 2001 From: Marc Herbert Date: Wed, 26 May 2021 02:58:02 +0000 Subject: [PATCH 2/3] logger: print the value of a negative DELTA when there is one Because why not. Signed-off-by: Marc Herbert --- tools/logger/convert.c | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/tools/logger/convert.c b/tools/logger/convert.c index 8c87b98ccf3a..c181b4b26012 100644 --- a/tools/logger/convert.c +++ b/tools/logger/convert.c @@ -457,7 +457,8 @@ static void print_entry_params(const struct log_entry_header *dma_log, if (dma_log->timestamp < last_timestamp) { fprintf(out_fd, - "\n\t\t --- negative DELTA: wrap, IPC_TRACE, other? ---\n\n"); + "\n\t\t --- negative DELTA = %.3f us: wrap, IPC_TRACE, other? ---\n\n", + -to_usecs(last_timestamp - dma_log->timestamp)); entry_number = 1; } From 9810ffd5ddcfa94499e2533c04784b967dc1f684 Mon Sep 17 00:00:00 2001 From: Marc Herbert Date: Wed, 26 May 2021 03:14:59 +0000 Subject: [PATCH 3/3] Restore original, 2018 mtrace_event(atomic) spin lock logic Fixes bad commit b284ac32b53f5 ("debugability: Macro Metaprogramming Refactor") that accidentally swapped mtrace_event() and mtrace_event_atomic() Before that accidental inversion, _trace_event_mboxN() functions invoked spin_lock_irq() whereas _trace_even_mbox_atomicN() did NOT take locks. That was consistent with the non-mbox, DMA variants of these functions. As explained in the message of commit 3dca7b777879 ("trace: dma: Add atomic and nowait DMA tracing support."), functions with the `_atomic()` suffix,, are meant to be used in atomic contexts where the lock is _already_ taken. Searching for spin_lock_irq() in the code after the bad commit shows that the logic was inverted for the _mbox variants: the lock became used for the _atomic() variants. The reasons why I can't reproduce any actual issue are likely the same reasons why this inversion was never noticed: - no multicore - very little use of trace_.*_atomic variants - spin_lock_irq() is re-entrant? I merely noticed the inconsistency with DMA tracing while trying to solve unrelated issues in the same places. The non-mbox, DMA variants were not affected by the bad commit because for DMA the lock was and is managed in a different file: dma-trace.c. Searching "spin_lock_irq" in later commit b12a6626c5ade0a ("trace: Remove metaprogramming from trace implementation") shows that it preserved this inversion across this second refactor; it left the bug untouched. Signed-off-by: Marc Herbert --- src/trace/trace.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/trace/trace.c b/src/trace/trace.c index c7c9af9b0b2a..9c17cf982cd8 100644 --- a/src/trace/trace.c +++ b/src/trace/trace.c @@ -250,11 +250,11 @@ static void vatrace_log(bool send_atomic, uint32_t log_entry, const struct tr_ct #if CONFIG_TRACEM /* send event by mail box too. */ if (send_atomic) { - spin_lock_irq(&trace->lock, flags); mtrace_event((const char *)data, MESSAGE_SIZE(arg_count)); - spin_unlock_irq(&trace->lock, flags); } else { + spin_lock_irq(&trace->lock, flags); mtrace_event((const char *)data, MESSAGE_SIZE(arg_count)); + spin_unlock_irq(&trace->lock, flags); } #else /* send event by mail box if level is LOG_LEVEL_CRITICAL. */