master: make check buzzes forever in qos-test

[Claudio Fontana]

Hi all,

I see a strange effect on master, with 

cd build
../configure --enable-kvm --enable-debug --enable-tcg 
--target-list=x86_64-softmmu
make -j

make -j check
...

Not run: 220 287
Passed all 121 iotests
[buzzes here]


ps -a
  PID TTY          TIME CMD
 3609 pts/0    00:00:00 make
 4196 pts/0    00:00:00 bash
 4212 pts/0    00:00:00 qos-test
 4215 pts/0    00:00:00 perl
 9025 pts/0    00:00:00 qemu-storage-da
 9027 pts/0    00:00:00 qemu-system-x86
11293 pts/3    00:00:00 ps

/proc/4196/cmdline:
bash -o pipefail -c echo 'Running test qtest-x86_64/qos-test' && 
MALLOC_PERTURB_=${MALLOC_PERTURB_:-$(( ${RANDOM:-0} % 255 + 1))} 
QTEST_QEMU_IMG=./qemu-img 
G_TEST_DBUS_DAEMON=/home/claudio/git/qemu-pristine/qemu/tests/dbus-vmstate-daemon.sh
 QTEST_QEMU_BINARY=./qemu-system-x86_64 
QTEST_QEMU_STORAGE_DAEMON_BINARY=./storage-daemon/qemu-storage-daemon 
tests/qtest/qos-test --tap -k -m quick < /dev/null | ./scripts/tap-driver.pl 
--test-name="qtest-x86_64/qos-test" --show-failures-only
gstack 4196
#0  0x00007f66624e32ba in waitpid () from /lib64/libc.so.6
#1  0x000056036f401bd6 in ?? ()
#2  0x000056036f404416 in wait_for ()
#3  0x000056036f3c8cf3 in execute_command_internal ()
#4  0x000056036f3cb108 in ?? ()
#5  0x000056036f375a83 in ?? ()
#6  0x000056036f3c95a1 in execute_command ()
#7  0x000056036f376484 in ?? ()
#8  0x000056036f3ee706 in parse_and_execute ()
#9  0x000056036f3f86f5 in ?? ()
#10 0x000056036f3bd696 in main ()

/proc/4212/cmdline:
tests/qtest/qos-test --tap -k -m quick
gstack 4212

Thread 2 (Thread 0x7f247fe03700 (LWP 4886)):
#0  0x00007f24818cf839 in syscall () from /lib64/libc.so.6
#1  0x00005617895e6c85 in qemu_futex_wait (f=0x561789663398 
<rcu_call_ready_event>, val=4294967295) at 
/home/claudio/git/qemu-pristine/qemu/include/qemu/futex.h:29
#2  0x00005617895e6e4c in qemu_event_wait (ev=0x561789663398 
<rcu_call_ready_event>) at ../util/qemu-thread-posix.c:480
#3  0x00005617895c3824 in call_rcu_thread (opaque=0x0) at ../util/rcu.c:258
#4  0x00005617895e7006 in qemu_thread_start (args=0x56178a168420) at 
../util/qemu-thread-posix.c:541
#5  0x00007f2481b9c4f9 in start_thread () from /lib64/libpthread.so.0
#6  0x00007f24818d4fbf in clone () from /lib64/libc.so.6
Thread 1 (Thread 0x7f24830ddf40 (LWP 4212)):
#0  0x00007f2481ba5e88 in read () from /lib64/libpthread.so.0
#1  0x00005617895494e8 in qtest_client_socket_recv_line (s=0x56178a1cde00) at 
../tests/qtest/libqtest.c:494
#2  0x0000561789549664 in qtest_rsp_args (s=0x56178a1cde00, expected_args=1) at 
../tests/qtest/libqtest.c:521
#3  0x00005617895499f4 in qtest_query_target_endianness (s=0x56178a1cde00) at 
../tests/qtest/libqtest.c:570
#4  0x0000561789548b72 in qtest_init_without_qmp_handshake 
(extra_args=0x56178a19e2f0 "-M pc  -device 
vhost-user-blk-pci,id=drv0,chardev=char1,addr=4.0 -object 
memory-backend-memfd,id=mem,size=256M,share=on  -M memory-backend=mem -m 256M 
-chardev socket,id=char1,path=/tmp/qtest-4212-soc"...) at 
../tests/qtest/libqtest.c:332
#5  0x0000561789548ba1 in qtest_init (extra_args=0x56178a19e2f0 "-M pc  -device 
vhost-user-blk-pci,id=drv0,chardev=char1,addr=4.0 -object 
memory-backend-memfd,id=mem,size=256M,share=on  -M memory-backend=mem -m 256M 
-chardev socket,id=char1,path=/tmp/qtest-4212-soc"...) at 
../tests/qtest/libqtest.c:339
#6  0x000056178952afb8 in qtest_start (args=0x56178a19e2f0 "-M pc  -device 
vhost-user-blk-pci,id=drv0,chardev=char1,addr=4.0 -object 
memory-backend-memfd,id=mem,size=256M,share=on  -M memory-backend=mem -m 256M 
-chardev socket,id=char1,path=/tmp/qtest-4212-soc"...) at 
../tests/qtest/libqtest-single.h:29
#7  0x000056178952b33c in restart_qemu_or_continue (path=0x56178a19e2f0 "-M pc  
-device vhost-user-blk-pci,id=drv0,chardev=char1,addr=4.0 -object 
memory-backend-memfd,id=mem,size=256M,share=on  -M memory-backend=mem -m 256M 
-chardev socket,id=char1,path=/tmp/qtest-4212-soc"...) at 
../tests/qtest/qos-test.c:105
#8  0x000056178952b4a1 in run_one_test (arg=0x56178a1d7400) at 
../tests/qtest/qos-test.c:178
#9  0x00007f2482a3a826 in ?? () from /usr/lib64/libglib-2.0.so.0
#10 0x00007f2482a3a73b in ?? () from /usr/lib64/libglib-2.0.so.0
#11 0x00007f2482a3a73b in ?? () from /usr/lib64/libglib-2.0.so.0
#12 0x00007f2482a3a73b in ?? () from /usr/lib64/libglib-2.0.so.0
#13 0x00007f2482a3a73b in ?? () from /usr/lib64/libglib-2.0.so.0
#14 0x00007f2482a3a73b in ?? () from /usr/lib64/libglib-2.0.so.0
#15 0x00007f2482a3a73b in ?? () from /usr/lib64/libglib-2.0.so.0
#16 0x00007f2482a3a73b in ?? () from /usr/lib64/libglib-2.0.so.0
#17 0x00007f2482a3a73b in ?? () from /usr/lib64/libglib-2.0.so.0
#18 0x00007f2482a3ace2 in g_test_run_suite () from /usr/lib64/libglib-2.0.so.0
#19 0x00007f2482a3ad01 in g_test_run () from /usr/lib64/libglib-2.0.so.0
#20 0x000056178952b9cb in main (argc=1, argv=0x7ffed7147028, 
envp=0x7ffed7147058) at ../tests/qtest/qos-test.c:338

/proc/4215/cmdline:
perl ./scripts/tap-driver.pl --test-name=qtest-x86_64/qos-test 
--show-failures-only
gstack 4215

#0  0x00007f411d4c8e51 in read () from /lib64/libpthread.so.0
#1  0x000056173781a78d in PerlIOUnix_read ()
#2  0x000056173781dbc8 in PerlIOBuf_fill ()
#3  0x000056173781c2c8 in Perl_PerlIO_fill ()
#4  0x000056173781dac0 in PerlIOBase_read ()
#5  0x000056173781fa98 in PerlIO_getc ()
#6  0x00005617377b5575 in Perl_sv_gets ()
#7  0x00005617377929d8 in Perl_do_readline ()
#8  0x000056173778d8e6 in Perl_runops_standard ()
#9  0x000056173770e7d7 in perl_run ()
#10 0x00005617376e5ef2 in main ()

/proc/9027/cmdline:
./qemu-system-x86_64 -qtest unix:/tmp/qtest-4212.sock -qtest-log /dev/null 
-chardev socket,path=/tmp/qtest-4212.qmp,id=char0 -mon 
chardev=char0,mode=control -display none -M pc -device 
vhost-user-blk-pci,id=drv0,chardev=char1,addr=4.0 -object 
memory-backend-memfd,id=mem,size=256M,share=on -M memory-backend=mem -m 256M 
-chardev socket,id=char1,path=/tmp/qtest-4212-sock.leKGw1 -accel qtest
gstack 9027

Thread 4 (Thread 0x7fced5d8f700 (LWP 9055)):
#0  0x00007fceeef55dcf in do_sigwait () at /lib64/libpthread.so.0
#1  0x00007fceeef55e5d in sigwait () at /lib64/libpthread.so.0
#2  0x000055ba630ed5b7 in dummy_cpu_thread_fn (arg=0x55ba64830600) at 
../accel/dummy-cpus.c:46
#3  0x000055ba63333c1a in qemu_thread_start (args=0x55ba6483d7a0) at 
../util/qemu-thread-posix.c:541
#4  0x00007fceeef4b4f9 in start_thread () at /lib64/libpthread.so.0
#5  0x00007fceeec83fbf in clone () at /lib64/libc.so.6
Thread 3 (Thread 0x7fced6772700 (LWP 9052)):
#0  0x00007fceeec796db in poll () at /lib64/libc.so.6
#1  0x00007fcef5455779 in  () at /usr/lib64/libglib-2.0.so.0
#2  0x00007fcef5455ac2 in g_main_loop_run () at /usr/lib64/libglib-2.0.so.0
#3  0x000055ba6319e03f in iothread_run (opaque=0x55ba64496be0) at 
../iothread.c:73
#4  0x000055ba63333c1a in qemu_thread_start (args=0x55ba6476f2f0) at 
../util/qemu-thread-posix.c:541
#5  0x00007fceeef4b4f9 in start_thread () at /lib64/libpthread.so.0
#6  0x00007fceeec83fbf in clone () at /lib64/libc.so.6
Thread 2 (Thread 0x7fced7074700 (LWP 9038)):
#0  0x00007fceeef54c3d in __lll_lock_wait () at /lib64/libpthread.so.0
#1  0x00007fceeef578a7 in __lll_lock_elision () at /lib64/libpthread.so.0
#2  0x000055ba63332ffb in qemu_mutex_lock_impl (mutex=0x55ba63bb6600 
<qemu_global_mutex>, file=0x55ba63772a1b "../util/rcu.c", line=266) at 
../util/qemu-thread-posix.c:79
#3  0x000055ba631094f1 in qemu_mutex_lock_iothread_impl (file=0x55ba63772a1b 
"../util/rcu.c", line=266) at ../softmmu/cpus.c:493
#4  0x000055ba63303c92 in call_rcu_thread (opaque=0x0) at ../util/rcu.c:266
#5  0x000055ba63333c1a in qemu_thread_start (args=0x55ba644ce520) at 
../util/qemu-thread-posix.c:541
#6  0x00007fceeef4b4f9 in start_thread () at /lib64/libpthread.so.0
#7  0x00007fceeec83fbf in clone () at /lib64/libc.so.6
Thread 1 (Thread 0x7fcef7bee140 (LWP 9027)):
#0  0x00007fceeec796db in poll () at /lib64/libc.so.6
#1  0x00007fcef5455779 in  () at /usr/lib64/libglib-2.0.so.0
#2  0x00007fcef5455ac2 in g_main_loop_run () at /usr/lib64/libglib-2.0.so.0
#3  0x000055ba62fffe2f in vhost_user_read (dev=0x55ba655b3330, 
msg=0x7fff63510230) at ../hw/virtio/vhost-user.c:402
#4  0x000055ba63002512 in vhost_user_get_u64 (dev=0x55ba655b3330, request=1, 
u64=0x7fff63510518) at ../hw/virtio/vhost-user.c:1334
#5  0x000055ba630025c7 in vhost_user_get_features (dev=0x55ba655b3330, 
features=0x7fff63510518) at ../hw/virtio/vhost-user.c:1356
#6  0x000055ba63003b48 in vhost_user_backend_init (dev=0x55ba655b3330, 
opaque=0x55ba655b35b0, errp=0x7fff635106d0) at ../hw/virtio/vhost-user.c:1877
#7  0x000055ba63037c2e in vhost_dev_init (hdev=0x55ba655b3330, 
opaque=0x55ba655b35b0, backend_type=VHOST_BACKEND_TYPE_USER, 
busyloop_timeout=0, errp=0x7fff635106d0) at ../hw/virtio/vhost.c:1302
#8  0x000055ba630dca97 in vhost_user_blk_connect (dev=0x55ba655b30e0, 
errp=0x7fff635106d0) at ../hw/block/vhost-user-blk.c:339
#9  0x000055ba630dcd86 in vhost_user_blk_realize_connect (s=0x55ba655b30e0, 
errp=0x7fff635106d0) at ../hw/block/vhost-user-blk.c:440
#10 0x000055ba630dd195 in vhost_user_blk_device_realize (dev=0x55ba655b30e0, 
errp=0x7fff635106d0) at ../hw/block/vhost-user-blk.c:513
#11 0x000055ba63026405 in virtio_device_realize (dev=0x55ba655b30e0, 
errp=0x7fff63510730) at ../hw/virtio/virtio.c:3659
#12 0x000055ba631845f5 in device_set_realized (obj=0x55ba655b30e0, value=true, 
errp=0x7fff63510838) at ../hw/core/qdev.c:761
#13 0x000055ba6316fed8 in property_set_bool (obj=0x55ba655b30e0, 
v=0x55ba655fed80, name=0x55ba634f3051 "realized", opaque=0x55ba6453a7e0, 
errp=0x7fff63510838) at ../qom/object.c:2257
#14 0x000055ba6316dfe7 in object_property_set (obj=0x55ba655b30e0, 
name=0x55ba634f3051 "realized", v=0x55ba655fed80, errp=0x7fff635109b8) at 
../qom/object.c:1402
#15 0x000055ba6316ab20 in object_property_set_qobject (obj=0x55ba655b30e0, 
name=0x55ba634f3051 "realized", value=0x55ba655fecc0, errp=0x7fff635109b8) at 
../qom/qom-qobject.c:28
#16 0x000055ba6316e34d in object_property_set_bool (obj=0x55ba655b30e0, 
name=0x55ba634f3051 "realized", value=true, errp=0x7fff635109b8) at 
../qom/object.c:1472
#17 0x000055ba6318367b in qdev_realize (dev=0x55ba655b30e0, bus=0x55ba655b3058, 
errp=0x7fff635109b8) at ../hw/core/qdev.c:389
#18 0x000055ba630332f7 in vhost_user_blk_pci_realize (vpci_dev=0x55ba655aae60, 
errp=0x7fff635109b8) at ../hw/virtio/vhost-user-blk-pci.c:66
#19 0x000055ba62e0f8a0 in virtio_pci_realize (pci_dev=0x55ba655aae60, 
errp=0x7fff635109b8) at ../hw/virtio/virtio-pci.c:1907
#20 0x000055ba62dd16ec in pci_qdev_realize (qdev=0x55ba655aae60, 
errp=0x7fff63510a70) at ../hw/pci/pci.c:2148
#21 0x000055ba62e0fc44 in virtio_pci_dc_realize (qdev=0x55ba655aae60, 
errp=0x7fff63510a70) at ../hw/virtio/virtio-pci.c:1992
#22 0x000055ba631845f5 in device_set_realized (obj=0x55ba655aae60, value=true, 
errp=0x7fff63510b78) at ../hw/core/qdev.c:761
#23 0x000055ba6316fed8 in property_set_bool (obj=0x55ba655aae60, 
v=0x55ba655f86f0, name=0x55ba634f3051 "realized", opaque=0x55ba6453a7e0, 
errp=0x7fff63510b78) at ../qom/object.c:2257
#24 0x000055ba6316dfe7 in object_property_set (obj=0x55ba655aae60, 
name=0x55ba634f3051 "realized", v=0x55ba655f86f0, errp=0x55ba63bba880 
<error_fatal>) at ../qom/object.c:1402
#25 0x000055ba6316ab20 in object_property_set_qobject (obj=0x55ba655aae60, 
name=0x55ba634f3051 "realized", value=0x55ba655f86b0, errp=0x55ba63bba880 
<error_fatal>) at ../qom/qom-qobject.c:28
#26 0x000055ba6316e34d in object_property_set_bool (obj=0x55ba655aae60, 
name=0x55ba634f3051 "realized", value=true, errp=0x55ba63bba880 <error_fatal>) 
at ../qom/object.c:1472
#27 0x000055ba6318367b in qdev_realize (dev=0x55ba655aae60, bus=0x55ba649a5000, 
errp=0x55ba63bba880 <error_fatal>) at ../hw/core/qdev.c:389
#28 0x000055ba62f0353b in qdev_device_add (opts=0x55ba645370e0, 
errp=0x55ba63bba880 <error_fatal>) at ../softmmu/qdev-monitor.c:673
#29 0x000055ba62fe4aa2 in device_init_func (opaque=0x0, opts=0x55ba645370e0, 
errp=0x55ba63bba880 <error_fatal>) at ../softmmu/vl.c:1185
#30 0x000055ba63311904 in qemu_opts_foreach (list=0x55ba63ad6280 
<qemu_device_opts>, func=0x55ba62fe4a7b <device_init_func>, opaque=0x0, 
errp=0x55ba63bba880 <error_fatal>) at ../util/qemu-option.c:1135
#31 0x000055ba62fe82e2 in qemu_create_cli_devices () at ../softmmu/vl.c:2624
#32 0x000055ba62fe8406 in qmp_x_exit_preconfig (errp=0x55ba63bba880 
<error_fatal>) at ../softmmu/vl.c:2672
#33 0x000055ba62feaa89 in qemu_init (argc=25, argv=0x7fff63511008, 
envp=0x7fff635110d8) at ../softmmu/vl.c:3692
#34 0x000055ba62bf0ae2 in main (argc=25, argv=0x7fff63511008, 
envp=0x7fff635110d8) at ../softmmu/main.c:49


/proc/9025/cmdline:
./storage-daemon/qemu-storage-daemon --blockdev 
driver=file,node-name=disk0,filename=qtest.X95rzW --export 
type=vhost-user-blk,id=disk0,addr.type=unix,addr.path=/tmp/qtest-4212-sock.leKGw1,node-name=disk0,writable=on,num-queues=1
gstack 9025

Thread 2 (Thread 0x7f1df77a5700 (LWP 9029)):
#0  0x00007f1e06d03839 in syscall () from /lib64/libc.so.6
#1  0x000055d5bd350f93 in qemu_futex_wait (f=0x55d5bd4737f8 
<rcu_call_ready_event>, val=4294967295) at 
/home/claudio/git/qemu-pristine/qemu/include/qemu/futex.h:29
#2  0x000055d5bd35115a in qemu_event_wait (ev=0x55d5bd4737f8 
<rcu_call_ready_event>) at ../util/qemu-thread-posix.c:480
#3  0x000055d5bd325617 in call_rcu_thread (opaque=0x0) at ../util/rcu.c:258
#4  0x000055d5bd351314 in qemu_thread_start (args=0x55d5bf4a4270) at 
../util/qemu-thread-posix.c:541
#5  0x00007f1e06fd04f9 in start_thread () from /lib64/libpthread.so.0
#6  0x00007f1e06d08fbf in clone () from /lib64/libc.so.6
Thread 1 (Thread 0x7f1e0a367e80 (LWP 9025)):
#0  0x00007f1e06cfe7d6 in ppoll () from /lib64/libc.so.6
#1  0x000055d5bd33c593 in qemu_poll_ns (fds=0x55d5bf4aa6c0, nfds=5, timeout=-1) 
at ../util/qemu-timer.c:336
#2  0x000055d5bd343abb in os_host_main_loop_wait (timeout=-1) at 
../util/main-loop.c:250
#3  0x000055d5bd343be1 in main_loop_wait (nonblocking=0) at 
../util/main-loop.c:531
#4  0x000055d5bd1bda5c in main (argc=5, argv=0x7ffcbaf84a28) at 
../storage-daemon/qemu-storage-daemon.c:345

Any idea what could be up?

Thanks,

Claudio