Optional nanosecond timestamp logging

Rikus Wessels 2025-03-10 18:16:58 +02:00 committed by Rikus Wessels
parent 6b46063eee
commit f69fccd528
1 changed files with 55 additions and 31 deletions

View File

@ -128,6 +128,7 @@ static void print_usage(void)
fprintf(stderr, "Options:\n"); fprintf(stderr, "Options:\n");
fprintf(stderr, " -t <type> (timestamp: (a)bsolute/(d)elta/(z)ero/(A)bsolute w date)\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, " -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, " -c (increment color mode level)\n");
fprintf(stderr, " -i (binary output - may exceed 80 chars/line)\n"); fprintf(stderr, " -i (binary output - may exceed 80 chars/line)\n");
fprintf(stderr, " -a (enable additional ASCII output)\n"); fprintf(stderr, " -a (enable additional ASCII output)\n");
@ -220,16 +221,22 @@ static int idx2dindex(int ifidx, int socket)
return i; return i;
} }
static int sprint_timestamp(char *ts_buffer, const char timestamp, static int sprint_timestamp(char *ts_buffer, const char timestamp, const char use_ns,
const struct timeval *tv, struct timeval *const last_tv) const struct timespec *ts, struct timespec *const last_ts)
{ {
int numchars = 0; int numchars = 0;
switch (timestamp) { switch (timestamp) {
case 'a': /* absolute with timestamp */ case 'a': /* absolute with timestamp */
numchars = sprintf(ts_buffer, "(%010llu.%06llu) ", if (use_ns) {
(unsigned long long)tv->tv_sec, numchars = sprintf(ts_buffer, "(%010llu.%09llu) ",
(unsigned long long)tv->tv_usec); (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; break;
case 'A': /* absolute with date */ case 'A': /* absolute with date */
@ -237,32 +244,43 @@ static int sprint_timestamp(char *ts_buffer, const char timestamp,
struct tm tm; struct tm tm;
char timestring[25]; char timestring[25];
tm = *localtime(&tv->tv_sec); tm = *localtime(&ts->tv_sec);
strftime(timestring, 24, "%Y-%m-%d %H:%M:%S", &tm); strftime(timestring, 24, "%Y-%m-%d %H:%M:%S", &tm);
numchars = sprintf(ts_buffer, "(%s.%06llu) ", timestring, if (use_ns) {
(unsigned long long)tv->tv_usec); 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; break;
case 'd': /* delta */ case 'd': /* delta */
case 'z': /* starting with zero */ case 'z': /* starting with zero */
{ {
struct timeval diff; struct timespec diff;
if (last_tv->tv_sec == 0) /* first init */ if (last_ts->tv_sec == 0) /* first init */
*last_tv = *tv; *last_ts = *ts;
diff.tv_sec = tv->tv_sec - last_tv->tv_sec; diff.tv_sec = ts->tv_sec - last_ts->tv_sec;
diff.tv_usec = tv->tv_usec - last_tv->tv_usec; diff.tv_nsec = ts->tv_nsec - last_ts->tv_nsec;
if (diff.tv_usec < 0) if (diff.tv_nsec < 0)
diff.tv_sec--, diff.tv_usec += 1000000; diff.tv_sec--, diff.tv_nsec += 1000000000;
if (diff.tv_sec < 0) if (diff.tv_sec < 0)
diff.tv_sec = diff.tv_usec = 0; diff.tv_sec = diff.tv_nsec = 0;
numchars = sprintf(ts_buffer, "(%03llu.%06llu) ", if (use_ns) {
(unsigned long long)diff.tv_sec, numchars = sprintf(ts_buffer, "(%03llu.%09llu) ",
(unsigned long long)diff.tv_usec); (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') if (timestamp == 'd')
*last_tv = *tv; /* update for delta calculation */ *last_ts = *ts; /* update for delta calculation */
} }
break; break;
@ -288,6 +306,7 @@ int main(int argc, char **argv)
unsigned char timestamp = 0; unsigned char timestamp = 0;
unsigned char logtimestamp = 'a'; unsigned char logtimestamp = 'a';
unsigned char hwtimestamp = 0; unsigned char hwtimestamp = 0;
unsigned char use_ns = 0;
unsigned char down_causes_exit = 1; unsigned char down_causes_exit = 1;
unsigned char dropmonitor = 0; unsigned char dropmonitor = 0;
unsigned char extra_msg_info = 0; unsigned char extra_msg_info = 0;
@ -322,7 +341,7 @@ int main(int argc, char **argv)
static cu_t cu; /* union for CAN CC/FD/XL frames */ static cu_t cu; /* union for CAN CC/FD/XL frames */
int nbytes, i; int nbytes, i;
struct ifreq ifr; struct ifreq ifr;
struct timeval tv, last_tv; struct timespec ts, last_ts;
int timeout_ms = -1; /* default to no timeout */ int timeout_ms = -1; /* default to no timeout */
FILE *logfile = NULL; FILE *logfile = NULL;
char fname[83]; /* suggested by -Wformat-overflow= */ char fname[83]; /* suggested by -Wformat-overflow= */
@ -334,12 +353,12 @@ int main(int argc, char **argv)
signal(SIGHUP, sigterm); signal(SIGHUP, sigterm);
signal(SIGINT, sigterm); signal(SIGINT, sigterm);
last_tv.tv_sec = 0; last_ts.tv_sec = 0;
last_tv.tv_usec = 0; last_ts.tv_nsec = 0;
progname = basename(argv[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) { switch (opt) {
case 't': case 't':
timestamp = optarg[0]; timestamp = optarg[0];
@ -359,6 +378,10 @@ int main(int argc, char **argv)
hwtimestamp = 1; hwtimestamp = 1;
break; break;
case 'N':
use_ns = 1;
break;
case 'c': case 'c':
color++; color++;
break; break;
@ -784,7 +807,11 @@ int main(int argc, char **argv)
cmsg && (cmsg->cmsg_level == SOL_SOCKET); cmsg && (cmsg->cmsg_level == SOL_SOCKET);
cmsg = CMSG_NXTHDR(&msg,cmsg)) { cmsg = CMSG_NXTHDR(&msg,cmsg)) {
if (cmsg->cmsg_type == SO_TIMESTAMP) { if (cmsg->cmsg_type == SO_TIMESTAMP) {
struct timeval tv;
memcpy(&tv, CMSG_DATA(cmsg), sizeof(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) { } else if (cmsg->cmsg_type == SO_TIMESTAMPING) {
struct timespec *stamp = (struct timespec *)CMSG_DATA(cmsg); struct timespec *stamp = (struct timespec *)CMSG_DATA(cmsg);
@ -795,8 +822,7 @@ int main(int argc, char **argv)
* See chapter 2.1.2 Receive timestamps in * See chapter 2.1.2 Receive timestamps in
* linux/Documentation/networking/timestamping.txt * linux/Documentation/networking/timestamping.txt
*/ */
tv.tv_sec = stamp[2].tv_sec; ts = stamp[2];
tv.tv_usec = stamp[2].tv_nsec / 1000;
} else if (cmsg->cmsg_type == SO_RXQ_OVFL) { } else if (cmsg->cmsg_type == SO_RXQ_OVFL) {
memcpy(&obj->dropcnt, CMSG_DATA(cmsg), sizeof(__u32)); memcpy(&obj->dropcnt, CMSG_DATA(cmsg), sizeof(__u32));
} }
@ -831,11 +857,9 @@ int main(int argc, char **argv)
/* build common log format output */ /* build common log format output */
if ((log) || ((logfrmt) && (silent == SILENT_OFF))) { if ((log) || ((logfrmt) && (silent == SILENT_OFF))) {
alen = sprint_timestamp(afrbuf, logtimestamp, alen = sprint_timestamp(afrbuf, logtimestamp, use_ns, &ts, &last_ts);
&tv, &last_tv);
alen += sprintf(afrbuf + alen, "%*s ", alen += sprintf(afrbuf + alen, "%*s ", max_devname_len, devname[idx]);
max_devname_len, devname[idx]);
alen += snprintf_canframe(afrbuf + alen, sizeof(afrbuf) - alen, &cu, 0); alen += snprintf_canframe(afrbuf + alen, sizeof(afrbuf) - alen, &cu, 0);
} }
@ -861,7 +885,7 @@ int main(int argc, char **argv)
/* print (colored) long CAN frame style to stdout */ /* print (colored) long CAN frame style to stdout */
alen = sprintf(afrbuf, " %s", (color > 2) ? col_on[idx % MAXCOL] : ""); 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", alen += sprintf(afrbuf + alen, " %s%*s",
(color && (color < 3)) ? col_on[idx % MAXCOL] : "", (color && (color < 3)) ? col_on[idx % MAXCOL] : "",
max_devname_len, devname[idx]); max_devname_len, devname[idx]);