Re: backup transaction with io-thread core dumps

[Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>]

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:95
> 
>>> On March 24, 2020 2:47 PM Max Reitz <mreitz@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, sigh
>>>>> This 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 <dietmar@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