1. Patchew
  2. QEMU
  3. View series

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

Daniel P. Berrangé posted 1 patch 3 years, 7 months ago
Test docker-quick@centos7 failed
Test docker-mingw@fedora failed
Test checkpatch failed
Test FreeBSD failed
Patches applied successfully (tree, apply log)
git fetch https://github.com/patchew-project/qemu tags/patchew/20200914110948.1425082-1-berrange@redhat.com
scripts/mtest2make.py | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
[PATCH] scripts: display how long each test takes to execute
Posted by Daniel P. Berrangé 3 years, 7 months ago 
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
Re: [PATCH] scripts: display how long each test takes to execute
Posted by no-reply@patchew.org 3 years, 7 months ago 
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
Re: [PATCH] scripts: display how long each test takes to execute
Posted by Paolo Bonzini 3 years, 7 months ago 
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
Re: [PATCH] scripts: display how long each test takes to execute
Posted by Daniel P. Berrangé 3 years, 7 months ago 
On Mon, Sep 14, 2020 at 01:19:20PM +0200, Paolo Bonzini wrote:
> 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.

When I run "meson test" it doesn't use the results from the previous
"make", instead it re-compiles the entire codebase using ninja.

If we're telling users to continue to use "make" and "make check" though,
I don't think we should be using "meson test" in the CI systems, as it
means CI is not testing the same build process as our users, which is
defeating the point of CI.

If using "meson compile" and "meson test" already works though, what
is our current ninja -> make convertor doing for us, besides letting
people have a facade to pretend nothing has changed ?


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

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 :|
Re: [PATCH] scripts: display how long each test takes to execute
Posted by Paolo Bonzini 3 years, 7 months ago 
On 14/09/20 13:33, Daniel P. Berrangé wrote:
> On Mon, Sep 14, 2020 at 01:19:20PM +0200, Paolo Bonzini wrote:
>> 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.
> 
> When I run "meson test" it doesn't use the results from the previous
> "make", instead it re-compiles the entire codebase using ninja.

Yes, you'd have to add --no-rebuild.

> If we're telling users to continue to use "make" and "make check" though,
> I don't think we should be using "meson test" in the CI systems, as it
> means CI is not testing the same build process as our users, which is
> defeating the point of CI.

We can of course cover both.

> If using "meson compile" and "meson test" already works though, what
> is our current ninja -> make convertor doing for us, besides letting
> people have a facade to pretend nothing has changed ?

Before unit tests were converted, it was needed because unit tests were
built part with Meson and part with Makefile rules.  Now we still need
the Makefile to build submodules.  Richard posted a patch to build
capstone from meson.build; libfdt can have the same treatment and SLIRP
can be converted to a subproject.  With that gone, there's no reason to
keep the ninja2make converter.

Even before that, it's also possible to send the build to Ninja instead
of using ninja2make.  In that case the Makefile would only spawn
recursive builds using either Make or Ninja.  That would also add a
Ninja build dependency, so I haven't proposed it yet (despite having the
patches ready).

To sum up: the hard part is done, but that means that we have to decide
in what order to do the next steps.

Paolo "what are the Romans doing for us?"
Re: [PATCH] scripts: display how long each test takes to execute
Posted by Thomas Huth 3 years, 6 months ago 
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
Re: [PATCH] scripts: display how long each test takes to execute
Posted by Daniel P. Berrangé 3 years, 6 months ago 
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 :|
Re: [PATCH] scripts: display how long each test takes to execute
Posted by Paolo Bonzini 3 years, 6 months ago 
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

Patchew 2.1-devel-0870f84

© 2016 - 2024 Red Hat, Inc.