[PATCH net 4/4] net/udpgso_bench_tx: audit error queue

[Fred Klassen <fklassen@appneta.com>]

This enhancement adds the '-a' option, which will count all CMSG
messages on the error queue and print a summary report.

Fixes: 3a687bef148d ("selftests: udp gso benchmark")

Example:

    # ./udpgso_bench_tx -4uT -a -l5 -S 1472 -D 172.16.120.189
    udp tx:    492 MB/s     8354 calls/s   8354 msg/s
    udp tx:    477 MB/s     8106 calls/s   8106 msg/s
    udp tx:    488 MB/s     8288 calls/s   8288 msg/s
    udp tx:    882 MB/s    14975 calls/s  14975 msg/s
    Summary over 5.000 seconds ...
    sum udp tx:    696 MB/s      57696 calls (11539/s)  57696 msgs (11539/s)
    Tx Timestamps: received:     57696   errors: 0

This can be useful in tracking loss of messages when under load. For example,
adding the '-z' option results in loss of TX timestamp messages:

    # ./udpgso_bench_tx -4ucT -a -l5 -S 1472 -D 172.16.120.189 -p 3239 -z
    udp tx:    490 MB/s     8325 calls/s   8325 msg/s
    udp tx:    500 MB/s     8492 calls/s   8492 msg/s
    udp tx:    883 MB/s    14985 calls/s  14985 msg/s
    udp tx:    756 MB/s    12823 calls/s  12823 msg/s
    Summary over 5.000 seconds ...
    sum udp tx:    657 MB/s      54429 calls (10885/s)  54429 msgs (10885/s)
    Tx Timestamps: received:     34046   errors: 0
    Zerocopy acks: received:     54422   errors: 0

Fixes: 3a687bef148d ("selftests: udp gso benchmark")
Signed-off-by: Fred Klassen <fklassen@appneta.com>
---
 tools/testing/selftests/net/udpgso_bench_tx.c | 152 +++++++++++++++++++-------
 1 file changed, 113 insertions(+), 39 deletions(-)

diff --git a/tools/testing/selftests/net/udpgso_bench_tx.c b/tools/testing/selftests/net/udpgso_bench_tx.c
index 56e0d890b066..9924342a0b03 100644
--- a/tools/testing/selftests/net/udpgso_bench_tx.c
+++ b/tools/testing/selftests/net/udpgso_bench_tx.c
@@ -62,10 +62,19 @@ static bool	cfg_tcp;
 static uint32_t	cfg_tx_ts = SOF_TIMESTAMPING_TX_SOFTWARE;
 static bool	cfg_tx_tstamp;
 static uint32_t	cfg_tos;
+static bool	cfg_audit;
 static bool	cfg_verbose;
 static bool	cfg_zerocopy;
 static int	cfg_msg_nr;
 static uint16_t	cfg_gso_size;
+static unsigned long total_num_msgs;
+static unsigned long total_num_sends;
+static unsigned long stat_tx_ts;
+static unsigned long stat_tx_ts_errors;
+static unsigned long tstart;
+static unsigned long tend;
+static unsigned long stat_zcopies;
+static unsigned long stat_zcopy_errors;
 
 static socklen_t cfg_alen;
 static struct sockaddr_storage cfg_dst_addr;
@@ -137,8 +146,11 @@ static void flush_cmsg(struct cmsghdr *cmsg)
 			struct my_scm_timestamping *tss;
 
 			tss = (struct my_scm_timestamping *)CMSG_DATA(cmsg);
-			fprintf(stderr, "tx timestamp = %lu.%09lu\n",
-				tss->ts[i].tv_sec, tss->ts[i].tv_nsec);
+			if (tss->ts[i].tv_sec == 0)
+				stat_tx_ts_errors++;
+			if (cfg_verbose)
+				fprintf(stderr, "tx timestamp = %lu.%09lu\n",
+					tss->ts[i].tv_sec, tss->ts[i].tv_nsec);
 		} else {
 			error(1, 0,
 			      "unknown SOL_SOCKET cmsg type=%u level=%u\n",
@@ -157,41 +169,52 @@ static void flush_cmsg(struct cmsghdr *cmsg)
 			switch (err->ee_origin) {
 			case SO_EE_ORIGIN_TIMESTAMPING:
 				// Got a TX timestamp from error queue
-				fprintf(stderr,
-					"got SO_EE_ORIGIN_TIMESTAMPING\n");
+				stat_tx_ts++;
+				if (cfg_verbose)
+					fprintf(stderr,
+						"got SO_EE_ORIGIN_TIMESTAMPING\n");
 				break;
 			case SO_EE_ORIGIN_ICMP:
 			case SO_EE_ORIGIN_ICMP6:
-				fprintf(stderr,
-					"received ICMP error: type=%u, code=%u\n",
-					err->ee_type, err->ee_code);
+				if (cfg_verbose)
+					fprintf(stderr,
+						"received ICMP error: type=%u, code=%u\n",
+						err->ee_type, err->ee_code);
 				break;
 			case SO_EE_ORIGIN_ZEROCOPY:
 			{
 				__u32 lo = err->ee_info;
 				__u32 hi = err->ee_data;
 
-				if (hi == lo - 1)
+				if (hi == lo - 1) {
 					// TX was aborted
-					fprintf(stderr,
-						"Zerocopy TX aborted: lo=%u hi=%u\n",
-						lo, hi);
-				if (hi == lo)
+					stat_zcopy_errors++;
+					if (cfg_verbose)
+						fprintf(stderr,
+							"Zerocopy TX aborted: lo=%u hi=%u\n",
+							lo, hi);
+				} else if (hi == lo) {
 					// single ID acknowledged
-					fprintf(stderr,
-						"Zerocopy TX ack ID: %u\n",
-						lo);
-				else
+					stat_zcopies++;
+					if (cfg_verbose)
+						fprintf(stderr,
+							"Zerocopy TX ack ID: %u\n",
+							lo);
+				} else {
 					// range of IDs acknowledged
-					fprintf(stderr,
-						"Zerocopy TX ack %u IDs %u to %u\n",
-						hi - lo + 1, lo, hi);
+					stat_zcopies += hi - lo + 1;
+					if (cfg_verbose)
+						fprintf(stderr,
+							"Zerocopy TX ack %u IDs %u to %u\n",
+							hi - lo + 1, lo, hi);
+				}
 				break;
 			}
 			case SO_EE_ORIGIN_LOCAL:
-				fprintf(stderr,
-					"received packet with local origin: %u\n",
-					err->ee_origin);
+				if (cfg_verbose)
+					fprintf(stderr,
+						"received packet with local origin: %u\n",
+						err->ee_origin);
 				break;
 			default:
 				error(0, 1,
@@ -236,7 +259,7 @@ static void flush_errqueue_recv(int fd)
 		if (ret == -1)
 			error(1, errno, "errqueue");
 		msg.msg_flags = 0;
-		if (cfg_verbose) {
+		if (cfg_audit || cfg_verbose) {
 			for (cmsg = CMSG_FIRSTHDR(&msg);
 					cmsg;
 					cmsg = CMSG_NXTHDR(&msg, cmsg))
@@ -245,19 +268,21 @@ static void flush_errqueue_recv(int fd)
 	}
 }
 
-static void flush_errqueue(int fd)
+static void flush_errqueue(int fd, const bool do_poll)
 {
-	if (cfg_poll) {
+	if (do_poll) {
 		struct pollfd fds = { 0 };
 		int ret;
 
 		fds.fd = fd;
 		fds.events = POLLERR;
-		ret = poll(&fds, 1, 1000);
-		if (ret == 0)
-			error(1, 0, "poll timeout");
-		else if (ret < 0)
+		ret = poll(&fds, 1, 500);
+		if (ret == 0) {
+			if (cfg_verbose)
+				fprintf(stderr, "poll timeout\n");
+		} else if (ret < 0) {
 			error(1, errno, "poll");
+		}
 	}
 
 	flush_errqueue_recv(fd);
@@ -458,7 +483,7 @@ static int send_udp_segment(int fd, char *data)
 static void usage(const char *filepath)
 {
 	error(1, 0,
-	      "Usage: %s [-46cmHPtTuvz] [-C cpu] [-D dst ip] [-l secs] [-M messagenr] [-p port] [-q tos] [-s sendsize] [-S gsosize]",
+	      "Usage: %s [-46acmHPtTuvz] [-C cpu] [-D dst ip] [-l secs] [-M messagenr] [-p port] [-q tos] [-s sendsize] [-S gsosize]",
 	      filepath);
 }
 
@@ -467,7 +492,7 @@ static void parse_opts(int argc, char **argv)
 	int max_len, hdrlen;
 	int c;
 
-	while ((c = getopt(argc, argv, "46cC:D:Hl:mM:p:s:q:PS:tTuvz")) != -1) {
+	while ((c = getopt(argc, argv, "46acC:D:Hl:mM:p:s:q:PS:tTuvz")) != -1) {
 		switch (c) {
 		case '4':
 			if (cfg_family != PF_UNSPEC)
@@ -481,6 +506,9 @@ static void parse_opts(int argc, char **argv)
 			cfg_family = PF_INET6;
 			cfg_alen = sizeof(struct sockaddr_in6);
 			break;
+		case 'a':
+			cfg_audit = true;
+			break;
 		case 'c':
 			cfg_cache_trash = true;
 			break;
@@ -599,6 +627,51 @@ static void set_tx_timestamping(int fd)
 		error(1, errno, "setsockopt tx timestamping");
 }
 
+static void print_final_report(unsigned long num_msgs, unsigned long num_sends)
+{
+	unsigned long tdelta;
+
+	tdelta = tend - tstart;
+	if (!tdelta)
+		return;
+
+	fprintf(stderr, "Summary over %lu.%03lu seconds ...\n", tdelta / 1000,
+		tdelta % 1000);
+	fprintf(stderr,
+		"sum %s tx: %6lu MB/s %10lu calls (%lu/s) %10lu msgs (%lu/s)\n",
+		cfg_tcp ? "tcp" : "udp",
+		((num_msgs * cfg_payload_len) >> 10) / tdelta,
+		num_sends, num_sends * 1000 / tdelta,
+		num_msgs, num_msgs * 1000 / tdelta);
+	if (cfg_tx_tstamp)
+		fprintf(stderr,
+			"Tx Timestamps: received: %9lu   errors: %lu\n",
+			stat_tx_ts, stat_tx_ts_errors);
+
+	if (cfg_zerocopy)
+		fprintf(stderr,
+			"Zerocopy acks: received: %9lu   errors: %lu\n",
+			stat_zcopies, stat_zcopy_errors);
+}
+
+static void print_report(unsigned long num_msgs, unsigned long num_sends,
+			 const bool final)
+{
+	if (!final)
+		fprintf(stderr,
+			"%s tx: %6lu MB/s %8lu calls/s %6lu msg/s\n",
+			cfg_tcp ? "tcp" : "udp",
+			(num_msgs * cfg_payload_len) >> 20,
+			num_sends, num_msgs);
+
+	if (cfg_audit) {
+		total_num_msgs += num_msgs;
+		total_num_sends += num_sends;
+		if (final)
+			print_final_report(total_num_msgs, total_num_sends);
+	}
+}
+
 int main(int argc, char **argv)
 {
 	unsigned long num_msgs, num_sends;
@@ -640,6 +713,8 @@ int main(int argc, char **argv)
 	num_msgs = 0;
 	num_sends = 0;
 	tnow = gettimeofday_ms();
+	tstart = tnow;
+	tend = tnow;
 	tstop = tnow + cfg_runtime_ms;
 	treport = tnow + 1000;
 
@@ -654,19 +729,15 @@ int main(int argc, char **argv)
 		else
 			num_sends += send_udp(fd, buf[i]);
 		num_msgs++;
-		if ((cfg_zerocopy && (num_msgs & 0xF) == 0) || cfg_tx_tstamp)
-			flush_errqueue(fd);
+		if (cfg_tx_tstamp || (cfg_zerocopy && (num_msgs & 0xF) == 0))
+			flush_errqueue(fd, cfg_poll);
 
 		if (cfg_msg_nr && num_msgs >= cfg_msg_nr)
 			break;
 
 		tnow = gettimeofday_ms();
 		if (tnow > treport) {
-			fprintf(stderr,
-				"%s tx: %6lu MB/s %8lu calls/s %6lu msg/s\n",
-				cfg_tcp ? "tcp" : "udp",
-				(num_msgs * cfg_payload_len) >> 20,
-				num_sends, num_msgs);
+			print_report(num_msgs, num_sends, false);
 			num_msgs = 0;
 			num_sends = 0;
 			treport = tnow + 1000;
@@ -679,10 +750,13 @@ int main(int argc, char **argv)
 	} while (!interrupted && (cfg_runtime_ms == -1 || tnow < tstop));
 
 	if (cfg_zerocopy || cfg_tx_tstamp)
-		flush_errqueue(fd);
+		flush_errqueue(fd, true);
 
 	if (close(fd))
 		error(1, errno, "close");
 
+	tend = tnow;
+	print_report(num_msgs, num_sends, true);
+
 	return 0;
 }
-- 
2.11.0