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

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

On Mon, Oct 26, 2026 at 04:00:17PM +0000, Daniel P. Berrangé wrote:
> 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 ....

To answer my own question - the problem is in tests/qtest/libqmp.c
and fixing it cuts 35% off the normal execution time, and 99% off
the executuion time under strace, with syscalls dropping from 8.6
million to 9 thousand, for a single machine.


This is the change I tested with:

diff --git a/tests/qtest/libqmp.c b/tests/qtest/libqmp.c
index cd12bd26782..d3e2b8f90a4 100644
--- a/tests/qtest/libqmp.c
+++ b/tests/qtest/libqmp.c
@@ -64,6 +64,9 @@ QDict *qmp_fd_receive(int fd)
 {
     QMPResponseParser qmp;
     bool log = qtest_verbose("qmp");
+    static char recvbuf[1024];
+    static size_t recvlen = 0;
+    static size_t recvoff = 0;
 
     qmp.response = NULL;
     json_message_parser_init(&qmp.parser, qmp_response, &qmp, NULL);
@@ -71,15 +74,21 @@ QDict *qmp_fd_receive(int fd)
         ssize_t len;
         char c;
 
-        len = recv(fd, &c, 1, 0);
-        if (len == -1 && errno == EINTR) {
-            continue;
-        }
-
-        if (len == -1 || len == 0) {
-            fprintf(stderr, "Broken pipe\n");
-            abort();
+        if (recvoff == recvlen) {
+            len = recv(fd, recvbuf, G_N_ELEMENTS(recvbuf), 0);
+            if (len == -1 && errno == EINTR) {
+                continue;
+            }
+
+            if (len == -1 || len == 0) {
+                fprintf(stderr, "Broken pipe\n");
+                abort();
+            }
+            recvlen = len;
+            recvoff = 0;
         }
+        c = recvbuf[recvoff];
+        recvoff++;
 
         if (log) {
             g_assert(write(2, &c, 1) == 1);


which is probably not suitable to merge, given that it is assuming
qtest only has a single QMP client connection open at once. THis
will break the migration test at least.

libqmp.c has no global state to pass around, just a raw FD, so
a real fix would have to wrap the FD in a "QTestQMPClient" struct
to allow parallel usage.

Of course 35% off a big number is still a big number, but that's
only a problem with G_TEST_SLOW=1, not the default execution path
for 'make check-qtest' which will only use a single 'none' machine
type.

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