* [PATCH] tests/qtest: Increase the timeout of the device-introspect-test
@ 2026-10-26 9:23 Thomas Huth
2026-10-26 11:04 ` Alex Bennée
0 siblings, 1 reply; 7+ messages in thread
From: Thomas Huth @ 2026-10-26 9:23 UTC (permalink / raw)
To: Fabiano Rosas; +Cc: Laurent Vivier, qemu-devel
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.
Signed-off-by: Thomas Huth <thuth@redhat.com>
---
tests/qtest/meson.build | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/tests/qtest/meson.build b/tests/qtest/meson.build
index 2d01837ff29..540aa5fc8d3 100644
--- a/tests/qtest/meson.build
+++ b/tests/qtest/meson.build
@@ -3,7 +3,7 @@ slow_qtests = {
'aspeed_smc-test': 360,
'bios-tables-test' : 910,
'cdrom-test' : 610,
- 'device-introspect-test' : 720,
+ 'device-introspect-test' : 840,
'ide-test' : 120,
'migration-test' : 480,
'npcm7xx_pwm-test': 300,
--
2.56.0
^ permalink raw reply related [flat|nested] 7+ messages in thread
* Re: [PATCH] tests/qtest: Increase the timeout of the device-introspect-test
2026-10-26 9:23 [PATCH] tests/qtest: Increase the timeout of the device-introspect-test Thomas Huth
@ 2026-10-26 11:04 ` Alex Bennée
2026-10-26 11:30 ` Thomas Huth
0 siblings, 1 reply; 7+ messages in thread
From: Alex Bennée @ 2026-10-26 11:04 UTC (permalink / raw)
To: Thomas Huth; +Cc: Fabiano Rosas, Laurent Vivier, qemu-devel
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*"
ninja: Entering directory `/home/alex/lsrc/qemu.git/builds/all'
[1/38] Generating qemu-version.h with a custom command (wrapped by meson to capture output)
1/29 qemu:qtest+qtest-avr+slow / qtest-avr/device-introspect-test OK 1.03s 6 subtests passed
2/29 qemu:qtest+qtest-rx+slow / qtest-rx/device-introspect-test OK 1.10s 6 subtests passed
3/29 qemu:qtest+qtest-tricore+slow / qtest-tricore/device-introspect-test OK 1.07s 6 subtests passed
4/29 qemu:qtest+qtest-m68k+slow / qtest-m68k/device-introspect-test OK 1.21s 6 subtests passed
5/29 qemu:qtest+qtest-sparc+slow / qtest-sparc/device-introspect-test OK 1.15s 6 subtests passed
6/29 qemu:qtest+qtest-hexagon+slow / qtest-hexagon/device-introspect-test OK 1.33s 6 subtests passed
7/29 qemu:qtest+qtest-microblaze+slow / qtest-microblaze/device-introspect-test OK 1.32s 6 subtests passed
8/29 qemu:qtest+qtest-sh4eb+slow / qtest-sh4eb/device-introspect-test OK 1.75s 6 subtests passed
9/29 qemu:qtest+qtest-alpha+slow / qtest-alpha/device-introspect-test OK 1.90s 6 subtests passed
10/29 qemu:qtest+qtest-sh4+slow / qtest-sh4/device-introspect-test OK 1.81s 6 subtests passed
11/29 qemu:qtest+qtest-xtensa+slow / qtest-xtensa/device-introspect-test OK 1.77s 6 subtests passed
12/29 qemu:qtest+qtest-hppa+slow / qtest-hppa/device-introspect-test OK 1.89s 6 subtests passed
13/29 qemu:qtest+qtest-mips+slow / qtest-mips/device-introspect-test OK 1.86s 6 subtests passed
14/29 qemu:qtest+qtest-loongarch64+slow / qtest-loongarch64/device-introspect-test OK 1.90s 6 subtests passed
15/29 qemu:qtest+qtest-mips64+slow / qtest-mips64/device-introspect-test OK 1.89s 6 subtests passed
16/29 qemu:qtest+qtest-mipsel+slow / qtest-mipsel/device-introspect-test OK 1.88s 6 subtests passed
17/29 qemu:qtest+qtest-or1k+slow / qtest-or1k/device-introspect-test OK 1.89s 6 subtests passed
18/29 qemu:qtest+qtest-xtensaeb+slow / qtest-xtensaeb/device-introspect-test OK 1.82s 6 subtests passed
19/29 qemu:qtest+qtest-sparc64+slow / qtest-sparc64/device-introspect-test OK 1.88s 6 subtests passed
20/29 qemu:qtest+qtest-mips64el+slow / qtest-mips64el/device-introspect-test OK 2.08s 6 subtests passed
21/29 qemu:qtest+qtest-riscv64+slow / qtest-riscv64/device-introspect-test OK 2.24s 6 subtests passed
22/29 qemu:qtest+qtest-riscv32+slow / qtest-riscv32/device-introspect-test OK 2.35s 6 subtests passed
23/29 qemu:qtest+qtest-ppc+slow / qtest-ppc/device-introspect-test OK 2.46s 6 subtests passed
24/29 qemu:qtest+qtest-ppc64+slow / qtest-ppc64/device-introspect-test OK 2.89s 6 subtests passed
25/29 qemu:qtest+qtest-arm+slow / qtest-arm/device-introspect-test OK 3.26s 6 subtests passed
26/29 qemu:qtest+qtest-aarch64+slow / qtest-aarch64/device-introspect-test OK 3.49s 6 subtests passed
27/29 qemu:qtest+qtest-s390x+slow / qtest-s390x/device-introspect-test OK 3.74s 6 subtests passed
28/29 qemu:qtest+qtest-i386+slow / qtest-i386/device-introspect-test OK 5.36s 6 subtests passed
29/29 qemu:qtest+qtest-x86_64+slow / qtest-x86_64/device-introspect-test OK 5.42s 6 subtests passed
Ok: 29
Expected Fail: 0
Fail: 0
Unexpected Pass: 0
Skipped: 0
Timeout: 0
Full log written to /home/alex/lsrc/qemu.git/builds/all/meson-logs/testlog.txt
________________________________________________________
Executed in 8.20 secs fish external
usr time 30.44 secs 871.00 micros 30.44 secs
sys time 21.28 secs 160.00 micros 21.28 secs
>
> Signed-off-by: Thomas Huth <thuth@redhat.com>
> ---
> tests/qtest/meson.build | 2 +-
> 1 file changed, 1 insertion(+), 1 deletion(-)
>
> diff --git a/tests/qtest/meson.build b/tests/qtest/meson.build
> index 2d01837ff29..540aa5fc8d3 100644
> --- a/tests/qtest/meson.build
> +++ b/tests/qtest/meson.build
> @@ -3,7 +3,7 @@ slow_qtests = {
> 'aspeed_smc-test': 360,
> 'bios-tables-test' : 910,
> 'cdrom-test' : 610,
> - 'device-introspect-test' : 720,
> + 'device-introspect-test' : 840,
> 'ide-test' : 120,
> 'migration-test' : 480,
> 'npcm7xx_pwm-test': 300,
--
Alex Bennée
Virtualisation Tech Lead @ Linaro
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: [PATCH] tests/qtest: Increase the timeout of the device-introspect-test
2026-10-26 11:04 ` Alex Bennée
@ 2026-10-26 11:30 ` Thomas Huth
2026-10-26 13:35 ` Alex Bennée
2026-10-26 15:20 ` Alex Bennée
0 siblings, 2 replies; 7+ messages in thread
From: Thomas Huth @ 2026-10-26 11:30 UTC (permalink / raw)
To: Alex Bennée; +Cc: Fabiano Rosas, Laurent Vivier, qemu-devel
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.
Thomas
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: [PATCH] tests/qtest: Increase the timeout of the device-introspect-test
2026-10-26 11:30 ` Thomas Huth
@ 2026-10-26 13:35 ` Alex Bennée
2026-10-26 15:20 ` Alex Bennée
1 sibling, 0 replies; 7+ messages in thread
From: Alex Bennée @ 2026-10-26 13:35 UTC (permalink / raw)
To: Thomas Huth; +Cc: Fabiano Rosas, Laurent Vivier, qemu-devel
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.
Thanks for that. I did a run to look at the profile but:
0.81% qemu-system-aar [.] object_property_iter_next
0.40% qemu-system-aar [.] qdict_next
0.36% qemu-system-aar [.] qdict_destroy_obj
0.35% IO mon_iothread [.] object_dynamic_cast_assert
0.27% qemu-system-aar [.] object_unref
0.24% qemu-system-aar [.] monitor_puts_locked
0.24% qemu-system-aar [.] quoted_str
0.22% IO mon_iothread [.] json_lexer_feed_char
0.22% IO mon_iothread [.] qio_channel_socket_readv
0.21% IO mon_iothread [.] timerlist_deadline_ns
0.21% qemu-system-aar [.] phys_page_compact
0.19% IO mon_iothread [.] aio_ctx_check
0.18% qemu-system-aar [.] phys_page_set_level
0.18% IO mon_iothread [.] timerlistgroup_deadline_ns
0.16% IO mon_iothread [.] aio_ctx_prepare
0.14% IO mon_iothread [.] tcp_chr_recv
0.13% IO mon_iothread [.] qemu_lockcnt_cmpxchg_or_wait
0.12% IO mon_iothread [.] tcp_chr_read
0.12% qemu-system-aar [.] mod_utf8_codepoint
0.11% qemu-system-aar [.] object_class_property_find
0.09% qemu-system-aar [.] render_memory_region
0.09% qemu-system-aar [.] register_subpage
0.09% IO mon_iothread [.] qemu_lockcnt_dec
0.09% qemu-system-aar [.] qdict_first
0.07% qemu-system-aar [.] object_initialize_with_type
0.07% qemu-system-aar [.] g_hash_table_iter_next@plt
0.06% qemu-system-aar [.] object_dynamic_cast_assert
0.06% IO mon_iothread [.] object_class_dynamic_cast_assert
Nothing is really jumping out at me. So much of the time seems to be
spent in the kernel:
3.91% IO mon_iothread [vdso] [.] __vdso_clock_gettime
3.68% device-introspe libc.so.6 [.] __syscall_cancel_arch
2.73% qemu-system-aar libc.so.6 [.] __memset_avx2_unaligned_erms
2.12% IO mon_iothread libc.so.6 [.] __syscall_cancel_arch
1.93% device-introspe [kernel.kallsyms] [k] __sys_recvfrom
1.82% device-introspe [kernel.kallsyms] [k] _copy_to_iter
1.70% device-introspe [kernel.kallsyms] [k] unix_stream_read_generic
1.67% device-introspe [kernel.kallsyms] [k] do_syscall_64
1.63% device-introspe [kernel.kallsyms] [k] fdget
1.55% device-introspe [kernel.kallsyms] [k] entry_SYSRETQ_unsafe_stack
1.36% IO mon_iothread [kernel.kallsyms] [k] entry_SYSRETQ_unsafe_stack
1.36% qemu-system-aar ld-linux-x86-64.so.2 [.] do_lookup_x
1.22% qemu-system-aar libglib-2.0.so.0.8400.4 [.] g_hash_table_add
1.17% device-introspe [kernel.kallsyms] [k] _raw_spin_lock
1.16% qemu-system-aar libc.so.6 [.] _int_malloc
1.14% IO mon_iothread [kernel.kallsyms] [k] do_syscall_64
1.02% IO mon_iothread [kernel.kallsyms] [k] _copy_from_user
0.99% qemu-system-aar libglib-2.0.so.0.8400.4 [.] g_hash_table_iter_next
0.91% device-introspe [kernel.kallsyms] [k] mutex_lock
0.88% device-introspe device-introspect-test [.] json_lexer_feed_char
0.85% IO mon_iothread [kernel.kallsyms] [k] do_sys_poll
0.84% IO mon_iothread libglib-2.0.so.0.8400.4 [.] 0x000000000005a7b3
0.81% qemu-system-aar qemu-system-aarch64 [.] object_property_iter_next
0.81% IO mon_iothread libglib-2.0.so.0.8400.4 [.] g_mutex_lock
0.78% device-introspe [kernel.kallsyms] [k] fput
0.77% IO mon_iothread [kernel.kallsyms] [k] fput
0.71% qemu-system-aar libc.so.6 [.] malloc
0.70% device-introspe [kernel.kallsyms] [k] __check_object_size
0.68% meson python3.13 [.] _PyEval_EvalFrameDefault
0.66% IO mon_iothread libglib-2.0.so.0.8400.4 [.] g_source_ref
0.65% IO mon_iothread [kernel.kallsyms] [k] fdget
0.63% IO mon_iothread libglib-2.0.so.0.8400.4 [.] g_mutex_unlock
0.59% IO mon_iothread [kernel.kallsyms] [k] _copy_to_iter
0.55% device-introspe [kernel.kallsyms] [k] __virt_addr_valid
0.53% qemu-system-aar libc.so.6 [.] _int_free_chunk
0.53% device-introspe [kernel.kallsyms] [k] entry_SYSCALL_64
0.51% IO mon_iothread [kernel.kallsyms] [k] fdget_pos
0.48% device-introspe [kernel.kallsyms] [k] security_socket_recvmsg
which makes me wonder if there is any low-hanging fruit we could look at
in the amount of IO we are doing for the test?
>
> Thomas
--
Alex Bennée
Virtualisation Tech Lead @ Linaro
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: [PATCH] tests/qtest: Increase the timeout of the device-introspect-test
2026-10-26 11:30 ` Thomas Huth
2026-10-26 13:35 ` Alex Bennée
@ 2026-10-26 15:20 ` Alex Bennée
2026-10-26 16:00 ` Daniel P. Berrangé
1 sibling, 1 reply; 7+ messages in thread
From: Alex Bennée @ 2026-10-26 15:20 UTC (permalink / raw)
To: Thomas Huth; +Cc: Fabiano Rosas, Laurent Vivier, qemu-devel
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.
I think we need to reconsider exactly what it is we are trying to test
here.
>
> Thomas
--
Alex Bennée
Virtualisation Tech Lead @ Linaro
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: [PATCH] tests/qtest: Increase the timeout of the device-introspect-test
2026-10-26 15:20 ` Alex Bennée
@ 2026-10-26 16:00 ` Daniel P. Berrangé
2026-10-26 16:18 ` Daniel P. Berrangé
0 siblings, 1 reply; 7+ messages in thread
From: Daniel P. Berrangé @ 2026-10-26 16:00 UTC (permalink / raw)
To: Alex Bennée; +Cc: Thomas Huth, Fabiano Rosas, Laurent Vivier, qemu-devel
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 :|
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: [PATCH] tests/qtest: Increase the timeout of the device-introspect-test
2026-10-26 16:00 ` Daniel P. Berrangé
@ 2026-10-26 16:18 ` Daniel P. Berrangé
0 siblings, 0 replies; 7+ messages in thread
From: Daniel P. Berrangé @ 2026-10-26 16:18 UTC (permalink / raw)
To: Alex Bennée, Thomas Huth, Fabiano Rosas, Laurent Vivier,
qemu-devel
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 :|
^ permalink raw reply related [flat|nested] 7+ messages in thread
end of thread, other threads:[~2026-10-26 16:19 UTC | newest]
Thread overview: 7+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2026-10-26 9:23 [PATCH] tests/qtest: Increase the timeout of the device-introspect-test Thomas Huth
2026-10-26 11:04 ` Alex Bennée
2026-10-26 11:30 ` Thomas Huth
2026-10-26 13:35 ` Alex Bennée
2026-10-26 15:20 ` Alex Bennée
2026-10-26 16:00 ` Daniel P. Berrangé
2026-10-26 16:18 ` Daniel P. Berrangé
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.