test: Speed up by cutting on eye candy and performance test duration

We have a number of delays when we switch to new layouts that were
added to make the tests visually easier to follow, together with
blinking status bars. Shorten the delays and avoid blinking the
status bar if $FAST is set to 1 (no demo mode).

Shorten delays in busy loops to 10ms, instead of 100ms, and skip the
one-second fixed delay when we wait for the status of a command.

Cut the duration of throughput and latency tests to one second, down
from ten. Somewhat surprisingly, the results we get are rather
consistent, and not significantly different from what we'd get with
10 seconds.

This, together with Podman's commit 20f3e8909e3a ("test/system:
pasta_test_do add explicit port check"), cuts the time needed on my
setup for full test run from approximately 37 minutes to...:

  $ time ./run
  [exited]
  PASS: 165, FAIL: 0
  Log at /home/sbrivio/passt/test/test_logs/test.log

  real	15m34.253s
  user	0m0.011s
  sys	0m0.011s

Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
Reviewed-by: David Gibson <david@gibson.dropbear.id.au>
Tested-by: David Gibson <david@gibson.dropbear.id.au>

test/lib/layout

@@ -15,7 +15,7 @@
 
 # layout_pasta() - Panes for host, pasta, and separate one for namespace
 layout_pasta() {
-	sleep 3
+	sleep 1
 
 	tmux kill-pane -a -t 0
 	cmd_write 0 clear
@@ -46,7 +46,7 @@ layout_pasta() {
 
 # layout_passt() - Panes for host, passt, and guest
 layout_passt() {
-	sleep 3
+	sleep 1
 
 	tmux kill-pane -a -t 0
 	cmd_write 0 clear
@@ -77,7 +77,7 @@ layout_passt() {
 
 # layout_passt_in_pasta() - Host, passt within pasta, namespace and guest
 layout_passt_in_pasta() {
-	sleep 3
+	sleep 1
 
 	tmux kill-pane -a -t 0
 	cmd_write 0 clear
@@ -113,7 +113,7 @@ layout_passt_in_pasta() {
 
 # layout_two_guests() - Two guest panes, two passt panes, plus host and log
 layout_two_guests() {
-	sleep 3
+	sleep 1
 
 	tmux kill-pane -a -t 0
 	cmd_write 0 clear
@@ -152,7 +152,7 @@ layout_two_guests() {
 
 # layout_demo_pasta() - Four panes for pasta demo
 layout_demo_pasta() {
-	sleep 3
+	sleep 1
 
 	cmd_write 0 cd ${BASEPATH}
 	cmd_write 0 clear
@@ -188,7 +188,7 @@ layout_demo_pasta() {
 
 # layout_demo_passt() - Four panes for passt demo
 layout_demo_passt() {
-	sleep 3
+	sleep 1
 
 	cmd_write 0 cd ${BASEPATH}
 	cmd_write 0 clear
@@ -224,7 +224,7 @@ layout_demo_passt() {
 
 # layout_demo_podman() - Four panes for pasta demo with Podman
 layout_demo_podman() {
-	sleep 3
+	sleep 1
 
 	cmd_write 0 cd ${BASEPATH}
 	cmd_write 0 clear

test/lib/term

@@ -97,7 +97,6 @@ display_delay() {
 switch_pane() {
 	tmux select-pane -t ${1}
 	PR_DELAY=${PR_DELAY_INIT}
-	display_delay "0.2"
 }
 
 # cmd_write() - Write a command to a pane, letter by letter, and execute it
@@ -199,7 +198,7 @@ pane_run() {
 # $1:	Pane name
 pane_wait() {
 	__lc="$(echo "${1}" | tr [A-Z] [a-z])"
-	sleep 0.1 || sleep 1
+	sleep 0.01 || sleep 1
 
 	__done=0
 	while
@@ -207,7 +206,7 @@ pane_wait() {
 		case ${__l} in
 		*"$ " | *"# ") return ;;
 		esac
-	do sleep 0.1 || sleep 1; done
+	do sleep 0.01 || sleep 1; done
 }
 
 # pane_parse() - Print last line, @EMPTY@ if command had no output
@@ -231,7 +230,7 @@ pane_status() {
 
 	__status="$(pane_parse "${1}")"
 	while ! [ "${__status}" -eq "${__status}" ] 2>/dev/null; do
-		sleep 1
+		sleep 0.01 || sleep 1
 		pane_run "${1}" 'echo $?'
 		pane_wait "${1}"
 		__status="$(pane_parse "${1}")"
@@ -383,6 +382,16 @@ info_check_failed() {
 	printf " < failed.\n" >> "${LOGFILE}"
 }
 
+# status_bar_blink() - Make status bar blink
+status_bar_blink() {
+	for i in `seq 1 3`; do
+		tmux set status-right-style 'bg=colour1 fg=colour196 bold'
+		sleep 0.1 || sleep 1
+		tmux set status-right-style 'bg=colour1 fg=colour233 bold'
+		sleep 0.1 || sleep 1
+	done
+}
+
 # info_passed() - Display, log, and make status bar blink when a test passes
 info_passed() {
 	switch_pane ${PANE_INFO}
@@ -391,12 +400,7 @@ info_passed() {
 	log "...passed."
 	log
 
-	for i in `seq 1 3`; do
+	[ ${FAST} -eq 1 ] || status_bar_blink
-		tmux set status-right-style 'bg=colour1 fg=colour2 bold'
-		sleep "0.1"
-		tmux set status-right-style 'bg=colour1 fg=colour233 bold'
-		sleep "0.1"
-	done
 }
 
 # info_failed() - Display, log, and make status bar blink when a test passes
@@ -407,12 +411,7 @@ info_failed() {
 	log "...failed."
 	log
 
-	for i in `seq 1 3`; do
+	[ ${FAST} -eq 1 ] || status_bar_blink
-		tmux set status-right-style 'bg=colour1 fg=colour196 bold'
-		sleep "0.1"
-		tmux set status-right-style 'bg=colour1 fg=colour233 bold'
-		sleep "0.1"
-	done
 
 	pause_continue \
 		"Press any key to pause test session"		\

test/lib/test

@@ -33,7 +33,7 @@ test_iperf3k() {
 
 	pane_or_context_run "${__sctx}" 'kill -INT $(cat s.pid); rm s.pid'
 
-	sleep 3		# Wait for kernel to free up ports
+	sleep 1		# Wait for kernel to free up ports
 }
 
 # test_iperf3() - Ugly helper for iperf3 directive

test/pasta_options/log_to_file

@@ -19,7 +19,7 @@ sleep	1
 endef
 
 def	flood_log_client
-host	tcp_crr --nolog -P 10001 -C 10002 -6 -c -H ::1
+host	tcp_crr --nolog -l1 -P 10001 -C 10002 -6 -c -H ::1
 endef
 
 def	check_log_size_mountns
@@ -42,7 +42,7 @@ pout	PID2 echo $!
 check	head -1 __LOG_FILE__ | grep '^pasta .* [(]__PID2__[)]$'
 
 test	Maximum log size
-passtb	./pasta --config-net -d -f -l __LOG_FILE__ --log-size $((100 * 1024)) -- sh -c 'while true; do tcp_crr --nolog -P 10001 -C 10002 -6; done'
+passtb	./pasta --config-net -d -f -l __LOG_FILE__ --log-size $((100 * 1024)) -- sh -c 'while true; do tcp_crr --nolog -l1 -P 10001 -C 10002 -6; done'
 sleep	1
 
 flood_log_client

test/perf/passt_tcp

@@ -38,7 +38,7 @@ hout	FREQ_CPUFREQ (echo "scale=1"; printf '( %i + 10^5 / 2 ) / 10^6\n' $(cat /sy
 hout	FREQ [ -n "__FREQ_CPUFREQ__" ] && echo __FREQ_CPUFREQ__ || echo __FREQ_PROCFS__
 
 set	THREADS 4
-set	TIME 10
+set	TIME 1
 set	OMIT 0.1
 set	OPTS -Z -P __THREADS__ -l 1M -O__OMIT__
 
@@ -75,7 +75,7 @@ lat	-
 lat	-
 lat	-
 nsb	tcp_rr --nolog -6
-gout	LAT tcp_rr --nolog -6 -c -H __GW6__%__IFNAME__ | sed -n 's/^throughput=\(.*\)/\1/p'
+gout	LAT tcp_rr --nolog -l1 -6 -c -H __GW6__%__IFNAME__ | sed -n 's/^throughput=\(.*\)/\1/p'
 lat	__LAT__ 200 150
 
 tl	TCP CRR latency over IPv6: guest to host
@@ -85,7 +85,7 @@ lat	-
 lat	-
 lat	-
 nsb	tcp_crr --nolog -6
-gout	LAT tcp_crr --nolog -6 -c -H __GW6__%__IFNAME__ | sed -n 's/^throughput=\(.*\)/\1/p'
+gout	LAT tcp_crr --nolog -l1 -6 -c -H __GW6__%__IFNAME__ | sed -n 's/^throughput=\(.*\)/\1/p'
 lat	__LAT__ 500 400
 
 tr	TCP throughput over IPv4: guest to host
@@ -119,7 +119,7 @@ lat	-
 lat	-
 lat	-
 nsb	tcp_rr --nolog -4
-gout	LAT tcp_rr --nolog -4 -c -H __GW__ | sed -n 's/^throughput=\(.*\)/\1/p'
+gout	LAT tcp_rr --nolog -l1 -4 -c -H __GW__ | sed -n 's/^throughput=\(.*\)/\1/p'
 lat	__LAT__ 200 150
 
 tl	TCP CRR latency over IPv4: guest to host
@@ -129,7 +129,7 @@ lat	-
 lat	-
 lat	-
 nsb	tcp_crr --nolog -4
-gout	LAT tcp_crr --nolog -4 -c -H __GW__ | sed -n 's/^throughput=\(.*\)/\1/p'
+gout	LAT tcp_crr --nolog -l1 -4 -c -H __GW__ | sed -n 's/^throughput=\(.*\)/\1/p'
 lat	__LAT__ 500 400
 
 tr	TCP throughput over IPv6: host to guest
@@ -153,7 +153,7 @@ lat	-
 lat	-
 guestb	tcp_rr --nolog -P 10001 -C 10011 -6
 sleep	1
-nsout	LAT tcp_rr --nolog -P 10001 -C 10011 -6 -c -H ::1 | sed -n 's/^throughput=\(.*\)/\1/p'
+nsout	LAT tcp_rr --nolog -l1 -P 10001 -C 10011 -6 -c -H ::1 | sed -n 's/^throughput=\(.*\)/\1/p'
 lat	__LAT__ 200 150
 
 tl	TCP CRR latency over IPv6: host to guest
@@ -164,7 +164,7 @@ lat	-
 lat	-
 guestb	tcp_crr --nolog -P 10001 -C 10011 -6
 sleep	1
-nsout	LAT tcp_crr --nolog -P 10001 -C 10011 -6 -c -H ::1 | sed -n 's/^throughput=\(.*\)/\1/p'
+nsout	LAT tcp_crr --nolog -l1 -P 10001 -C 10011 -6 -c -H ::1 | sed -n 's/^throughput=\(.*\)/\1/p'
 lat	__LAT__ 500 350
 
 
@@ -189,7 +189,7 @@ lat	-
 lat	-
 guestb	tcp_rr --nolog -P 10001 -C 10011 -4
 sleep	1
-nsout	LAT tcp_rr --nolog -P 10001 -C 10011 -4 -c -H 127.0.0.1 | sed -n 's/^throughput=\(.*\)/\1/p'
+nsout	LAT tcp_rr --nolog -l1 -P 10001 -C 10011 -4 -c -H 127.0.0.1 | sed -n 's/^throughput=\(.*\)/\1/p'
 lat	__LAT__ 200 150
 
 tl	TCP CRR latency over IPv6: host to guest
@@ -200,7 +200,7 @@ lat	-
 lat	-
 guestb	tcp_crr --nolog -P 10001 -C 10011 -4
 sleep	1
-nsout	LAT tcp_crr --nolog -P 10001 -C 10011 -4 -c -H 127.0.0.1 | sed -n 's/^throughput=\(.*\)/\1/p'
+nsout	LAT tcp_crr --nolog -l1 -P 10001 -C 10011 -4 -c -H 127.0.0.1 | sed -n 's/^throughput=\(.*\)/\1/p'
 lat	__LAT__ 500 300
 
 te

test/perf/passt_udp

@@ -31,7 +31,7 @@ hout	FREQ_CPUFREQ (echo "scale=1"; printf '( %i + 10^5 / 2 ) / 10^6\n' $(cat /sy
 hout	FREQ [ -n "__FREQ_CPUFREQ__" ] && echo __FREQ_CPUFREQ__ || echo __FREQ_PROCFS__
 
 set	THREADS 2
-set	TIME 10
+set	TIME 1
 set	OPTS -u -P __THREADS__ --pacing-timer 1000
 
 info	Throughput in Gbps, latency in µs, __THREADS__ threads at __FREQ__ GHz

test/perf/pasta_tcp

@@ -22,7 +22,7 @@ ns	/sbin/sysctl -w net.ipv4.tcp_timestamps=0
 
 
 set	THREADS 4
-set	TIME 10
+set	TIME 1
 set	OMIT 0.1
 set	OPTS -Z -w 4M -l 1M -P __THREADS__ -O__OMIT__
 
@@ -46,13 +46,13 @@ iperf3k	host
 
 tl	TCP RR latency over IPv6: ns to host
 hostb	tcp_rr --nolog -P 10003 -C 10013 -6
-nsout	LAT tcp_rr --nolog -P 10003 -C 10013 -6 -c -H ::1 | sed -n 's/^throughput=\(.*\)/\1/p'
+nsout	LAT tcp_rr --nolog -l1 -P 10003 -C 10013 -6 -c -H ::1 | sed -n 's/^throughput=\(.*\)/\1/p'
 hostw
 lat	__LAT__ 150 100
 
 tl	TCP CRR latency over IPv6: ns to host
 hostb	tcp_crr --nolog -P 10003 -C 10013 -6
-nsout	LAT tcp_crr --nolog -P 10003 -C 10013 -6 -c -H ::1 | sed -n 's/^throughput=\(.*\)/\1/p'
+nsout	LAT tcp_crr --nolog -l1 -P 10003 -C 10013 -6 -c -H ::1 | sed -n 's/^throughput=\(.*\)/\1/p'
 hostw
 lat	__LAT__ 500 350
 
@@ -67,13 +67,13 @@ iperf3k	host
 
 tl	TCP RR latency over IPv4: ns to host
 hostb	tcp_rr --nolog -P 10003 -C 10013 -4
-nsout	LAT tcp_rr --nolog -P 10003 -C 10013 -4 -c -H 127.0.0.1 | sed -n 's/^throughput=\(.*\)/\1/p'
+nsout	LAT tcp_rr --nolog -l1 -P 10003 -C 10013 -4 -c -H 127.0.0.1 | sed -n 's/^throughput=\(.*\)/\1/p'
 hostw
 lat	__LAT__ 150 100
 
 tl	TCP CRR latency over IPv4: ns to host
 hostb	tcp_crr --nolog -P 10003 -C 10013 -4
-nsout	LAT tcp_crr --nolog -P 10003 -C 10013 -4 -c -H 127.0.0.1 | sed -n 's/^throughput=\(.*\)/\1/p'
+nsout	LAT tcp_crr --nolog -l1 -P 10003 -C 10013 -4 -c -H 127.0.0.1 | sed -n 's/^throughput=\(.*\)/\1/p'
 hostw
 lat	__LAT__ 500 350
 
@@ -87,13 +87,13 @@ iperf3k	ns
 
 tl	TCP RR latency over IPv6: host to ns
 nsb	tcp_rr --nolog -P 10002 -C 10012 -6
-hout	LAT tcp_rr --nolog -P 10002 -C 10012 -6 -c -H ::1 | sed -n 's/^throughput=\(.*\)/\1/p'
+hout	LAT tcp_rr --nolog -l1 -P 10002 -C 10012 -6 -c -H ::1 | sed -n 's/^throughput=\(.*\)/\1/p'
 nsw
 lat	__LAT__ 150 100
 
 tl	TCP CRR latency over IPv6: host to ns
 nsb	tcp_crr --nolog -P 10002 -C 10012 -6
-hout	LAT tcp_crr --nolog -P 10002 -C 10012 -6 -c -H ::1 | sed -n 's/^throughput=\(.*\)/\1/p'
+hout	LAT tcp_crr --nolog -l1 -P 10002 -C 10012 -6 -c -H ::1 | sed -n 's/^throughput=\(.*\)/\1/p'
 nsw
 lat	__LAT__ 1000 700
 
@@ -108,13 +108,13 @@ iperf3k	ns
 
 tl	TCP RR latency over IPv4: host to ns
 nsb	tcp_rr --nolog -P 10002 -C 10012 -4
-hout	LAT tcp_rr --nolog -P 10002 -C 10012 -4 -c -H 127.0.0.1 | sed -n 's/^throughput=\(.*\)/\1/p'
+hout	LAT tcp_rr --nolog -l1 -P 10002 -C 10012 -4 -c -H 127.0.0.1 | sed -n 's/^throughput=\(.*\)/\1/p'
 nsw
 lat	__LAT__ 150 100
 
 tl	TCP CRR latency over IPv4: host to ns
 nsb	tcp_crr --nolog -P 10002 -C 10012 -4
-hout	LAT tcp_crr --nolog -P 10002 -C 10012 -4 -c -H 127.0.0.1 | sed -n 's/^throughput=\(.*\)/\1/p'
+hout	LAT tcp_crr --nolog -l1 -P 10002 -C 10012 -4 -c -H 127.0.0.1 | sed -n 's/^throughput=\(.*\)/\1/p'
 nsw
 lat	__LAT__ 1000 700
 
@@ -156,7 +156,7 @@ lat	-
 lat	-
 lat	-
 hostb	tcp_rr --nolog -P 10003 -C 10013 -6
-nsout	LAT tcp_rr --nolog -P 10003 -C 10013 -6 -c -H __GW6__%__IFNAME__ | sed -n 's/^throughput=\(.*\)/\1/p'
+nsout	LAT tcp_rr --nolog -l1 -P 10003 -C 10013 -6 -c -H __GW6__%__IFNAME__ | sed -n 's/^throughput=\(.*\)/\1/p'
 hostw
 lat	__LAT__ 150 100
 
@@ -165,7 +165,7 @@ lat	-
 lat	-
 lat	-
 hostb	tcp_crr --nolog -P 10003 -C 10013 -6
-nsout	LAT tcp_crr --nolog -P 10003 -C 10013 -6 -c -H __GW6__%__IFNAME__ | sed -n 's/^throughput=\(.*\)/\1/p'
+nsout	LAT tcp_crr --nolog -l1 -P 10003 -C 10013 -6 -c -H __GW6__%__IFNAME__ | sed -n 's/^throughput=\(.*\)/\1/p'
 hostw
 lat	__LAT__ 1500 500
 
@@ -193,7 +193,7 @@ lat	-
 lat	-
 lat	-
 hostb	tcp_rr --nolog -P 10003 -C 10013 -4
-nsout	LAT tcp_rr --nolog -P 10003 -C 10013 -4 -c -H __GW__ | sed -n 's/^throughput=\(.*\)/\1/p'
+nsout	LAT tcp_rr --nolog -l1 -P 10003 -C 10013 -4 -c -H __GW__ | sed -n 's/^throughput=\(.*\)/\1/p'
 hostw
 lat	__LAT__ 150 100
 
@@ -202,7 +202,7 @@ lat	-
 lat	-
 lat	-
 hostb	tcp_crr --nolog -P 10003 -C 10013 -4
-nsout	LAT tcp_crr --nolog -P 10003 -C 10013 -4 -c -H __GW__ | sed -n 's/^throughput=\(.*\)/\1/p'
+nsout	LAT tcp_crr --nolog -l1 -P 10003 -C 10013 -4 -c -H __GW__ | sed -n 's/^throughput=\(.*\)/\1/p'
 hostw
 lat	__LAT__ 1500 500
 
@@ -224,7 +224,7 @@ lat	-
 lat	-
 lat	-
 nsb	tcp_rr --nolog -P 10002 -C 10012 -6
-hout	LAT tcp_rr --nolog -P 10002 -C 10012 -6 -c -H __ADDR6__ | sed -n 's/^throughput=\(.*\)/\1/p'
+hout	LAT tcp_rr --nolog -l1 -P 10002 -C 10012 -6 -c -H __ADDR6__ | sed -n 's/^throughput=\(.*\)/\1/p'
 nsw
 lat	__LAT__ 150 100
 
@@ -234,7 +234,7 @@ lat	-
 lat	-
 sleep	1
 nsb	tcp_crr --nolog -P 10002 -C 10012 -6
-hout	LAT tcp_crr --nolog -P 10002 -C 10012 -6 -c -H __ADDR6__ | sed -n 's/^throughput=\(.*\)/\1/p'
+hout	LAT tcp_crr --nolog -l1 -P 10002 -C 10012 -6 -c -H __ADDR6__ | sed -n 's/^throughput=\(.*\)/\1/p'
 nsw
 lat	__LAT__ 5000 10000
 
@@ -256,7 +256,7 @@ lat	-
 lat	-
 lat	-
 nsb	tcp_rr --nolog -P 10002 -C 10012 -4
-hout	LAT tcp_rr --nolog -P 10002 -C 10012 -4 -c -H __ADDR__ | sed -n 's/^throughput=\(.*\)/\1/p'
+hout	LAT tcp_rr --nolog -l1 -P 10002 -C 10012 -4 -c -H __ADDR__ | sed -n 's/^throughput=\(.*\)/\1/p'
 nsw
 lat	__LAT__ 150 100
 
@@ -266,7 +266,7 @@ lat	-
 lat	-
 sleep	1
 nsb	tcp_crr --nolog -P 10002 -C 10012 -4
-hout	LAT tcp_crr --nolog -P 10002 -C 10012 -4 -c -H __ADDR__ | sed -n 's/^throughput=\(.*\)/\1/p'
+hout	LAT tcp_crr --nolog -l1 -P 10002 -C 10012 -4 -c -H __ADDR__ | sed -n 's/^throughput=\(.*\)/\1/p'
 nsw
 lat	__LAT__ 5000 10000
 

test/perf/pasta_udp

@@ -21,7 +21,7 @@ hout	FREQ_CPUFREQ (echo "scale=1"; printf '( %i + 10^5 / 2 ) / 10^6\n' $(cat /sy
 hout	FREQ [ -n "__FREQ_CPUFREQ__" ] && echo __FREQ_CPUFREQ__ || echo __FREQ_PROCFS__
 
 set	THREADS 1
-set	TIME 10
+set	TIME 1
 set	OPTS -u -P __THREADS__
 
 info	Throughput in Gbps, latency in µs, one thread at __FREQ__ GHz