[PATCH net-next 1/2] selftests: net: fix timestamp not arriving in cmsg_time.sh

[PATCH net-next 1/2] selftests: net: fix timestamp not arriving in cmsg_time.sh

[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.

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'

Signed-off-by: Jakub Kicinski <kuba@kernel.org>
---
CC: shuah@kernel.org
CC: linux-kselftest@vger.kernel.org
---
 tools/testing/selftests/net/cmsg_sender.c | 20 +++++++++++++++-----
 1 file changed, 15 insertions(+), 5 deletions(-)

diff --git a/tools/testing/selftests/net/cmsg_sender.c b/tools/testing/selftests/net/cmsg_sender.c
index c79e65581dc3..f25268504937 100644
--- a/tools/testing/selftests/net/cmsg_sender.c
+++ b/tools/testing/selftests/net/cmsg_sender.c
@@ -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:
-- 
2.45.0

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

[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'

Signed-off-by: Jakub Kicinski <kuba@kernel.org>
---
CC: shuah@kernel.org
CC: linux-kselftest@vger.kernel.org
---
 tools/testing/selftests/net/cmsg_sender.c | 32 +++++++++++++----------
 tools/testing/selftests/net/cmsg_time.sh  |  7 +++--
 2 files changed, 23 insertions(+), 16 deletions(-)

diff --git a/tools/testing/selftests/net/cmsg_sender.c b/tools/testing/selftests/net/cmsg_sender.c
index f25268504937..b2df05ef71cb 100644
--- a/tools/testing/selftests/net/cmsg_sender.c
+++ b/tools/testing/selftests/net/cmsg_sender.c
@@ -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[])
diff --git a/tools/testing/selftests/net/cmsg_time.sh b/tools/testing/selftests/net/cmsg_time.sh
index af85267ad1e3..1d7e756644bc 100755
--- a/tools/testing/selftests/net/cmsg_time.sh
+++ b/tools/testing/selftests/net/cmsg_time.sh
@@ -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
-- 
2.45.0

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

[Willem de Bruijn]

Jakub Kicinski wrote:
> 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'
> 
> Signed-off-by: Jakub Kicinski <kuba@kernel.org>

Reviewed-by: Willem de Bruijn <willemb@google.com>

Re: [PATCH net-next 1/2] selftests: net: fix timestamp not arriving in cmsg_time.sh

[Willem de Bruijn]

Jakub Kicinski 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.
> 
> This fixes the "TXTIME abs" failures on debug kernels, like:
> 
>    Case ICMPv4  - TXTIME abs returned '', expected 'OK'
> 
> Signed-off-by: Jakub Kicinski <kuba@kernel.org>

Reviewed-by: Willem de Bruijn <willemb@google.com>

> diff --git a/tools/testing/selftests/net/cmsg_sender.c b/tools/testing/selftests/net/cmsg_sender.c
> index c79e65581dc3..f25268504937 100644
> --- a/tools/testing/selftests/net/cmsg_sender.c
> +++ b/tools/testing/selftests/net/cmsg_sender.c
> @@ -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

Re: [PATCH net-next 1/2] selftests: net: fix timestamp not arriving in cmsg_time.sh

[Jakub Kicinski]

On Thu, 09 May 2024 22:49:50 -0400 Willem de Bruijn wrote:
> >  	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!

Re: [PATCH net-next 1/2] selftests: net: fix timestamp not arriving in cmsg_time.sh

[patchwork-bot+netdevbpf]

Hello:

This series was applied to netdev/net-next.git (main)
by Jakub Kicinski <kuba@kernel.org>:

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!
-- 
Deet-doot-dot, I am a bot.
https://korg.docs.kernel.org/patchwork/pwbot.html