Re: [PATCH] tests/qtest: Increase the timeout of the device-introspect-test

["Daniel P. Berrangé" <berrange@redhat.com>]

On Mon, Oct 26, 2026 at 03:20:46PM +0000, Alex Bennée wrote:
> Thomas Huth <thuth@redhat.com> writes:
> 
> > On 26/10/2026 12.04, Alex Bennée wrote:
> >> Thomas Huth <thuth@redhat.com> writes:
> >> 
> >>> I'm occasionally seeing timeouts of the device-introspect-test for
> >>> the aarch64 target when running "make check SPEED=thorough" - looks
> >>> like the 720 seconds aren't enough anymore nowadays. Add 2 more
> >>> minutes to give some more headroom.
> >> What is taking so long, I can run all the introspect builds in under
> >> 10
> >> seconds:
> >>    ➜  time ./run meson test --suite qtest "*device-introspect*"
> >
> > You've got to run the tests in slow/thorough mode:
> >
> > G_TEST_SLOW=1 time ./run meson test --suite qtest "*device-introspect*"
> >
> > otherwise a lot of the tests will be skipped and the tests will finish
> > fast.
> 
>   env G_TEST_SLOW=1 QTEST_QEMU_BINARY=./qemu-system-aarch64 ./run time strace -e trace=read,write,recvfrom,sendto -c /home/alex/lsrc/qemu.git/builds/testing/tests/qtest/device-introspect-test --tap -k
>   ...
>   # slow test /aarch64/device/introspect/concrete/nodefaults/raspi0 executed in 30.19 secs
>   # End of nodefaults tests
>   # End of concrete tests
>   # End of introspect tests
>   # End of device tests
>   # End of aarch64 tests
>   % time     seconds  usecs/call     calls    errors syscall
>   ------ ----------- ----------- --------- --------- ----------------
>    99.61  793.101303           1 420646079           recvfrom
>     0.28    2.229951           3    619529           sendto
>     0.11    0.840259           4    179705           write
>     0.00    0.000000           0        14           read
>   ------ ----------- ----------- --------- --------- ----------------
>   100.00  796.171513           1 421445327           total
>   926.31user 3944.47system 1:28:16elapsed 91%CPU (0avgtext+0avgdata 1132064maxresident)k
>   43824inputs+0outputs (324major+7978563minor)pagefaults 0swaps
> 
> So it looks like the majority of the runtime is just ploughing through
> 420M unix socket calls introspecting the same large set of non user
> creatable devices for every machine type. This will just get bigger and
> bigger every new device or machine we add.

NB, you use G_TEST_SLOW so it iterates over all machines, the
default behaviour is just to test 'none' machine only, but....

...urgh, our JSON client parser reads data off the wire 1 byte
at a time....

recvfrom(6, "{", 1, 0, NULL, NULL)      = 1
recvfrom(6, "\"", 1, 0, NULL, NULL)     = 1
recvfrom(6, "Q", 1, 0, NULL, NULL)      = 1
recvfrom(6, "M", 1, 0, NULL, NULL)      = 1
recvfrom(6, "P", 1, 0, NULL, NULL)      = 1
recvfrom(6, "\"", 1, 0, NULL, NULL)     = 1
recvfrom(6, ":", 1, 0, NULL, NULL)      = 1
recvfrom(6, " ", 1, 0, NULL, NULL)      = 1
recvfrom(6, "{", 1, 0, NULL, NULL)      = 1
recvfrom(6, "\"", 1, 0, NULL, NULL)     = 1
recvfrom(6, "v", 1, 0, NULL, NULL)      = 1
recvfrom(6, "e", 1, 0, NULL, NULL)      = 1
recvfrom(6, "r", 1, 0, NULL, NULL)      = 1
recvfrom(6, "s", 1, 0, NULL, NULL)      = 1
recvfrom(6, "i", 1, 0, NULL, NULL)      = 1
recvfrom(6, "o", 1, 0, NULL, NULL)      = 1
recvfrom(6, "n", 1, 0, NULL, NULL)      = 1
recvfrom(6, "\"", 1, 0, NULL, NULL)     = 1
recvfrom(6, ":", 1, 0, NULL, NULL)      = 1
recvfrom(6, " ", 1, 0, NULL, NULL)      = 1
recvfrom(6, "{", 1, 0, NULL, NULL)      = 1
recvfrom(6, "\"", 1, 0, NULL, NULL)     = 1
recvfrom(6, "q", 1, 0, NULL, NULL)      = 1
recvfrom(6, "e", 1, 0, NULL, NULL)      = 1
recvfrom(6, "m", 1, 0, NULL, NULL)      = 1
recvfrom(6, "u", 1, 0, NULL, NULL)      = 1
recvfrom(6, "\"", 1, 0, NULL, NULL)     = 1
recvfrom(6, ":", 1, 0, NULL, NULL)      = 1
recvfrom(6, " ", 1, 0, NULL, NULL)      = 1
recvfrom(6, "{", 1, 0, NULL, NULL)      = 1
recvfrom(6, "\"", 1, 0, NULL, NULL)     = 1
recvfrom(6, "m", 1, 0, NULL, NULL)      = 1
recvfrom(6, "i", 1, 0, NULL, NULL)      = 1
recvfrom(6, "c", 1, 0, NULL, NULL)      = 1
recvfrom(6, "r", 1, 0, NULL, NULL)      = 1
recvfrom(6, "o", 1, 0, NULL, NULL)      = 1
recvfrom(6, "\"", 1, 0, NULL, NULL)     = 1
recvfrom(6, ":", 1, 0, NULL, NULL)      = 1

> I think we need to reconsider exactly what it is we are trying to test
> here.

I fear this test suite is perhaps just exposing a scalability problem
of our JSON parser. I wonder how much quicker could it be if it read
data in chunks ....

With regards,
Daniel
-- 
|: https://berrange.com       ~~        https://hachyderm.io/@berrange :|
|: https://libvirt.org          ~~          https://entangle-photo.org :|
|: https://pixelfed.art/berrange   ~~    https://fstop138.berrange.com :|