[PATCH 0/4] can-round-trip-stats

[PATCH 0/4] can-round-trip-stats

[Vincent Mailhol]

This series applies to below branch of Marc's fork of can-utils:

https://github.com/marckleinebudde/can-utils/tree/can-roundtrip-stats

It does some cleanup on the can-round-trip-stats in a first time and
then add the support for hardware timestamps (including TX hardware
timestamps).

This series can be helpfull for those of you who want to test the
kernel patch series which I recently posted:
https://lore.kernel.org/linux-can/20220725133208.432176-1-mailhol.vincent@wanadoo.fr/T/

Vincent Mailhol (4):
  can-roundtrip-stats: add print_stats() and calc_and_print_stats()
  can-roundtrip-stats: remove needless else after continue
  can-roundtrip-stats: rewrite the logic of the main loop to make it
    more robust
  can-roundrip-stats: add hardware timestamps information

 can-roundtrip-stats.c | 237 +++++++++++++++++++++++++++++-------------
 1 file changed, 164 insertions(+), 73 deletions(-)

-- 
2.35.1

[PATCH 1/4] can-roundtrip-stats: add print_stats() and calc_and_print_stats()

[Vincent Mailhol]

Split the main() into sub functions to increase readability.

Signed-off-by: Vincent Mailhol <mailhol.vincent@wanadoo.fr>
---
 can-roundtrip-stats.c | 83 +++++++++++++++++++++++++------------------
 1 file changed, 49 insertions(+), 34 deletions(-)

diff --git a/can-roundtrip-stats.c b/can-roundtrip-stats.c
index b261404..1eaed35 100644
--- a/can-roundtrip-stats.c
+++ b/can-roundtrip-stats.c
@@ -375,6 +375,51 @@ int get_rx_timestamp(int soc, struct msghdr *msg, struct timespec *tspec)
 	return 1;
 }
 
+void print_stats(const char *timestamp_name, canid_t canid,
+		 struct timespec tx, struct timespec rx, struct timespec diff)
+{
+	printf("[%s] ID: 0x%x, TX: %ld.%09ld, RX: %ld.%09ld, diff: %ld.%09ld\n",
+	       timestamp_name, canid,
+	       tx.tv_sec, tx.tv_nsec,
+	       rx.tv_sec, rx.tv_nsec,
+	       diff.tv_sec, diff.tv_nsec);
+
+}
+
+void calc_and_print_stats(struct timespec kernel_tx, struct timespec kernel_rx,
+			  struct timespec user_tx, struct timespec user_rx,
+			  canid_t canid)
+{
+	struct timespec kernel_diff, user_diff;
+	struct timespec user_to_kernel_tx, kernel_to_user_rx;
+	static double kernel_time_sum = 0, user_time_sum = 0;
+	static double user_to_kernel_tx_sum = 0, kernel_to_user_rx_sum = 0;
+
+	static int cnt = 0;
+
+	kernel_diff = timespec_sub(kernel_rx, kernel_tx);
+	kernel_time_sum += kernel_diff.tv_sec + kernel_diff.tv_nsec / 1000000000.;
+	user_to_kernel_tx = timespec_sub(kernel_tx, user_tx);
+	user_to_kernel_tx_sum += user_to_kernel_tx.tv_sec + user_to_kernel_tx.tv_nsec / 1000000000.;
+	kernel_to_user_rx = timespec_sub(user_rx, kernel_rx);
+	kernel_to_user_rx_sum += kernel_to_user_rx.tv_sec + kernel_to_user_rx.tv_nsec / 1000000000.;
+	user_diff = timespec_sub(user_rx, user_tx);
+	user_time_sum += user_diff.tv_sec + user_diff.tv_nsec / 1000000000.;
+	cnt++;
+
+	print_stats("User", canid, user_tx, user_rx, user_diff);
+	print_stats("Kernel", canid, kernel_tx, kernel_rx, kernel_diff);
+	printf("User to kernel TX: %ld.%09ld, kernel to user RX:  %ld.%09ld\n",
+	       timespec_sub(kernel_tx, user_tx).tv_sec,
+	       timespec_sub(kernel_tx, user_tx).tv_nsec,
+	       timespec_sub(user_rx, kernel_rx).tv_sec,
+	       timespec_sub(user_rx, kernel_rx).tv_nsec);
+	printf("[Average] Total: %d, user to kernel (tx): %fs, kernel round trip: %fs, kernel to user (rx): %fs, user round trip: %fs\n\n",
+	       cnt, user_to_kernel_tx_sum / cnt,
+	       kernel_time_sum / cnt, kernel_to_user_rx_sum / cnt,
+	       user_time_sum / cnt);
+}
+
 int main(int argc, char **argv)
 {
 	int soc;
@@ -399,12 +444,8 @@ int main(int argc, char **argv)
 	struct canfd_frame frame;
 	int can_id = 0 /* | CAN_EFF_FLAG */;
 
-	struct timespec kernel_tx, kernel_rx, kernel_diff;
-	struct timespec user_tx, user_rx, user_diff;
-	struct timespec user_to_kernel_tx, kernel_to_user_rx;
-	int cnt = 0;
-	double kernel_time_sum = 0, user_time_sum = 0;
-	double user_to_kernel_tx_sum = 0, kernel_to_user_rx_sum = 0;
+	struct timespec kernel_tx, kernel_rx;
+	struct timespec user_tx, user_rx;
 
 	if (argc != 2)
 		ifname = default_ifname;
@@ -470,34 +511,8 @@ int main(int argc, char **argv)
 		} else if (get_rx_timestamp(soc, &msg, &kernel_rx) == 1) {
 			got_tx_timestamp = false;
 			clock_gettime(CLOCK_REALTIME, &user_rx);
-			kernel_diff = timespec_sub(kernel_rx, kernel_tx);
-			kernel_time_sum += kernel_diff.tv_sec + kernel_diff.tv_nsec / 1000000000.;
-			user_to_kernel_tx = timespec_sub(kernel_tx, user_tx);
-			user_to_kernel_tx_sum += user_to_kernel_tx.tv_sec + user_to_kernel_tx.tv_nsec / 1000000000.;
-			kernel_to_user_rx = timespec_sub(user_rx, kernel_rx);
-			kernel_to_user_rx_sum += kernel_to_user_rx.tv_sec + kernel_to_user_rx.tv_nsec / 1000000000.;
-			user_diff = timespec_sub(user_rx, user_tx);
-			user_time_sum += user_diff.tv_sec + user_diff.tv_nsec / 1000000000.;
-			cnt++;
-			printf("[User] ID: 0x%x, TX: %ld.%09ld, RX: %ld.%09ld, diff: %ld.%09ld\n",
-			       ((struct canfd_frame *)msg.msg_iov->iov_base)->can_id,
-			       user_tx.tv_sec, user_tx.tv_nsec,
-			       user_rx.tv_sec, user_rx.tv_nsec,
-			       user_diff.tv_sec, user_diff.tv_nsec);
-			printf("[Kernel] ID: 0x%x, TX: %ld.%09ld, RX: %ld.%09ld, diff: %ld.%09ld\n",
-			       ((struct canfd_frame *)msg.msg_iov->iov_base)->can_id,
-			       kernel_tx.tv_sec, kernel_tx.tv_nsec,
-			       kernel_rx.tv_sec, kernel_rx.tv_nsec,
-			       kernel_diff.tv_sec, kernel_diff.tv_nsec);
-			printf("User to kernel TX: %ld.%09ld, kernel to user RX:  %ld.%09ld\n",
-			       timespec_sub(kernel_tx, user_tx).tv_sec,
-			       timespec_sub(kernel_tx, user_tx).tv_nsec,
-			       timespec_sub(user_rx, kernel_rx).tv_sec,
-			       timespec_sub(user_rx, kernel_rx).tv_nsec);
-			printf("[Average] Total: %d, user to kernel (tx): %fs, kernel round trip: %fs, kernel to user (rx): %fs, user round trip: %fs\n\n",
-			       cnt, user_to_kernel_tx_sum / cnt,
-			       kernel_time_sum / cnt, kernel_to_user_rx_sum / cnt,
-			       user_time_sum / cnt);
+			calc_and_print_stats(kernel_tx, kernel_rx, user_tx, user_rx,
+					     ((struct canfd_frame *)msg.msg_iov->iov_base)->can_id);
 		}
 	}
 
-- 
2.35.1

[PATCH 2/4] can-roundtrip-stats: remove needless else after continue

[Vincent Mailhol]

The "else" is not needed after the "continue" statements. Remove it.

Signed-off-by: Vincent Mailhol <mailhol.vincent@wanadoo.fr>
---
 can-roundtrip-stats.c | 7 +++----
 1 file changed, 3 insertions(+), 4 deletions(-)

diff --git a/can-roundtrip-stats.c b/can-roundtrip-stats.c
index 1eaed35..9d828d1 100644
--- a/can-roundtrip-stats.c
+++ b/can-roundtrip-stats.c
@@ -503,11 +503,10 @@ int main(int argc, char **argv)
 			if (get_tx_timestamp(soc, &msg, &kernel_tx) == 1) {
 				got_tx_timestamp = true;
 				continue;
-			} else {
-				usleep(100000);
-				clock_gettime(CLOCK_REALTIME, &user_tx);
-				send_canfd_frame_str(soc, can_id++, "", CANFD_BRS);
 			}
+			usleep(100000);
+			clock_gettime(CLOCK_REALTIME, &user_tx);
+			send_canfd_frame_str(soc, can_id++, "", CANFD_BRS);
 		} else if (get_rx_timestamp(soc, &msg, &kernel_rx) == 1) {
 			got_tx_timestamp = false;
 			clock_gettime(CLOCK_REALTIME, &user_rx);
-- 
2.35.1

[PATCH 3/4] can-roundtrip-stats: rewrite the logic of the main loop to make it more robust

[Vincent Mailhol]

The initial version was poorly writen and relied on some dirty hacks
using flags to wait for messages on the socket. Instead, make the
socket blocking (i.e. go back to default and remove O_NONBLOCK flag).

N.B.: error queue is always non-blocking [1]. For this reason, first
check the normal queue. This gives enough time for TX timestamps to
reach the error queue. Use a dirty while loop as a fail-safe in case
the TX timestamps still arrive too late. Would be cleaner to use
poll() or select(). There is room for improvement.

Signed-off-by: Vincent Mailhol <mailhol.vincent@wanadoo.fr>
---
 can-roundtrip-stats.c | 77 ++++++++++++++++++++++++++-----------------
 1 file changed, 46 insertions(+), 31 deletions(-)

diff --git a/can-roundtrip-stats.c b/can-roundtrip-stats.c
index 9d828d1..2e2ff90 100644
--- a/can-roundtrip-stats.c
+++ b/can-roundtrip-stats.c
@@ -270,17 +270,19 @@ int read_can_frame(int soc, struct canfd_frame *frame, int ms_timeout)
 	return -1;
 }
 
+bool is_timestamp_zero(struct timespec ts)
+{
+	return !(ts.tv_sec || ts.tv_nsec);
+}
+
 int get_tx_timestamp(int soc, struct msghdr *msg, struct timespec *tspec)
 {
 	struct cmsghdr *cmsg;
-	static bool warn_once = false;
-	int ret;
+	int i, ret;
 
-	ret = recvmsg(soc, msg, MSG_ERRQUEUE);
+	ret = recvmsg(soc, msg, MSG_ERRQUEUE | 0);
 	if (ret <= 0) {
-		if (!warn_once)
-			perror("recvmsg");
-		warn_once = true;
+		perror("get_tx_timestamp:recvmsg");
 		return ret;
 	} else {
 		struct canfd_frame *frame = msg->msg_iov->iov_base;
@@ -297,8 +299,11 @@ int get_tx_timestamp(int soc, struct msghdr *msg, struct timespec *tspec)
 		switch (cmsg->cmsg_type) {
 		case SCM_TIMESTAMPING:
 			tss = (struct scm_timestamping *)CMSG_DATA(cmsg);
-			debug(1, "SCM_TIMESTAMPING: tss->ts[0]: %lu.%lu\n",
-			      tss->ts[0].tv_sec, tss->ts[0].tv_nsec);
+			for (i = 0;
+			     i < (int)(cmsg->cmsg_len / sizeof(*tss));
+			     i++)
+				debug(1, "SCM_TIMESTAMPING: tss->ts[%d]: %lu.%lu\n",
+				      i, tss->ts[i].tv_sec, tss->ts[i].tv_nsec);
 			*tspec = tss->ts[0];
 			break;
 
@@ -321,20 +326,17 @@ int get_tx_timestamp(int soc, struct msghdr *msg, struct timespec *tspec)
 		}
 	}
 
-	return 1;
+	return is_timestamp_zero(*tspec) ? -ENODATA : 0;
 }
 
 int get_rx_timestamp(int soc, struct msghdr *msg, struct timespec *tspec)
 {
 	struct cmsghdr *cmsg;
-	static bool warn_once = false;
 	int i, ret;
 
 	ret = recvmsg(soc, msg, 0);
 	if (ret <= 0) {
-		if (!warn_once)
-			perror("recvmsg");
-		warn_once = true;
+		perror("get_rx_timestamp:recvmsg");
 		return ret;
 	} else {
 		struct canfd_frame *frame = msg->msg_iov->iov_base;
@@ -342,6 +344,11 @@ int get_rx_timestamp(int soc, struct msghdr *msg, struct timespec *tspec)
 		      frame->can_id, frame->len, data_to_int(frame->data));
 	}
 
+	if (!(msg->msg_flags & MSG_DONTROUTE)) {
+		debug(0, "We are not the sender, ignore the frame");
+		return -ENODATA;
+	}
+
 	for (cmsg = CMSG_FIRSTHDR(msg);
 	     cmsg /* && (cmsg->cmsg_level == SOL_SOCKET) */;
 	     cmsg = CMSG_NXTHDR(msg, cmsg)) {
@@ -360,7 +367,7 @@ int get_rx_timestamp(int soc, struct msghdr *msg, struct timespec *tspec)
 		case SO_TIMESTAMPING:
 			stamp = (struct timespec *)CMSG_DATA(cmsg);
 			for (i = 0;
-			     i < (int)(cmsg->cmsg_len / sizeof(struct timespec));
+			     i < (int)(cmsg->cmsg_len / sizeof(*stamp));
 			     i++)
 				debug(1, "SO_TIMESTAMPING: stamp[%d] = %ld.%09ld\n",
 				      i, stamp[i].tv_sec, stamp[i].tv_nsec);
@@ -372,7 +379,7 @@ int get_rx_timestamp(int soc, struct msghdr *msg, struct timespec *tspec)
 		}
 	}
 
-	return 1;
+	return is_timestamp_zero(*tspec) ? -ENODATA : 0;
 }
 
 void print_stats(const char *timestamp_name, canid_t canid,
@@ -463,7 +470,6 @@ int main(int argc, char **argv)
 
 	addr.can_family = AF_CAN;
 	addr.can_ifindex = ifr.ifr_ifindex;
-	fcntl(soc, F_SETFL, O_NONBLOCK);
 
 	/* try to switch the socket into CAN FD mode */
 	setsockopt(soc, SOL_CAN_RAW, CAN_RAW_FD_FRAMES, &canfd_on, sizeof(canfd_on));
@@ -491,7 +497,7 @@ int main(int argc, char **argv)
 	msg.msg_control = &ctrlmsg;
 
 	while (true) {
-		static bool got_tx_timestamp = false;
+		int ret;
 
 		/* these settings may be modified by recvmsg() */
 		iov.iov_len = sizeof(frame);
@@ -499,20 +505,29 @@ int main(int argc, char **argv)
 		msg.msg_controllen = sizeof(ctrlmsg);
 		msg.msg_flags = 0;
 
-		if (!got_tx_timestamp) {
-			if (get_tx_timestamp(soc, &msg, &kernel_tx) == 1) {
-				got_tx_timestamp = true;
-				continue;
-			}
-			usleep(100000);
-			clock_gettime(CLOCK_REALTIME, &user_tx);
-			send_canfd_frame_str(soc, can_id++, "", CANFD_BRS);
-		} else if (get_rx_timestamp(soc, &msg, &kernel_rx) == 1) {
-			got_tx_timestamp = false;
-			clock_gettime(CLOCK_REALTIME, &user_rx);
-			calc_and_print_stats(kernel_tx, kernel_rx, user_tx, user_rx,
-					     ((struct canfd_frame *)msg.msg_iov->iov_base)->can_id);
-		}
+		/* send new frame */
+		usleep(100000);
+		clock_gettime(CLOCK_REALTIME, &user_tx);
+		send_canfd_frame_str(soc, can_id++, "", CANFD_BRS);
+
+
+		/* Reading from the error queue is always a
+		   non-blocking operation. c.f.:
+		   https://docs.kernel.org/networking/timestamping.html#blocking-read
+		   Read first from the "normal" queue to leave time
+		   for the error queue to be ready.*/
+		get_rx_timestamp(soc, &msg, &kernel_rx);
+
+		/* Empirical tests show that the error queue is always
+		   ready after the "normal" one. This while loop is
+		   just a failsafe.
+		   Yet, TODO: use poll() or select() instead of this
+		   dirty while loop. */
+		while ((ret = get_tx_timestamp(soc, &msg, &kernel_tx)) == -ENODATA);
+
+		clock_gettime(CLOCK_REALTIME, &user_rx);
+		calc_and_print_stats(kernel_tx, kernel_rx, user_tx, user_rx,
+				     ((struct canfd_frame *)msg.msg_iov->iov_base)->can_id);
 	}
 
 	close(soc);
-- 
2.35.1

[PATCH 4/4] can-roundrip-stats: add hardware timestamps information

[Vincent Mailhol]

In addition, add the feature to report both the RX and TX hardware
timestamps. The RX and TX hardware timestamps are equal. This is
because the TX frame and the RX frame are actually the same thing
because of the loopback feature of socket CAN.

Same as before, the feature is hardcoded, but it can be easily
deactivated by commenting out line 56:
| #define HARDWARE_TIMESTAMP

Signed-off-by: Vincent Mailhol <mailhol.vincent@wanadoo.fr>
---
 can-roundtrip-stats.c | 128 +++++++++++++++++++++++++++++++-----------
 1 file changed, 95 insertions(+), 33 deletions(-)

diff --git a/can-roundtrip-stats.c b/can-roundtrip-stats.c
index 2e2ff90..877d8f3 100644
--- a/can-roundtrip-stats.c
+++ b/can-roundtrip-stats.c
@@ -53,6 +53,9 @@
 		__LINE__, __func__, ##args);		\
 })
 
+/* Comment out this line to deactivate Hardware timestamps */
+#define HARDWARE_TIMESTAMP
+
 static inline struct timespec
 timespec_sub(const struct timespec a, const struct timespec b)
 {
@@ -275,7 +278,27 @@ bool is_timestamp_zero(struct timespec ts)
 	return !(ts.tv_sec || ts.tv_nsec);
 }
 
-int get_tx_timestamp(int soc, struct msghdr *msg, struct timespec *tspec)
+enum timestamp_type {
+	NONE = 0x00,
+	SW = 0x01,
+	HW = 0x02
+};
+
+enum timestamp_type get_timestamp_type(struct timespec *sw_ts, struct timespec *hw_ts)
+{
+	enum timestamp_type type = NONE;
+
+	if (!is_timestamp_zero(*sw_ts))
+		type |= SW;
+	if (!is_timestamp_zero(*hw_ts))
+		type |= HW;
+
+
+	return type;
+}
+
+enum timestamp_type get_tx_timestamp(int soc, struct msghdr *msg,
+				     struct timespec *sw_ts, struct timespec *hw_ts)
 {
 	struct cmsghdr *cmsg;
 	int i, ret;
@@ -300,11 +323,14 @@ int get_tx_timestamp(int soc, struct msghdr *msg, struct timespec *tspec)
 		case SCM_TIMESTAMPING:
 			tss = (struct scm_timestamping *)CMSG_DATA(cmsg);
 			for (i = 0;
-			     i < (int)(cmsg->cmsg_len / sizeof(*tss));
+			     i < (int)(cmsg->cmsg_len / sizeof(*tss->ts));
 			     i++)
 				debug(1, "SCM_TIMESTAMPING: tss->ts[%d]: %lu.%lu\n",
 				      i, tss->ts[i].tv_sec, tss->ts[i].tv_nsec);
-			*tspec = tss->ts[0];
+			if (!is_timestamp_zero(tss->ts[0]))
+				*sw_ts = tss->ts[0];
+			if (!is_timestamp_zero(tss->ts[2]))
+				*hw_ts = tss->ts[2];
 			break;
 
 		case PACKET_TX_TIMESTAMP:
@@ -326,10 +352,11 @@ int get_tx_timestamp(int soc, struct msghdr *msg, struct timespec *tspec)
 		}
 	}
 
-	return is_timestamp_zero(*tspec) ? -ENODATA : 0;
+	return get_timestamp_type(sw_ts, hw_ts);
 }
 
-int get_rx_timestamp(int soc, struct msghdr *msg, struct timespec *tspec)
+enum timestamp_type get_rx_timestamp(int soc, struct msghdr *msg,
+				     struct timespec *sw_ts, struct timespec *hw_ts)
 {
 	struct cmsghdr *cmsg;
 	int i, ret;
@@ -360,8 +387,8 @@ int get_rx_timestamp(int soc, struct msghdr *msg, struct timespec *tspec)
 			tv = (struct timeval *)CMSG_DATA(cmsg);
 			debug(1, "SO_TIMESTAMP: stamp = %lu.%06lu\n",
 			      tv->tv_sec, tv->tv_usec);
-			tspec->tv_sec = tv->tv_sec;
-			tspec->tv_nsec = tv->tv_usec * 1000;
+			sw_ts->tv_sec = tv->tv_sec;
+			sw_ts->tv_nsec = tv->tv_usec * 1000;
 			break;
 
 		case SO_TIMESTAMPING:
@@ -371,7 +398,8 @@ int get_rx_timestamp(int soc, struct msghdr *msg, struct timespec *tspec)
 			     i++)
 				debug(1, "SO_TIMESTAMPING: stamp[%d] = %ld.%09ld\n",
 				      i, stamp[i].tv_sec, stamp[i].tv_nsec);
-			*tspec = stamp[0];
+			*sw_ts = stamp[0];
+			*hw_ts = stamp[2];
 			break;
 
 		default:
@@ -379,7 +407,7 @@ int get_rx_timestamp(int soc, struct msghdr *msg, struct timespec *tspec)
 		}
 	}
 
-	return is_timestamp_zero(*tspec) ? -ENODATA : 0;
+	return get_timestamp_type(sw_ts, hw_ts);
 }
 
 void print_stats(const char *timestamp_name, canid_t canid,
@@ -393,36 +421,41 @@ void print_stats(const char *timestamp_name, canid_t canid,
 
 }
 
-void calc_and_print_stats(struct timespec kernel_tx, struct timespec kernel_rx,
-			  struct timespec user_tx, struct timespec user_rx,
-			  canid_t canid)
+void calc_and_print_stats(struct timespec user_tx, struct timespec user_rx,
+			  struct timespec kernel_sw_tx, struct timespec kernel_sw_rx,
+			  struct timespec kernel_hw_tx, struct timespec kernel_hw_rx,
+			  int drop_cnt, canid_t canid)
 {
-	struct timespec kernel_diff, user_diff;
+	struct timespec kernel_sw_diff, kernel_hw_diff, user_diff;
 	struct timespec user_to_kernel_tx, kernel_to_user_rx;
 	static double kernel_time_sum = 0, user_time_sum = 0;
 	static double user_to_kernel_tx_sum = 0, kernel_to_user_rx_sum = 0;
 
 	static int cnt = 0;
 
-	kernel_diff = timespec_sub(kernel_rx, kernel_tx);
-	kernel_time_sum += kernel_diff.tv_sec + kernel_diff.tv_nsec / 1000000000.;
-	user_to_kernel_tx = timespec_sub(kernel_tx, user_tx);
+	kernel_sw_diff = timespec_sub(kernel_sw_rx, kernel_sw_tx);
+	kernel_hw_diff = timespec_sub(kernel_hw_rx, kernel_hw_tx);
+	kernel_time_sum += kernel_sw_diff.tv_sec + kernel_sw_diff.tv_nsec / 1000000000.;
+	user_to_kernel_tx = timespec_sub(kernel_sw_tx, user_tx);
 	user_to_kernel_tx_sum += user_to_kernel_tx.tv_sec + user_to_kernel_tx.tv_nsec / 1000000000.;
-	kernel_to_user_rx = timespec_sub(user_rx, kernel_rx);
+	kernel_to_user_rx = timespec_sub(user_rx, kernel_sw_rx);
 	kernel_to_user_rx_sum += kernel_to_user_rx.tv_sec + kernel_to_user_rx.tv_nsec / 1000000000.;
 	user_diff = timespec_sub(user_rx, user_tx);
 	user_time_sum += user_diff.tv_sec + user_diff.tv_nsec / 1000000000.;
 	cnt++;
 
 	print_stats("User", canid, user_tx, user_rx, user_diff);
-	print_stats("Kernel", canid, kernel_tx, kernel_rx, kernel_diff);
+	print_stats("Kernel Software", canid, kernel_sw_tx, kernel_sw_rx, kernel_sw_diff);
+	if (!(is_timestamp_zero(kernel_hw_tx) || is_timestamp_zero(kernel_hw_rx)))
+		print_stats("Kernel Hardware", canid, kernel_hw_tx, kernel_hw_rx, kernel_hw_diff);
 	printf("User to kernel TX: %ld.%09ld, kernel to user RX:  %ld.%09ld\n",
-	       timespec_sub(kernel_tx, user_tx).tv_sec,
-	       timespec_sub(kernel_tx, user_tx).tv_nsec,
-	       timespec_sub(user_rx, kernel_rx).tv_sec,
-	       timespec_sub(user_rx, kernel_rx).tv_nsec);
-	printf("[Average] Total: %d, user to kernel (tx): %fs, kernel round trip: %fs, kernel to user (rx): %fs, user round trip: %fs\n\n",
-	       cnt, user_to_kernel_tx_sum / cnt,
+	       timespec_sub(kernel_sw_tx, user_tx).tv_sec,
+	       timespec_sub(kernel_sw_tx, user_tx).tv_nsec,
+	       timespec_sub(user_rx, kernel_sw_rx).tv_sec,
+	       timespec_sub(user_rx, kernel_sw_rx).tv_nsec);
+	printf("[Average] Total: %d, drop count: %d, user to kernel (tx): %fs, kernel round trip: %fs, kernel to user (rx): %fs, user round trip: %fs\n\n",
+	       cnt, drop_cnt,
+	       user_to_kernel_tx_sum / cnt,
 	       kernel_time_sum / cnt, kernel_to_user_rx_sum / cnt,
 	       user_time_sum / cnt);
 }
@@ -443,15 +476,26 @@ int main(int argc, char **argv)
 				3 * sizeof(struct timespec) +
 				sizeof(__u32))];
 	const int recv_own_msg = 1;
-	const int timestamping_flags = SOF_TIMESTAMPING_SOFTWARE |
-				       SOF_TIMESTAMPING_TX_SOFTWARE |
-				       SOF_TIMESTAMPING_RX_SOFTWARE |
-				       SOF_TIMESTAMPING_RAW_HARDWARE;
+	const int timestamping_flags_sw = SOF_TIMESTAMPING_SOFTWARE |
+					  SOF_TIMESTAMPING_TX_SOFTWARE |
+					  SOF_TIMESTAMPING_RX_SOFTWARE;
+
+#ifdef HARDWARE_TIMESTAMP
+	const int timestamping_flags_hw = SOF_TIMESTAMPING_TX_HARDWARE |
+					  SOF_TIMESTAMPING_RX_HARDWARE |
+					  SOF_TIMESTAMPING_RAW_HARDWARE |
+					  SOF_TIMESTAMPING_OPT_TX_SWHW;
+
+	const int timestamping_flags = timestamping_flags_sw | timestamping_flags_hw;
+#else
+	const int timestamping_flags = timestamping_flags_sw;
+#endif
 
 	struct canfd_frame frame;
 	int can_id = 0 /* | CAN_EFF_FLAG */;
 
-	struct timespec kernel_tx, kernel_rx;
+	struct timespec kernel_sw_tx, kernel_sw_rx;
+	struct timespec kernel_hw_tx, kernel_hw_rx;
 	struct timespec user_tx, user_rx;
 
 	if (argc != 2)
@@ -497,6 +541,8 @@ int main(int argc, char **argv)
 	msg.msg_control = &ctrlmsg;
 
 	while (true) {
+		static int drop_cnt = 0;
+		enum timestamp_type tx_type = NONE, rx_type = NONE;
 		int ret;
 
 		/* these settings may be modified by recvmsg() */
@@ -510,23 +556,39 @@ int main(int argc, char **argv)
 		clock_gettime(CLOCK_REALTIME, &user_tx);
 		send_canfd_frame_str(soc, can_id++, "", CANFD_BRS);
 
-
 		/* Reading from the error queue is always a
 		   non-blocking operation. c.f.:
 		   https://docs.kernel.org/networking/timestamping.html#blocking-read
 		   Read first from the "normal" queue to leave time
 		   for the error queue to be ready.*/
-		get_rx_timestamp(soc, &msg, &kernel_rx);
+		rx_type |= get_rx_timestamp(soc, &msg, &kernel_sw_rx, &kernel_hw_rx);
 
 		/* Empirical tests show that the error queue is always
 		   ready after the "normal" one. This while loop is
 		   just a failsafe.
 		   Yet, TODO: use poll() or select() instead of this
 		   dirty while loop. */
-		while ((ret = get_tx_timestamp(soc, &msg, &kernel_tx)) == -ENODATA);
+		while ((ret = get_tx_timestamp(soc, &msg, &kernel_sw_tx, &kernel_hw_tx)) < 0);
+		tx_type |= ret;
+
+		if (timestamping_flags & SOF_TIMESTAMPING_OPT_TX_SWHW) {
+			/* Need to unqueue the error queue twice: once for
+			  software and once for hardware timesptamps */
+			while ((ret = get_tx_timestamp(soc, &msg, &kernel_sw_tx, &kernel_hw_tx)) < 0);
+			tx_type |= ret;
+		}
+
+		/* Assert that we got at least the software timestamp
+		   for TX and RX */
+		if (!(rx_type & tx_type & SW)) {
+			drop_cnt++;
+			continue;
+		}
 
 		clock_gettime(CLOCK_REALTIME, &user_rx);
-		calc_and_print_stats(kernel_tx, kernel_rx, user_tx, user_rx,
+		calc_and_print_stats(user_tx, user_rx,
+				     kernel_sw_tx, kernel_sw_rx,
+				     kernel_hw_tx, kernel_hw_rx, drop_cnt,
 				     ((struct canfd_frame *)msg.msg_iov->iov_base)->can_id);
 	}
 
-- 
2.35.1

Re: [PATCH 0/4] can-round-trip-stats

[Marc Kleine-Budde]

[-- Attachment #1: Type: text/plain, Size: 895 bytes --]

On 25.07.2022 22:43:41, Vincent Mailhol wrote:
> This series applies to below branch of Marc's fork of can-utils:
> 
> https://github.com/marckleinebudde/can-utils/tree/can-roundtrip-stats
> 
> It does some cleanup on the can-round-trip-stats in a first time and
> then add the support for hardware timestamps (including TX hardware
> timestamps).
> 
> This series can be helpfull for those of you who want to test the
> kernel patch series which I recently posted:
> https://lore.kernel.org/linux-can/20220725133208.432176-1-mailhol.vincent@wanadoo.fr/T/

Applied and added some more cleanup patches.

Marc

-- 
Pengutronix e.K.                 | Marc Kleine-Budde           |
Embedded Linux                   | https://www.pengutronix.de  |
Vertretung West/Dortmund         | Phone: +49-231-2826-924     |
Amtsgericht Hildesheim, HRA 2686 | Fax:   +49-5121-206917-5555 |

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 488 bytes --]