Skip to content

Optional nanosecond timestamp logging #592

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
wants to merge 1 commit into
base: master
Choose a base branch
from
+96 −45
Open

Optional nanosecond timestamp logging #592

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
88 changes: 56 additions & 32 deletions candump.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -128,6 +128,7 @@ static void print_usage(void)
fprintf(stderr, "Options:\n");
fprintf(stderr, " -t <type> (timestamp: (a)bsolute/(d)elta/(z)ero/(A)bsolute w date)\n");
fprintf(stderr, " -H (read hardware timestamps instead of system timestamps)\n");
fprintf(stderr, " -N (log nanosecond timestamps instead of microseconds)\n");
fprintf(stderr, " -c (increment color mode level)\n");
fprintf(stderr, " -i (binary output - may exceed 80 chars/line)\n");
fprintf(stderr, " -a (enable additional ASCII output)\n");
Expand Down Expand Up @@ -220,49 +221,66 @@ static int idx2dindex(int ifidx, int socket)
return i;
}

static int sprint_timestamp(char *ts_buffer, const char timestamp,
const struct timeval *tv, struct timeval *const last_tv)
static int sprint_timestamp(char *ts_buffer, const char timestamp, const char use_ns,
const struct timespec *ts, struct timespec *const last_ts)
{
int numchars = 0;

switch (timestamp) {
case 'a': /* absolute with timestamp */
numchars = sprintf(ts_buffer, "(%010llu.%06llu) ",
(unsigned long long)tv->tv_sec,
(unsigned long long)tv->tv_usec);
if (use_ns) {
numchars = sprintf(ts_buffer, "(%010llu.%09llu) ",
(unsigned long long)ts->tv_sec,
(unsigned long long)ts->tv_nsec);
} else {
numchars = sprintf(ts_buffer, "(%010llu.%06llu) ",
(unsigned long long)ts->tv_sec,
(unsigned long long)ts->tv_nsec / 1000);
}
break;

case 'A': /* absolute with date */
{
struct tm tm;
char timestring[25];

tm = *localtime(&tv->tv_sec);
tm = *localtime(&ts->tv_sec);
strftime(timestring, 24, "%Y-%m-%d %H:%M:%S", &tm);
numchars = sprintf(ts_buffer, "(%s.%06llu) ", timestring,
(unsigned long long)tv->tv_usec);
if (use_ns) {
numchars = sprintf(ts_buffer, "(%s.%09llu) ", timestring,
(unsigned long long)ts->tv_nsec);
} else {
numchars = sprintf(ts_buffer, "(%s.%06llu) ", timestring,
(unsigned long long)ts->tv_nsec / 1000);
}
}
break;

case 'd': /* delta */
case 'z': /* starting with zero */
{
struct timeval diff;

if (last_tv->tv_sec == 0) /* first init */
*last_tv = *tv;
diff.tv_sec = tv->tv_sec - last_tv->tv_sec;
diff.tv_usec = tv->tv_usec - last_tv->tv_usec;
if (diff.tv_usec < 0)
diff.tv_sec--, diff.tv_usec += 1000000;
struct timespec diff;

if (last_ts->tv_sec == 0) /* first init */
*last_ts = *ts;
diff.tv_sec = ts->tv_sec - last_ts->tv_sec;
diff.tv_nsec = ts->tv_nsec - last_ts->tv_nsec;
if (diff.tv_nsec < 0)
diff.tv_sec--, diff.tv_nsec += 1000000000;
if (diff.tv_sec < 0)
diff.tv_sec = diff.tv_usec = 0;
numchars = sprintf(ts_buffer, "(%03llu.%06llu) ",
(unsigned long long)diff.tv_sec,
(unsigned long long)diff.tv_usec);
diff.tv_sec = diff.tv_nsec = 0;
if (use_ns) {
numchars = sprintf(ts_buffer, "(%03llu.%09llu) ",
(unsigned long long)diff.tv_sec,
(unsigned long long)diff.tv_nsec);
} else {
numchars = sprintf(ts_buffer, "(%03llu.%06llu) ",
(unsigned long long)diff.tv_sec,
(unsigned long long)diff.tv_nsec / 1000);
}

if (timestamp == 'd')
*last_tv = *tv; /* update for delta calculation */
*last_ts = *ts; /* update for delta calculation */
}
break;

Expand All @@ -288,6 +306,7 @@ int main(int argc, char **argv)
unsigned char timestamp = 0;
unsigned char logtimestamp = 'a';
unsigned char hwtimestamp = 0;
unsigned char use_ns = 0;
unsigned char down_causes_exit = 1;
unsigned char dropmonitor = 0;
unsigned char extra_msg_info = 0;
Expand Down Expand Up @@ -322,7 +341,7 @@ int main(int argc, char **argv)
static cu_t cu; /* union for CAN CC/FD/XL frames */
int nbytes, i;
struct ifreq ifr;
struct timeval tv, last_tv;
struct timespec ts, last_ts;
int timeout_ms = -1; /* default to no timeout */
FILE *logfile = NULL;
char fname[83]; /* suggested by -Wformat-overflow= */
Expand All @@ -334,12 +353,12 @@ int main(int argc, char **argv)
signal(SIGHUP, sigterm);
signal(SIGINT, sigterm);

last_tv.tv_sec = 0;
last_tv.tv_usec = 0;
last_ts.tv_sec = 0;
last_ts.tv_nsec = 0;

progname = basename(argv[0]);

while ((opt = getopt(argc, argv, "t:HciaSs:lf:Ln:r:Dde8xT:h?")) != -1) {
while ((opt = getopt(argc, argv, "t:HNciaSs:lf:Ln:r:Dde8xT:h?")) != -1) {
switch (opt) {
case 't':
timestamp = optarg[0];
Expand All @@ -359,6 +378,10 @@ int main(int argc, char **argv)
hwtimestamp = 1;
break;

case 'N':
use_ns = 1;
break;

case 'c':
color++;
break;
Expand Down Expand Up @@ -784,7 +807,11 @@ int main(int argc, char **argv)
cmsg && (cmsg->cmsg_level == SOL_SOCKET);
cmsg = CMSG_NXTHDR(&msg,cmsg)) {
if (cmsg->cmsg_type == SO_TIMESTAMP) {
struct timeval tv;
memcpy(&tv, CMSG_DATA(cmsg), sizeof(tv));
ts.tv_sec = tv.tv_sec;
ts.tv_nsec = tv.tv_usec;
ts.tv_nsec *= 1000;
} else if (cmsg->cmsg_type == SO_TIMESTAMPING) {
struct timespec *stamp = (struct timespec *)CMSG_DATA(cmsg);

Expand All @@ -795,8 +822,7 @@ int main(int argc, char **argv)
* See chapter 2.1.2 Receive timestamps in
* linux/Documentation/networking/timestamping.txt
*/
tv.tv_sec = stamp[2].tv_sec;
tv.tv_usec = stamp[2].tv_nsec / 1000;
ts = stamp[2];
} else if (cmsg->cmsg_type == SO_RXQ_OVFL) {
memcpy(&obj->dropcnt, CMSG_DATA(cmsg), sizeof(__u32));
}
Expand Down Expand Up @@ -831,11 +857,9 @@ int main(int argc, char **argv)
/* build common log format output */
if ((log) || ((logfrmt) && (silent == SILENT_OFF))) {

alen = sprint_timestamp(afrbuf, logtimestamp,
&tv, &last_tv);
alen = sprint_timestamp(afrbuf, logtimestamp, use_ns, &ts, &last_ts);

alen += sprintf(afrbuf + alen, "%*s ",
max_devname_len, devname[idx]);
alen += sprintf(afrbuf + alen, "%*s ", max_devname_len, devname[idx]);

alen += snprintf_canframe(afrbuf + alen, sizeof(afrbuf) - alen, &cu, 0);
}
Expand All @@ -861,7 +885,7 @@ int main(int argc, char **argv)

/* print (colored) long CAN frame style to stdout */
alen = sprintf(afrbuf, " %s", (color > 2) ? col_on[idx % MAXCOL] : "");
alen += sprint_timestamp(afrbuf + alen, timestamp, &tv, &last_tv);
alen += sprint_timestamp(afrbuf + alen, timestamp, use_ns, &ts, &last_ts);
alen += sprintf(afrbuf + alen, " %s%*s",
(color && (color < 3)) ? col_on[idx % MAXCOL] : "",
max_devname_len, devname[idx]);
Expand Down
30 changes: 21 additions & 9 deletions canplayer.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -452,14 +452,20 @@ int main(int argc, char **argv)
return 1;
}
log_tv.tv_sec = sec;
log_tv.tv_usec = usec;

/*
* ensure the fractions of seconds are 6 decimal places long to catch
* ensure the fractions of seconds are 6 or 9 decimal places long to catch
* 3rd party or handcrafted logfiles that treat the timestamp as float
*/
if (strchr(buf, ')') - strchr(buf, '.') != 7) {
fprintf(stderr, "timestamp format in logfile requires 6 decimal places\n");
switch (strchr(buf, ')') - strchr(buf, '.')) {
case 7: //6
log_tv.tv_usec = usec;
break;
case 10: //9
log_tv.tv_usec = usec / 1000;
break;
default:
fprintf(stderr, "timestamp format in logfile requires 6 or 9 decimal places\n");
return 1;
}

Expand Down Expand Up @@ -541,19 +547,25 @@ int main(int argc, char **argv)
break;
}

if (sscanf(buf, "(%llu.%llu) %s %s", &sec, &usec, device, afrbuf) != 4) {
if (sscanf(buf, "(%llu.%llu) %21s %6299s", &sec, &usec, device, afrbuf) != 4) {
fprintf(stderr, "incorrect line format in logfile\n");
return 1;
}
log_tv.tv_sec = sec;
log_tv.tv_usec = usec;

/*
* ensure the fractions of seconds are 6 decimal places long to catch
* ensure the fractions of seconds are 6 or 9 decimal places long to catch
* 3rd party or handcrafted logfiles that treat the timestamp as float
*/
if (strchr(buf, ')') - strchr(buf, '.') != 7) {
fprintf(stderr, "timestamp format in logfile requires 6 decimal places\n");
switch (strchr(buf, ')') - strchr(buf, '.')) {
case 7: //6
log_tv.tv_usec = usec;
break;
case 10: //9
log_tv.tv_usec = usec / 1000;
break;
default:
fprintf(stderr, "timestamp format in logfile requires 6 or 9 decimal places\n");
return 1;
}

Expand Down
17 changes: 16 additions & 1 deletion log2asc.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -407,7 +407,22 @@ int main(int argc, char **argv)
}
}
tv.tv_sec = sec;
tv.tv_usec = usec;

/*
* ensure the fractions of seconds are 6 or 9 decimal places long to catch
* 3rd party or handcrafted logfiles that treat the timestamp as float
*/
switch (strchr(buf, ')') - strchr(buf, '.')) {
case 7: //6
tv.tv_usec = usec;
break;
case 10: //9
tv.tv_usec = usec / 1000;
break;
default:
fprintf(stderr, "timestamp format in logfile requires 6 or 9 decimal places\n");
return 1;
}

if (print_banner) { /* print banner */
print_banner = 0;
Expand Down
6 changes: 3 additions & 3 deletions log2long.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -51,7 +51,7 @@
#include "lib.h"

#define DEVSZ 22
#define TIMESZ 22 /* sizeof("(1345212884.318850) ") */
#define TIMESZ 25 /* sizeof("(1345212884.318850123) ") */
#define BUFSZ (DEVSZ + AFRSZ + TIMESZ)

/* adapt sscanf() functions below on error */
Expand All @@ -61,7 +61,7 @@
#if (DEVSZ != 22)
#error "DEVSZ value does not fit sscanf restrictions!"
#endif
#if (TIMESZ != 22)
#if (TIMESZ != 25)
#error "TIMESZ value does not fit sscanf restrictions!"
#endif

Expand All @@ -78,7 +78,7 @@ int main(void)
return 1;
}

if (sscanf(buf, "%21s %21s %6299s", timestamp, device, afrbuf) != 3)
if (sscanf(buf, "%24s %21s %6299s", timestamp, device, afrbuf) != 3)
return 1;

mtu = parse_canframe(afrbuf, &cu);
Expand Down
Loading