Skip to content

Commit 7dbcd7e

Browse files
marc-hblgirdwood
authored andcommitted
logger: add ktime and date in header
Every log file should have a date. ktime can be related to the TIMESTAMP column. It is especially useful to spot logs delayed or stuck. Some logs use ktime while others use a date and it can be sometimes difficult to connect them with one another. This header can help. Before: TIMESTAMP (us) DELTA C# COMPONENT CONTENT [ 5120116529] ( 0) c0 dma-trace ERROR FW ABI 0x3012001 ... After: TIMESTAMP (us) DELTA C# COMPONENT \ CONTENT ktime=5132.663s @ 2021-04-27 14:36:09 -0700 PDT [ 5120116529] ( 0) c0 dma-trace ERROR FW ABI 0x3012001 ... Signed-off-by: Marc Herbert <marc.herbert@intel.com>
1 parent 67fdbd2 commit 7dbcd7e

File tree

1 file changed

+24
-1
lines changed

1 file changed

+24
-1
lines changed

tools/logger/convert.c

Lines changed: 24 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -15,6 +15,7 @@
1515
#include <unistd.h>
1616
#include <math.h>
1717
#include <sof/lib/uuid.h>
18+
#include <time.h>
1819
#include <user/abi_dbg.h>
1920
#include <user/trace.h>
2021
#include "convert.h"
@@ -316,6 +317,18 @@ static inline void print_table_header(void)
316317
int hide_location = global_config->hide_location;
317318
char time_fmt[32];
318319

320+
char date_string[64];
321+
const time_t epoc_secs = time(NULL);
322+
/* See SOF_IPC_TRACE_DMA_PARAMS_EXT in the kernel sources */
323+
struct timespec ktime;
324+
const int gettime_ret = clock_gettime(CLOCK_MONOTONIC, &ktime);
325+
326+
if (gettime_ret) {
327+
log_err("clock_gettime() failed: %s\n",
328+
strerror(gettime_ret));
329+
exit(1);
330+
}
331+
319332
if (global_config->time_precision >= 0) {
320333
const unsigned int ts_width =
321334
timestamp_width(global_config->time_precision);
@@ -327,8 +340,18 @@ static inline void print_table_header(void)
327340
fprintf(out_fd, "%2s %-18s ", "C#", "COMPONENT");
328341
if (!hide_location)
329342
fprintf(out_fd, "%-29s ", "LOCATION");
330-
fprintf(out_fd, "%s\n", "CONTENT");
343+
fprintf(out_fd, "%s", "CONTENT");
331344

345+
if (global_config->time_precision >= 0) {
346+
/* e.g.: ktime=4263.487s @ 2021-04-27 14:21:13 -0700 PDT */
347+
fprintf(out_fd, "\tktime=%lu.%03lus",
348+
ktime.tv_sec, ktime.tv_nsec / 1000000);
349+
if (strftime(date_string, sizeof(date_string),
350+
"%F %X %z %Z", localtime(&epoc_secs)))
351+
fprintf(out_fd, " @ %s", date_string);
352+
}
353+
354+
fprintf(out_fd, "\n");
332355
fflush(out_fd);
333356
}
334357

0 commit comments

Comments
 (0)