Optional nanosecond timestamp logging (#592)

* Optional nanosecond timestamp logging

* Removed limited string reading

candump.c

@@ -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");
@@ -220,16 +221,22 @@ static int idx2dindex(int ifidx, int socket)
 	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;
 
 	switch (timestamp) {
 	case 'a': /* absolute with timestamp */
+		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)tv->tv_sec,
+					   (unsigned long long)ts->tv_sec,
-				   (unsigned long long)tv->tv_usec);
+					   (unsigned long long)ts->tv_nsec / 1000);
+		}
 		break;
 
 	case 'A': /* absolute with date */
@@ -237,32 +244,43 @@ static int sprint_timestamp(char *ts_buffer, const char timestamp,
 		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);
+		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)tv->tv_usec);
+					   (unsigned long long)ts->tv_nsec / 1000);
+		}
 	}
 	break;
 
 	case 'd': /* delta */
 	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)
-			diff.tv_sec = diff.tv_usec = 0;
+			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_usec);
+					   (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;
 
@@ -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;
@@ -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= */
@@ -334,12 +353,12 @@ int main(int argc, char **argv)
 	signal(SIGHUP, 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]);
 
-	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];
@@ -359,6 +378,10 @@ int main(int argc, char **argv)
 			hwtimestamp = 1;
 			break;
 
+		case 'N':
+			use_ns = 1;
+			break;
+
 		case 'c':
 			color++;
 			break;
@@ -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);
 
@@ -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;
+					ts = stamp[2];
-					tv.tv_usec = stamp[2].tv_nsec / 1000;
 				} else if (cmsg->cmsg_type == SO_RXQ_OVFL) {
 					memcpy(&obj->dropcnt, CMSG_DATA(cmsg), sizeof(__u32));
 				}
@@ -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,
+				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);
 			}
@@ -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]);

canplayer.c

@@ -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) {
+		switch (strchr(buf, ')') - strchr(buf, '.')) {
-			fprintf(stderr, "timestamp format in logfile requires 6 decimal places\n");
+		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;
 		}
 
@@ -546,14 +552,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) {
+				switch (strchr(buf, ')') - strchr(buf, '.')) {
-					fprintf(stderr, "timestamp format in logfile requires 6 decimal places\n");
+				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;
 				}
 

log2asc.c

@@ -407,7 +407,22 @@ int main(int argc, char **argv)
 			}
 		}
 		tv.tv_sec = sec;
+
+		/*
+		 * 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;

log2long.c

@@ -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 */
@@ -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
 
@@ -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);