Skip to contentSkip to conversation

selftests: net: fix timestamp not arriving in cmsg_time.sh

PATCH Applied Jakub Kicinski 3 participants 6 messages May 10, 2024 – May 11, 2024

Subsystems (3)
lore
Share & tools
lore

Jakub Kicinski

author maintainer
#0 lore raw

PATCH 1/2 selftests: net: fix timestamp not arriving in cmsg_time.sh

On slow machines the SND timestamp sometimes doesn't arrive before we quit. The test only waits as long as the packet delay, so it's easy for a race condition to happen.

Double the wait but do a bit of polling, once the SND timestamp arrives there's no point to wait any longer.

This fixes the "TXTIME abs" failures on debug kernels, like:

Case ICMPv4 - TXTIME abs returned '', expected 'OK'

---
CC: [email protected]
CC: [email protected]

---
 tools/testing/selftests/net/cmsg_sender.c | 20 +++++++++++++++-----
 1 file changed, 15 insertions(+), 5 deletions(-)
tools/testing/selftests/net/cmsg_sender.c +15 -5
index c79e65581dc3..f25268504937 100644
@@ -333,16 +333,17 @@ static const char *cs_ts_info2str(unsigned int info)
 	return "unknown";
 }
 
-static void
+static unsigned long
 cs_read_cmsg(int fd, struct msghdr *msg, char *cbuf, size_t cbuf_sz)
 {
 	struct sock_extended_err *see;
 	struct scm_timestamping *ts;
+	unsigned int ts_seen = 0;
 	struct cmsghdr *cmsg;
 	int i, err;
 
 	if (!opt.ts.ena)
-		return;
+		return 0;
 	msg->msg_control = cbuf;
 	msg->msg_controllen = cbuf_sz;
 
@@ -396,8 +397,11 @@ cs_read_cmsg(int fd, struct msghdr *msg, char *cbuf, size_t cbuf_sz)
 			printf(" %5s ts%d %lluus\n",
 			       cs_ts_info2str(see->ee_info),
 			       i, rel_time);
+			ts_seen |= 1 << see->ee_info;
 		}
 	}
+
+	return ts_seen;
 }
 
 static void ca_set_sockopts(int fd)
@@ -509,10 +513,16 @@ int main(int argc, char *argv[])
 	err = ERN_SUCCESS;
 
 	if (opt.ts.ena) {
-		/* Make sure all timestamps have time to loop back */
-		usleep(opt.txtime.delay);
+		unsigned long seen;
+		int i;
 
-		cs_read_cmsg(fd, &msg, cbuf, sizeof(cbuf));
+		/* Make sure all timestamps have time to loop back */
+		for (i = 0; i < 40; i++) {
+			seen = cs_read_cmsg(fd, &msg, cbuf, sizeof(cbuf));
+			if (seen & (1 << SCM_TSTAMP_SND))
+				break;
+			usleep(opt.txtime.delay / 20);
+		}
 	}
 
 err_out:
Signature · 1 line
2.45.0
author maintainer
#1 lore raw

PATCH 2/2 selftests: net: increase the delay for relative cmsg_time.sh test

Slow machines can delay scheduling of the packets for milliseconds. Increase the delay to 8ms if KSFT_MACHINE_SLOW. Try to limit the variability by moving setsockopts earlier (before we read time).

This fixes the "TXTIME rel" failures on debug kernels, like:

Case ICMPv4 - TXTIME rel returned '', expected 'OK'

---
CC: [email protected]
CC: [email protected]

---
 tools/testing/selftests/net/cmsg_sender.c | 32 +++++++++++++----------
 tools/testing/selftests/net/cmsg_time.sh  |  7 +++--
 2 files changed, 23 insertions(+), 16 deletions(-)
tools/testing/selftests/net/cmsg_sender.c +18 -14
index f25268504937..b2df05ef71cb 100644
@@ -260,15 +260,8 @@ cs_write_cmsg(int fd, struct msghdr *msg, char *cbuf, size_t cbuf_sz)
 			  SOL_IPV6, IPV6_HOPLIMIT, &opt.v6.hlimit);
 
 	if (opt.txtime.ena) {
-		struct sock_txtime so_txtime = {
-			.clockid = CLOCK_MONOTONIC,
-		};
 		__u64 txtime;
 
-		if (setsockopt(fd, SOL_SOCKET, SO_TXTIME,
-			       &so_txtime, sizeof(so_txtime)))
-			error(ERN_SOCKOPT, errno, "setsockopt TXTIME");
-
 		txtime = time_start_mono.tv_sec * (1000ULL * 1000 * 1000) +
 			 time_start_mono.tv_nsec +
 			 opt.txtime.delay * 1000;
@@ -284,13 +277,6 @@ cs_write_cmsg(int fd, struct msghdr *msg, char *cbuf, size_t cbuf_sz)
 		memcpy(CMSG_DATA(cmsg), &txtime, sizeof(txtime));
 	}
 	if (opt.ts.ena) {
-		__u32 val = SOF_TIMESTAMPING_SOFTWARE |
-			    SOF_TIMESTAMPING_OPT_TSONLY;
-
-		if (setsockopt(fd, SOL_SOCKET, SO_TIMESTAMPING,
-			       &val, sizeof(val)))
-			error(ERN_SOCKOPT, errno, "setsockopt TIMESTAMPING");
-
 		cmsg = (struct cmsghdr *)(cbuf + cmsg_len);
 		cmsg_len += CMSG_SPACE(sizeof(__u32));
 		if (cbuf_sz < cmsg_len)
@@ -426,6 +412,24 @@ static void ca_set_sockopts(int fd)
 	    setsockopt(fd, SOL_SOCKET, SO_PRIORITY,
 		       &opt.sockopt.priority, sizeof(opt.sockopt.priority)))
 		error(ERN_SOCKOPT, errno, "setsockopt SO_PRIORITY");
+
+	if (opt.txtime.ena) {
+		struct sock_txtime so_txtime = {
+			.clockid = CLOCK_MONOTONIC,
+		};
+
+		if (setsockopt(fd, SOL_SOCKET, SO_TXTIME,
+			       &so_txtime, sizeof(so_txtime)))
+			error(ERN_SOCKOPT, errno, "setsockopt TXTIME");
+	}
+	if (opt.ts.ena) {
+		__u32 val = SOF_TIMESTAMPING_SOFTWARE |
+			SOF_TIMESTAMPING_OPT_TSONLY;
+
+		if (setsockopt(fd, SOL_SOCKET, SO_TIMESTAMPING,
+			       &val, sizeof(val)))
+			error(ERN_SOCKOPT, errno, "setsockopt TIMESTAMPING");
+	}
 }
 
 int main(int argc, char *argv[])
tools/testing/selftests/net/cmsg_time.sh +5 -2
index af85267ad1e3..1d7e756644bc 100755
@@ -66,10 +66,13 @@ for i in "-4 $TGT4" "-6 $TGT6"; do
 		 awk '/SND/ { if ($3 > 1000) print "OK"; }')
 	check_result $? "$ts" "OK" "$prot - TXTIME abs"
 
-	ts=$(ip netns exec $NS ./cmsg_sender -p $p $i 1234 -t -d 1000 |
+	[ "$KSFT_MACHINE_SLOW" = yes ] && delay=8000 || delay=1000
+
+	ts=$(ip netns exec $NS ./cmsg_sender -p $p $i 1234 -t -d $delay |
 		 awk '/SND/ {snd=$3}
 		      /SCHED/ {sch=$3}
-		      END { if (snd - sch > 500) print "OK"; }')
+		      END { if (snd - sch > '$((delay/2))') print "OK";
+			    else print snd, "-", sch, "<", '$((delay/2))'; }')
 	check_result $? "$ts" "OK" "$prot - TXTIME rel"
     done
 done
Signature · 1 line
2.45.0
Reviewed-by on v1 2/2
#2 lore raw

Re: [PATCH net-next 2/2] selftests: net: increase the delay for relative cmsg_time.sh test

Quoted 9 lines · Jakub Kicinski

Slow machines can delay scheduling of the packets for milliseconds. Increase the delay to 8ms if KSFT_MACHINE_SLOW. Try to limit the variability by moving setsockopts earlier (before we read time).

This fixes the "TXTIME rel" failures on debug kernels, like:

Case ICMPv4 - TXTIME rel returned '', expected 'OK'

Reviewed-by on v1 1/2
#3 lore raw
In reply to Jakub Kicinski
Quoted 4 lines · Jakub Kicinski

On slow machines the SND timestamp sometimes doesn't arrive before we quit. The test only waits as long as the packet delay, so it's easy for a race condition to happen.

Quoted 8 lines

Double the wait but do a bit of polling, once the SND timestamp arrives there's no point to wait any longer.

This fixes the "TXTIME abs" failures on debug kernels, like:

Case ICMPv4 - TXTIME abs returned '', expected 'OK'

Quoted 5 lines
tools/testing/selftests/net/cmsg_sender.c +0 -0
index c79e65581dc3..f25268504937 100644

tools/testing/selftests/net/cmsg_sender.c static const char *cs_ts_info2str(unsigned int info) · line 341

Quoted 10 lines
tools/testing/selftests/net/cmsg_sender.c +2 -1
@@ -333,16 +333,17 @@ static const char *cs_ts_info2str(unsigned int info)
 	return "unknown";
 }
 
-static void
+static unsigned long
 cs_read_cmsg(int fd, struct msghdr *msg, char *cbuf, size_t cbuf_sz)
 {
 	struct sock_extended_err *see;
 	struct scm_timestamping *ts;
+	unsigned int ts_seen = 0;

nit: mixing unsigned long and unsigned int

author maintainer
#4 lore raw
Quoted 5 lines · On Thu, 09 May 2024 22:49:50 -0400 Willem de Bruijn wrote:

tools/testing/selftests/net/cmsg_sender.c static const char *cs_ts_info2str(unsigned int info) · line 341

Quoted 3 lines
tools/testing/selftests/net/cmsg_sender.c +1 -0
 	struct sock_extended_err *see;
 	struct scm_timestamping *ts;
+	unsigned int ts_seen = 0;  

nit: mixing unsigned long and unsigned int

Fixed when applying, thanks!

#5 lore raw
In reply to Jakub Kicinski
This series was applied to netdev/net-next.git (main) by Jakub Kicinski <[email protected]>:

Hello:

This series was applied to netdev/net-next.git (main) by Jakub Kicinski <[email protected]>:

Quoted 8 lines · On Thu, 9 May 2024 17:57:04 -0700 you wrote:

On slow machines the SND timestamp sometimes doesn't arrive before we quit. The test only waits as long as the packet delay, so it's easy for a race condition to happen.

Double the wait but do a bit of polling, once the SND timestamp arrives there's no point to wait any longer.

[...]

Here is the summary with links:
- [net-next,1/2] selftests: net: fix timestamp not arriving in cmsg_time.sh

    https://git.kernel.org/netdev/net-next/c/2d3b8dfd82d7
  - [net-next,2/2] selftests: net: increase the delay for relative cmsg_time.sh test
    https://git.kernel.org/netdev/net-next/c/b9d5f5711dd8

You are awesome, thank you!

Signature · 2 lines
Deet-doot-dot, I am a bot.
https://korg.docs.kernel.org/patchwork/pwbot.html