OrgACRN
/
sof
mirror of https://github.com/thesofproject/sof.git
1
0
Fork 0
Code Issues Projects Releases Wiki Activity

logger: print a separator when the timestamp goes back in time 

This makes the display of the mailbox ring buffer log much less
confusing. It should not happen with the DMA trace but will behave the
same in case something goes wrong.

Before this commit the only clue that wrapping had happened was a NaN in
the delta column (instead of the negative value).

The "other?" is because the start of the mailbox is sometimes corrupted,
or the timestamp goes sometimes back at boot for no obvious reason. In
other words this new separator is useful to highlight bugs too.

Absolute mode -e 0 with this commit:

    TIMESTAMP         DELTA C# COMPONENT          LOCATION

[22598174808] (        11) c0 ipc                  src/ipc/....
[22598174824] (        15) c0 ipc                  src/ipc/....
[22598443257] (    268433) c0 dma-trace             src/trace/....
[22598443271] (        14) c0 dma-trace             src/trace/....
[22598443286] (        14) c0 dma-trace             src/trace/....
[22598943257] (    499971) c0 dma-trace             src/trace/....

		 --- negative DELTA: wrap, IPC_TRACE, other? ---

[22430943257] (         0) c0 dma-trace             src/trace/....
[22530943257] ( 100000000) c0 dma-trace             src/trace/....
[22542943257] (  12000000) c0 dma-trace             src/trace/....
[22542943271] (        14) c0 dma-trace             src/trace/....
[22542943285] (        14) c0 dma-trace             src/trace/....

Relative mode -e 1 with this commit:

    TIMESTAMP         DELTA C# COMPONENT          LOCATION

[  3080783.6] (       11.4) c0 ipc                  src/ipc/....
[  3080799.1] (       15.5) c0 ipc                  src/ipc/....
[  3349232.5] (   268433.4) c0 dma-trace             src/trace/....
[  3349246.8] (       14.3) c0 dma-trace             src/trace/....
[  3349261.2] (       14.4) c0 dma-trace             src/trace/....
[  3849232.4] (   499971.2) c0 dma-trace             src/trace/....

		 --- negative DELTA: wrap, IPC_TRACE, other? ---

[22430943257.0] (      0.0) c0 dma-trace             src/trace/....
[100000000.0] (100000000.0) c0 dma-trace             src/trace/....
[111999999.5] ( 12000000.0) c0 dma-trace             src/trace/....
[112000013.9] (       14.4) c0 dma-trace             src/trace/....
[112000028.2] (       14.3) c0 dma-trace             src/trace/....

Signed-off-by: Marc Herbert <marc.herbert@intel.com>
This commit is contained in:
Marc Herbert 2021-04-16 03:34:49 +00:00 committed by Liam Girdwood
parent 825bf79871
commit d54a9281f8
1 changed files with 7 additions and 2 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

9
tools/logger/convert.c
View File

@ -392,16 +392,21 @@ static void print_entry_params(const struct log_entry_header *dma_log,
use_colors = 0;
/* Something somewhere went wrong */
if (dt < 0 || dt > 1000.0 * 1000.0 * 1000.0)
if (dt > 1000.0 * 1000.0 * 1000.0)
dt = NAN;
if (dma_log->timestamp < last_timestamp) {
fprintf(out_fd,
"\n\t\t --- negative DELTA: wrap, IPC_TRACE, other? ---\n\n");
entry_number = 1;
}
/* The first entry:
* - is never shown with a relative TIMESTAMP (to itself!?)
* - shows a zero DELTA
*/
if (entry_number == 1) {
entry_number++;
assert(last_timestamp == 0);
/* Display absolute (and random) timestamps */
timestamp_origin = 0;
dt = 0;