[PATCH] scripts: display how long each test takes to execute

[Daniel P . Berrangé]

Sometimes under CI tests non-deterministically take longer to execute
than expected which can trigger timeouts. It is almost impossible to
diagnose this though without seeing execution time for each test case.

With this change, when passing "V=1" to make, we get a duration printed
at test completion:

$ make check V=1
...snip...
MALLOC_PERTURB_=${MALLOC_PERTURB_:-$(( ${RANDOM:-0} % 255 + 1))} 
QTEST_QEMU_IMG=./qemu-img 
G_TEST_DBUS_DAEMON=/home/berrange/src/virt/qemu/tests/dbus-vmstate-daemon.sh 
QTEST_QEMU_BINARY=./qemu-system-x86_64 tests/qtest/migration-test --tap -k
PASS 1 qtest-x86_64: migration-test /x86_64/migration/deprecated
PASS 2 qtest-x86_64: migration-test /x86_64/migration/bad_dest
PASS 3 qtest-x86_64: migration-test /x86_64/migration/fd_proto
PASS 4 qtest-x86_64: migration-test /x86_64/migration/validate_uuid
PASS 5 qtest-x86_64: migration-test /x86_64/migration/validate_uuid_error
PASS 6 qtest-x86_64: migration-test /x86_64/migration/validate_uuid_src_not_set
PASS 7 qtest-x86_64: migration-test /x86_64/migration/validate_uuid_dst_not_set
PASS 8 qtest-x86_64: migration-test /x86_64/migration/auto_converge
PASS 9 qtest-x86_64: migration-test /x86_64/migration/postcopy/unix
PASS 10 qtest-x86_64: migration-test /x86_64/migration/postcopy/recovery
PASS 11 qtest-x86_64: migration-test /x86_64/migration/precopy/unix
PASS 12 qtest-x86_64: migration-test /x86_64/migration/precopy/tcp
PASS 13 qtest-x86_64: migration-test /x86_64/migration/xbzrle/unix
PASS 14 qtest-x86_64: migration-test /x86_64/migration/multifd/tcp/none
PASS 15 qtest-x86_64: migration-test /x86_64/migration/multifd/tcp/cancel
PASS 16 qtest-x86_64: migration-test /x86_64/migration/multifd/tcp/zlib
TIME 28 seconds

Output without V=1 is unchanged.

Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
---

BTW, this script probably needs an update in MAINTAINERS as the
suggested CC's have never touched it.

Also, I feel this is quite a gross hack. If there is a better approach
I'm happy to hear suggestions. I was hoping to modify tap-driver.pl
originally, but then I discovered it doesn't actually invoke the test
program, it merely receives its output so can't track timings.

I'm unclear if meson's native test runner can print timings. If not,
we might want to submit an RFE there too.

 scripts/mtest2make.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/scripts/mtest2make.py b/scripts/mtest2make.py
index 9cbb2e374d..9103ae65b9 100644
--- a/scripts/mtest2make.py
+++ b/scripts/mtest2make.py
@@ -20,7 +20,7 @@ print('''
 SPEED = quick
 
 # $1 = environment, $2 = test command, $3 = test name, $4 = dir
-.test-human-tap = $1 $(if $4,(cd $4 && $2),$2) < /dev/null | 
./scripts/tap-driver.pl --test-name="$3" $(if $(V),,--show-failures-only)
+.test-human-tap = export then=`date +%s` ; $1 $(if $4,(cd $4 && $2),$2) < 
/dev/null | ./scripts/tap-driver.pl --test-name="$3" $(if 
$(V),,--show-failures-only) ; export now=`date +%s` ; delta=`expr $$now - 
$$then` ; $(if $(V),echo "TIME $$delta seconds",true)
 .test-human-exitcode = $1 $(PYTHON) scripts/test-driver.py $(if $4,-C$4) $(if 
$(V),--verbose) -- $2 < /dev/null
 .test-tap-tap = $1 $(if $4,(cd $4 && $2),$2) < /dev/null | sed "s/^[a-z][a-z]* 
[0-9]*/& $3/" || true
 .test-tap-exitcode = printf "%s\\n" 1..1 "`$1 $(if $4,(cd $4 && $2),$2) < 
/dev/null > /dev/null || echo "not "`ok 1 $3"
-- 
2.26.2