* [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.