| Message ID | 20200914110948.1425082-1-berrange@redhat.com |
|---|---|
| State | New |
| Headers | show |
| Series | scripts: display how long each test takes to execute | expand |
Patchew URL: https://patchew.org/QEMU/20200914110948.1425082-1-berrange@redhat.com/ Hi, This series seems to have some coding style problems. See output below for more information: Type: series Message-id: 20200914110948.1425082-1-berrange@redhat.com Subject: [PATCH] scripts: display how long each test takes to execute === TEST SCRIPT BEGIN === #!/bin/bash git rev-parse base > /dev/null || exit 0 git config --local diff.renamelimit 0 git config --local diff.renames True git config --local diff.algorithm histogram ./scripts/checkpatch.pl --mailback base.. === TEST SCRIPT END === From https://github.com/patchew-project/qemu * [new tag] patchew/20200914110948.1425082-1-berrange@redhat.com -> patchew/20200914110948.1425082-1-berrange@redhat.com Switched to a new branch 'test' 01009e6 scripts: display how long each test takes to execute === OUTPUT BEGIN === ERROR: line over 90 characters #49: FILE: scripts/mtest2make.py:23: +.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) total: 1 errors, 0 warnings, 8 lines checked Commit 01009e6e23e0 (scripts: display how long each test takes to execute) has style problems, please review. If any of these errors are false positives report them to the maintainer, see CHECKPATCH in MAINTAINERS. === OUTPUT END === Test command exited with code: 1 The full log is available at http://patchew.org/logs/20200914110948.1425082-1-berrange@redhat.com/testing.checkpatch/?type=message. --- Email generated automatically by Patchew [https://patchew.org/]. Please send your feedback to patchew-devel@redhat.com
On 14/09/20 13:09, Daniel P. Berrangé wrote: > I'm unclear if meson's native test runner can print timings. If not, > we might want to submit an RFE there too. I agree that any holes should be filled in there. In this case it does, so I think we should start using it in CI so that RFEs can be sent there. mtest2make-style output has been in use (and good enough) for years so I'd rather avoid piling up more hacks on top. "meson test" is not perfect but I'd rather improve it instead. Paolo > 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 Paolo
On 14/09/2020 13.09, Daniel P. Berrangé wrote: > 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 If I run "make check -j8" in parallel, it's quite hard to match the "TIME xx seconds" lines with the corresponding tests... so could you please in include the test name in the output there? Thanks, Thomas
On Mon, Oct 12, 2020 at 05:07:18PM +0200, Thomas Huth wrote: > On 14/09/2020 13.09, Daniel P. Berrangé wrote: > > 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 > > If I run "make check -j8" in parallel, it's quite hard to match the "TIME xx > seconds" lines with the corresponding tests... so could you please in > include the test name in the output there? I wasn't intending to update this given paolo's negative response to the patch. Regards, Daniel -- |: https://berrange.com -o- https://www.flickr.com/photos/dberrange :| |: https://libvirt.org -o- https://fstop138.berrange.com :| |: https://entangle-photo.org -o- https://www.instagram.com/dberrange :|
On 12/10/20 17:09, Daniel P. Berrangé wrote: > On Mon, Oct 12, 2020 at 05:07:18PM +0200, Thomas Huth wrote: >> On 14/09/2020 13.09, Daniel P. Berrangé wrote: >>> 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: > > I wasn't intending to update this given paolo's negative response to > the patch. FWIW I opened https://github.com/mesonbuild/meson/issues/7830 with ideas on how to improve "meson test". All the items I added are more or less blockers for QEMU, but feel free to add more if you have any ideas from your experience with Libvirt. Paolo
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"
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(-)