25.03.2020 14:40, Stefan Reiter wrote:
On 24/03/2020 17:49, Dietmar Maurer wrote:A more serious issue is that I also get a hang inside the poll loop when the VM is under load. For example, running "stress -d 5" inside the VM (Debian Buster).Then running a simply drive-backup like: { "execute": "drive-backup", "arguments": { "device": "drive-scsi0", "sync": "full", "target": "backup-scsi0.raw" } } At the end of the backup, VM hangs, gdb says: (gdb) bt #0 0x00007ffff5cb3916 in __GI_ppoll (fds=0x7fff63d35c40, nfds=2, timeout=<optimized out>, timeout@entry=0x0, sigmask=sigmask@entry=0x0) at ../sysdeps/unix/sysv/linux/ppoll.c:39 #1 0x0000555555c5f2c9 in ppoll (__ss=0x0, __timeout=0x0, __nfds=<optimized out>, __fds=<optimized out>) at /usr/include/x86_64-linux-gnu/bits/poll2.h:77 #2 0x0000555555c5f2c9 in qemu_poll_ns (fds=<optimized out>, nfds=<optimized out>, timeout=timeout@entry=-1) at util/qemu-timer.c:335 #3 0x0000555555c61ab1 in fdmon_poll_wait (ctx=0x7fffe8905e80, ready_list=0x7fffffffdc68, timeout=-1) at util/fdmon-poll.c:79 #4 0x0000555555c61097 in aio_poll (ctx=0x7fffe8905e80, blocking=blocking@entry=true) at util/aio-posix.c:589 #5 0x0000555555bc2243 in bdrv_do_drained_begin (poll=<optimized out>, ignore_bds_parents=false, parent=0x0, recursive=false, bs=0x7fff671c11c0) at block/io.c:429 #6 0x0000555555bc2243 in bdrv_do_drained_begin (bs=0x7fff671c11c0, recursive=<optimized out>, parent=0x0, ignore_bds_parents=<optimized out>, poll=<optimized out>) at block/io.c:395 #7 0x0000555555bdd132 in bdrv_backup_top_drop (bs=0x7fff671c11c0) at block/backup-top.c:273 #8 0x0000555555bd883c in backup_clean (job=0x7fffe5609a00) at block/backup.c:114 #9 0x0000555555b6d46d in job_clean (job=0x7fffe5609a00) at job.c:657 #10 0x0000555555b6d46d in job_finalize_single (job=0x7fffe5609a00) at job.c:673 #11 0x0000555555b6d46d in job_finalize_single (job=0x7fffe5609a00) at job.c:661 #12 0x0000555555b6dedc in job_txn_apply (txn=<optimized out>, fn=0x555555b6d420 <job_finalize_single>) at job.c:145 #13 0x0000555555b6dedc in job_do_finalize (job=0x7fffe5609a00) at job.c:782 #14 0x0000555555b6e131 in job_completed_txn_success (job=0x7fffe5609a00) at job.c:832 #15 0x0000555555b6e131 in job_completed (job=0x7fffe5609a00) at job.c:845 #16 0x0000555555b6e131 in job_completed (job=0x7fffe5609a00) at job.c:836 #17 0x0000555555b6e190 in job_exit (opaque=0x7fffe5609a00) at job.c:864 #18 0x0000555555c5d855 in aio_bh_call (bh=0x7fffe721a3c0) at util/async.c:164 #19 0x0000555555c5d855 in aio_bh_poll (ctx=ctx@entry=0x7fffe8905e80) at util/async.c:164 #20 0x0000555555c60ede in aio_dispatch (ctx=0x7fffe8905e80) at util/aio-posix.c:380 #21 0x0000555555c5d73e in aio_ctx_dispatch (source=<optimized out>, callback=<optimized out>, user_data=<optimized out>) at util/async.c:298 #22 0x00007ffff7c7ef2e in g_main_context_dispatch () at /usr/lib/x86_64-linux-gnu/libglib-2.0.so.0 #23 0x0000555555c60148 in glib_pollfds_poll () at util/main-loop.c:219 #24 0x0000555555c60148 in os_host_main_loop_wait (timeout=<optimized out>) at util/main-loop.c:242 #25 0x0000555555c60148 in main_loop_wait (nonblocking=nonblocking@entry=0) at util/main-loop.c:518 #26 0x00005555558fc579 in qemu_main_loop () at /home/dietmar/pve5-devel/mirror_qemu/softmmu/vl.c:1665 #27 0x0000555555800c2e in main (argc=<optimized out>, argv=<optimized out>, envp=<optimized out>) at /home/dietmar/pve5-devel/mirror_qemu/softmmu/main.c:49 The VM uses a similar hardware setup with io-threads as the previous example. Is somebody able to reproduce that? And ideas whats wrong here?Can't speak for the original issue, but this one I can reproduce exactly as you say: main thread hangs at the end of a backup job of a drive that uses IO threads, when said drive is under load. Single disk, raw-file backed. I've bisected the issue to commit 00e30f05de1d ("block/backup: use backup-top instead of write notifiers") - CC'ing Vladimir, since he wrote that one. Before that patch, backup works fine. For completeness, here's the trace I get on my machine (latest master) when everything's stuck, Thread 1 is the main thread, 3 the IO thread for the drive: Thread 1 (Thread 0x7ffff5d20680 (LWP 958009)): #0 0x00007ffff6cf2916 in __GI_ppoll (fds=0x7ffff4a0c2c0, nfds=0x2, timeout=<optimized out>, sigmask=0x0) at ../sysdeps/unix/sysv/linux/ppoll.c:39 #1 0x0000555555dba2dd in qemu_poll_ns (fds=0x7ffff4a0c2c0, nfds=0x2, timeout=0xffffffffffffffff) at util/qemu-timer.c:335 #2 0x0000555555dbdb1d in fdmon_poll_wait (ctx=0x7ffff49e3380, ready_list=0x7fffffffdab0, timeout=0xffffffffffffffff) at util/fdmon-poll.c:79 #3 0x0000555555dbd48d in aio_poll (ctx=0x7ffff49e3380, blocking=0x1) at util/aio-posix.c:589 #4 0x0000555555cf5a83 in bdrv_do_drained_begin (bs=0x7fffd1577180, recursive=0x0, parent=0x0, ignore_bds_parents=0x0, poll=0x1) at block/io.c:429
So we wait for some request, as we want to drain... And we are in BDRV_POLL_WHILE loop, which should release aio context before aio_poll() call. So it's strange that thread 3 hangs. Do we loop in BDRV_POLL_WHILE, or we are really hang here? You may print bs->tracked_requests, to see which requests we are waiting for. Requests has co pointers to their coroutines, which may be examined by gdb> source scripts/qemu-gdb.py gdb> qemu coroutine <coroutine-pointer>
#5 0x0000555555cf5aef in bdrv_drained_begin (bs=0x7fffd1577180) at block/io.c:435 #6 0x0000555555d1b135 in bdrv_backup_top_drop (bs=0x7fffd1577180) at block/backup-top.c:273 #7 0x0000555555d14734 in backup_clean (job=0x7ffff49fba00) at block/backup.c:132 #8 0x0000555555c81be5 in job_clean (job=0x7ffff49fba00) at job.c:656 #9 0x0000555555c81c60 in job_finalize_single (job=0x7ffff49fba00) at job.c:672 #10 0x0000555555c80830 in job_txn_apply (txn=0x7fffd1576a80, fn=0x555555c81be8 <job_finalize_single>) at job.c:145 #11 0x0000555555c82017 in job_do_finalize (job=0x7ffff49fba00) at job.c:781 #12 0x0000555555c821b4 in job_completed_txn_success (job=0x7ffff49fba00) at job.c:831 #13 0x0000555555c82254 in job_completed (job=0x7ffff49fba00) at job.c:844 #14 0x0000555555c822a3 in job_exit (opaque=0x7ffff49fba00) at job.c:863 #15 0x0000555555db78a0 in aio_bh_call (bh=0x7ffff3c0d240) at util/async.c:136 #16 0x0000555555db79aa in aio_bh_poll (ctx=0x7ffff49e3380) at util/async.c:164 #17 0x0000555555dbcdae in aio_dispatch (ctx=0x7ffff49e3380) at util/aio-posix.c:380 #18 0x0000555555db7dbc in aio_ctx_dispatch (source=0x7ffff49e3380, callback=0x0, user_data=0x0) at util/async.c:298 #19 0x00007ffff7c8ff2e in g_main_context_dispatch + 0x2ae () at /lib/x86_64-linux-gnu/libglib-2.0.so.0 #20 0x0000555555dbb360 in glib_pollfds_poll () at util/main-loop.c:219 #21 0x0000555555dbb3da in os_host_main_loop_wait (timeout=0x3b9aca00) at util/main-loop.c:242 #22 0x0000555555dbb4df in main_loop_wait (nonblocking=0x0) at util/main-loop.c:518 #23 0x0000555555947478 in qemu_main_loop () at /root/qemu/softmmu/vl.c:1665 #24 0x0000555555d58ddf in main (argc=0x15, argv=0x7fffffffe058, envp=0x7fffffffe108) at /root/qemu/softmmu/main.c:49 Thread 3 (Thread 0x7ffff497e700 (LWP 958039)):
Print the mutex content, to see who holds it.
#0 0x00007ffff6dd629c in __lll_lock_wait + 0x1c () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:103 #1 0x00007ffff6dcf7d1 in __GI___pthread_mutex_lock (mutex=0x7ffff49e36e0) at ../nptl/pthread_mutex_lock.c:115 #2 0x0000555555dc0ad7 in qemu_mutex_lock_impl (mutex=0x7ffff49e36e0, file=0x555555f66501 "util/async.c", line=0x254) at util/qemu-thread-posix.c:78 #3 0x0000555555db872e in aio_context_acquire (ctx=0x7ffff49e3680) at util/async.c:596 #4 0x0000555555db905e in thread_pool_completion_bh (opaque=0x7ffff3c0c000) at util/thread-pool.c:167 #5 0x0000555555db78a0 in aio_bh_call (bh=0x7ffff49d7f20) at util/async.c:136 #6 0x0000555555db79aa in aio_bh_poll (ctx=0x7ffff49e3680) at util/async.c:164 #7 0x0000555555dbd673 in aio_poll (ctx=0x7ffff49e3680, blocking=0x1) at util/aio-posix.c:638 #8 0x00005555559d7611 in iothread_run (opaque=0x7ffff49b1c80) at iothread.c:75 #9 0x0000555555dc1650 in qemu_thread_start (args=0x7ffff58ea480) at util/qemu-thread-posix.c:519 #10 0x00007ffff6dccfa3 in start_thread (arg=<optimized out>) at pthread_create.c:486 #11 0x00007ffff6cfd4cf in clone + 0x3f () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95On March 24, 2020 2:47 PM Max Reitz <mre...@redhat.com> wrote: Hi Dietmar, I assume this is with master and has popped up only recently? Maybe it has something to do with the recent mutex patches by Stefan, so I’m Cc-ing him. Max On 24.03.20 14:33, Dietmar Maurer wrote:spoke too soon - the error is still there, sighThis is fixed with this patch: https://lists.gnu.org/archive/html/qemu-devel/2020-03/msg07249.html thanks!On March 24, 2020 12:13 PM Dietmar Maurer <diet...@proxmox.com> wrote: I get a core dump with backup transactions when using io-threads. To reproduce, create and start a VM with: # qemu-img create disk1.raw 100M # qemu-img create disk2.raw 100M #./x86_64-softmmu/qemu-system-x86_64 -chardev 'socket,id=qmp,path=/var/run/qemu-test.qmp,server,nowait' -mon 'chardev=qmp,mode=control' -pidfile /var/run/qemu-server/108.pid -m 512 -object 'iothread,id=iothread-virtioscsi0' -object 'iothread,id=iothread-virtioscsi1' -device 'virtio-scsi-pci,id=virtioscsi0,iothread=iothread-virtioscsi0' -drive 'file=disk1.raw,if=none,id=drive-scsi0,format=raw,cache=none,aio=native,detect-zeroes=on' -device 'scsi-hd,bus=virtioscsi0.0,channel=0,scsi-id=0,lun=0,drive=drive-scsi0,id=scsi0' -device 'virtio-scsi-pci,id=virtioscsi1,iothread=iothread-virtioscsi1' -drive 'file=disk2.raw,if=none,id=drive-scsi1,format=raw,cache=none,aio=native,detect-zeroes=on' -device 'scsi-hd,bus=virtioscsi1.0,channel=0,scsi-id=0,lun=1,drive=drive-scsi1,id=scsi1' Then open socat to the qmp socket # socat /var/run/qemu-test.qmp - And run the following qmp command: { "execute": "qmp_capabilities", "arguments": {} } { "execute": "transaction", "arguments": { "actions": [{ "type": "drive-backup", "data": { "device": "drive-scsi0", "sync": "full", "target": "backup-sysi0.raw" }}, { "type": "drive-backup", "data": { "device": "drive-scsi1", "sync": "full", "target": "backup-scsi1.raw" }}], "properties": { "completion-mode": "grouped" } } } The VM will core dump: qemu: qemu_mutex_unlock_impl: Operation not permitted Aborted (core dumped) (gdb) bt #0 0x00007f099d5037bb in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #1 0x00007f099d4ee535 in __GI_abort () at abort.c:79 #2 0x000055c04e39525e in error_exit (err=<optimized out>, msg=msg@entry=0x55c04e5122e0 <__func__.16544> "qemu_mutex_unlock_impl") at util/qemu-thread-posix.c:36 #3 0x000055c04e395813 in qemu_mutex_unlock_impl (mutex=mutex@entry=0x7f09903154e0, file=file@entry=0x55c04e51129f "util/async.c", line=line@entry=601) at util/qemu-thread-posix.c:108 #4 0x000055c04e38f8e5 in aio_context_release (ctx=ctx@entry=0x7f0990315480) at util/async.c:601 #5 0x000055c04e299073 in bdrv_set_aio_context_ignore (bs=0x7f0929a76500, new_context=new_context@entry=0x7f0990315000, ignore=ignore@entry=0x7ffe08fa7400) at block.c:6238 #6 0x000055c04e2990cc in bdrv_set_aio_context_ignore (bs=bs@entry=0x7f092af47900, new_context=new_context@entry=0x7f0990315000, ignore=ignore@entry=0x7ffe08fa7400) at block.c:6211 #7 0x000055c04e299443 in bdrv_child_try_set_aio_context (bs=bs@entry=0x7f092af47900, ctx=0x7f0990315000, ignore_child=ignore_child@entry=0x0, errp=errp@entry=0x0) at block.c:6324 #8 0x000055c04e299576 in bdrv_try_set_aio_context (errp=0x0, ctx=<optimized out>, bs=0x7f092af47900) at block.c:6333 #9 0x000055c04e299576 in bdrv_replace_child (child=child@entry=0x7f09902ef5e0, new_bs=new_bs@entry=0x0) at block.c:2551 #10 0x000055c04e2995ff in bdrv_detach_child (child=0x7f09902ef5e0) at block.c:2666 #11 0x000055c04e299ec9 in bdrv_root_unref_child (child=<optimized out>) at block.c:2677 #12 0x000055c04e29f3fe in block_job_remove_all_bdrv (job=job@entry=0x7f0927c18800) at blockjob.c:191 #13 0x000055c04e29f429 in block_job_free (job=0x7f0927c18800) at blockjob.c:88 #14 0x000055c04e2a0909 in job_unref (job=0x7f0927c18800) at job.c:359 #15 0x000055c04e2a0909 in job_unref (job=0x7f0927c18800) at job.c:351 #16 0x000055c04e2a0b68 in job_conclude (job=0x7f0927c18800) at job.c:620 #17 0x000055c04e2a0b68 in job_finalize_single (job=0x7f0927c18800) at job.c:688 #18 0x000055c04e2a0b68 in job_finalize_single (job=0x7f0927c18800) at job.c:660 #19 0x000055c04e2a14fc in job_txn_apply (txn=<optimized out>, fn=0x55c04e2a0a50 <job_finalize_single>) at job.c:145 #20 0x000055c04e2a14fc in job_do_finalize (job=0x7f0927c1c200) at job.c:781 #21 0x000055c04e2a1751 in job_completed_txn_success (job=0x7f0927c1c200) at job.c:831 #22 0x000055c04e2a1751 in job_completed (job=0x7f0927c1c200) at job.c:844 #23 0x000055c04e2a1751 in job_completed (job=0x7f0927c1c200) at job.c:835 #24 0x000055c04e2a17b0 in job_exit (opaque=0x7f0927c1c200) at job.c:863 #25 0x000055c04e38ee75 in aio_bh_call (bh=0x7f098ec52000) at util/async.c:164 #26 0x000055c04e38ee75 in aio_bh_poll (ctx=ctx@entry=0x7f0990315000) at util/async.c:164 #27 0x000055c04e3924fe in aio_dispatch (ctx=0x7f0990315000) at util/aio-posix.c:380 #28 0x000055c04e38ed5e in aio_ctx_dispatch (source=<optimized out>, callback=<optimized out>, user_data=<optimized out>) at util/async.c:298 #29 0x00007f099f020f2e in g_main_context_dispatch () at /usr/lib/x86_64-linux-gnu/libglib-2.0.so.0 #30 0x000055c04e391768 in glib_pollfds_poll () at util/main-loop.c:219 #31 0x000055c04e391768 in os_host_main_loop_wait (timeout=<optimized out>) at util/main-loop.c:242 #32 0x000055c04e391768 in main_loop_wait (nonblocking=nonblocking@entry=0) at util/main-loop.c:518 #33 0x000055c04e032329 in qemu_main_loop () at /home/dietmar/pve5-devel/mirror_qemu/softmmu/vl.c:1665 #34 0x000055c04df36a8e in main (argc=<optimized out>, argv=<optimized out>, envp=<optimized out>) at /home/dietmar/pve5-devel/mirror_qemu/softmmu/main.c:49
-- Best regards, Vladimir