From: Andreas Dilger <adilger@whamcloud.com>
Date: Thu, 30 Apr 2020 06:36:21 +0000 (-0600)
Subject: LU-13138 tests: measure 'dd' time more accurately
X-Git-Tag: 2.13.54~119
X-Git-Url: https://git.whamcloud.com/?p=fs%2Flustre-release.git;a=commitdiff_plain;h=43ebfad490a02613ada66c9ac79e80d1d9feaac5;ds=sidebyside

LU-13138 tests: measure 'dd' time more accurately

The sanity test_101d can fail with 'readahead 5s > no-readahead 5s'
because the "do_and_time" function only measures runtime in whole
seconds.  Also, in some rare cases, the VM might be slow and cause
the runtime of the do_and_time() function to be slow, even if the
"dd" command finished quickly.

Instead of timing the duration of "dd" in seconds, parse the output
from "dd" directly, which provides fractional second precision.

Test-Parameters: trivial testlist=sanityn
Signed-off-by: Andreas Dilger <adilger@whamcloud.com>
Change-Id: I5f1ec0374c6a9b9c175db77b2b972e3b433ebbe5
Reviewed-on: https://review.whamcloud.com/38427
Tested-by: jenkins <devops@whamcloud.com>
Tested-by: Maloo <maloo@whamcloud.com>
Reviewed-by: James Nunez <jnunez@whamcloud.com>
Reviewed-by: Wei Liu <sarah@whamcloud.com>
Reviewed-by: Oleg Drokin <green@whamcloud.com>
---

diff --git a/lustre/tests/sanity.sh b/lustre/tests/sanity.sh
index 62a7f89..860e95f 100755
--- a/lustre/tests/sanity.sh
+++ b/lustre/tests/sanity.sh
@@ -9161,17 +9161,21 @@ test_101d() {
 	stack_trap "$LCTL set_param -n llite.*.max_read_ahead_mb $old_RA" EXIT
 	$LCTL get_param -n llite.*.max_read_ahead_mb
 
-	echo Reading the test file $file with read-ahead disabled
+	echo "Reading the test file $file with read-ahead disabled"
 	local sz_KB=$((sz_MB * 1024 / 4))
-	local raOFF=$(do_and_time "dd if=$file of=/dev/null bs=4k count=$sz_KB")
+	# 10485760 bytes transferred in 0.000938 secs (11179579337 bytes/sec)
+	# 104857600 bytes (105 MB) copied, 0.00876352 s, 12.0 GB/s
+	local raOFF=$(LANG=C dd if=$file of=/dev/null bs=4k count=$sz_KB |&
+		      sed -e '/records/d' -e 's/.* \([0-9]*\.[0-9]*\) *s.*/\1/')
 
-	echo Cancel LRU locks on lustre client to flush the client cache
+	echo "Cancel LRU locks on lustre client to flush the client cache"
 	cancel_lru_locks osc
 	echo Enable read-ahead with ${ra_MB}MB
 	$LCTL set_param -n llite.*.max_read_ahead_mb=$ra_MB
 
-	echo Reading the test file $file with read-ahead enabled
-	local raON=$(do_and_time "dd if=$file of=/dev/null bs=4k count=$sz_KB")
+	echo "Reading the test file $file with read-ahead enabled"
+	local raON=$(LANG=C dd if=$file of=/dev/null bs=4k count=$sz_KB |&
+		     sed -e '/records/d' -e 's/.* \([0-9]*\.[0-9]*\) *s.*/\1/')
 
 	echo "read-ahead disabled time read $raOFF"
 	echo "read-ahead enabled time read $raON"
@@ -9179,7 +9183,8 @@ test_101d() {
 	rm -f $file
 	wait_delete_completed
 
-	[ $raOFF -le 1 ] || [ $raON -lt $raOFF ] ||
+	# use awk for this check instead of bash because it handles decimals
+	awk "{ exit !($raOFF < 1.0 || $raOFF > $raON) }" <<<"ignore_me" ||
 		error "readahead ${raON}s > no-readahead ${raOFF}s ${sz_MB}M"
 }
 run_test 101d "file read with and without read-ahead enabled"
diff --git a/lustre/tests/test-framework.sh b/lustre/tests/test-framework.sh
index 17363b1..5868472 100755
--- a/lustre/tests/test-framework.sh
+++ b/lustre/tests/test-framework.sh
@@ -7151,16 +7151,16 @@ multiop_bg_pause() {
 }
 
 do_and_time () {
-    local cmd=$1
-    local rc
-
-    SECONDS=0
-    eval '$cmd'
+	local cmd="$1"
+	local start
+	local rc
 
-    [ ${PIPESTATUS[0]} -eq 0 ] || rc=1
+	start=$SECONDS
+	eval '$cmd'
+	[ ${PIPESTATUS[0]} -eq 0 ] || rc=1
 
-    echo $SECONDS
-    return $rc
+	echo $((SECONDS - start))
+	return $rc
 }
 
 inodes_available () {