Re: bdrv_drained_begin deadlock with io-threads

[Vladimir Sementsov-Ogievskiy]

31.03.2020 17:32, Dietmar Maurer wrote:
> > > After a few iteration the VM freeze inside bdrv_drained_begin():
> > >
> > > Thread 1 (Thread 0x7fffe9291080 (LWP 30949)):
> > > #0  0x00007ffff5cb3916 in __GI_ppoll (fds=0x7fff63d30c40, nfds=2, 
> > > timeout=<optimized out>, timeout@entry=0x0, sigmask=sigmask@entry=0x0) at 
> > > ../sysdeps/unix/sysv/linux/ppoll.c:39
> > > #1  0x0000555555c60419 in ppoll (__ss=0x0, __timeout=0x0, __nfds=<optimized out>, 
> > > __fds=<optimized out>) at /usr/include/x86_64-linux-gnu/bits/poll2.h:77
> > > #2  0x0000555555c60419 in qemu_poll_ns (fds=<optimized out>, nfds=<optimized 
> > > out>, timeout=timeout@entry=-1) at util/qemu-timer.c:335
> > > #3  0x0000555555c62c01 in fdmon_poll_wait (ctx=0x7fffe8905e80, 
> > > ready_list=0x7fffffffd3a8, timeout=-1) at util/fdmon-poll.c:79
> > > #4  0x0000555555c621e7 in aio_poll (ctx=0x7fffe8905e80, 
> > > blocking=blocking@entry=true) at util/aio-posix.c:589
> > > #5  0x0000555555bc2565 in bdrv_do_drained_begin (poll=<optimized out>, 
> > > ignore_bds_parents=false, parent=0x0, recursive=false, bs=0x7fff67240b80) at 
> > > block/io.c:430
> > > #6  0x0000555555bc2565 in bdrv_do_drained_begin (bs=0x7fff67240b80, recursive=<optimized 
> > > out>, parent=0x0, ignore_bds_parents=<optimized out>, poll=<optimized out>) at 
> > > block/io.c:395
> > > #7  0x0000555555bde252 in bdrv_backup_top_drop (bs=0x7fff67240b80) at 
> > > block/backup-top.c:273
> > > #8  0x0000555555bd995c in backup_clean (job=0x7fffe5609200) at 
> > > block/backup.c:114
> > > #9  0x0000555555b6e08d in job_clean (job=0x7fffe5609200) at job.c:657
> > > #10 0x0000555555b6e08d in job_finalize_single (job=0x7fffe5609200) at job.c:673
> > > #11 0x0000555555b6e08d in job_finalize_single (job=0x7fffe5609200) at job.c:661
> > > #12 0x0000555555b6ea3a in job_completed_txn_abort (job=<optimized out>) at 
> > > job.c:749
> > > #13 0x0000555555b6ec42 in job_completed (job=0x7fffe5609200) at job.c:843
> > > #14 0x0000555555b6ec42 in job_completed (job=0x7fffe5609200) at job.c:836
> > > #15 0x0000555555b6edf0 in job_exit (opaque=0x7fffe5609200) at job.c:864
> > > #16 0x0000555555c5e975 in aio_bh_call (bh=0x7fffe721a2d0) at util/async.c:164
> > > #17 0x0000555555c5e975 in aio_bh_poll (ctx=ctx@entry=0x7fffe8905e80) at 
> > > util/async.c:164
> > > #18 0x0000555555c6202e in aio_dispatch (ctx=0x7fffe8905e80) at 
> > > util/aio-posix.c:380
> > > #19 0x0000555555c5e85e in aio_ctx_dispatch (source=<optimized out>, callback=<optimized 
> > > out>, user_data=<optimized out>) at util/async.c:298
> > > #20 0x00007ffff7c7ef2e in g_main_context_dispatch () at 
> > > /usr/lib/x86_64-linux-gnu/libglib-2.0.so.0
> > > #21 0x0000555555c61298 in glib_pollfds_poll () at util/main-loop.c:219
> > > #22 0x0000555555c61298 in os_host_main_loop_wait (timeout=<optimized out>) at 
> > > util/main-loop.c:242
> > > #23 0x0000555555c61298 in main_loop_wait (nonblocking=nonblocking@entry=0) at 
> > > util/main-loop.c:518
> > > #24 0x00005555558fc5a9 in qemu_main_loop () at 
> > > /home/dietmar/pve5-devel/mirror_qemu/softmmu/vl.c:1665
> > > #25 0x0000555555800c3e in main (argc=<optimized out>, argv=<optimized out>, 
> > > envp=<optimized out>) at /home/dietmar/pve5-devel/mirror_qemu/softmmu/main.c:49
> >
> > The thing that we need to figure out is probably what operation we are
> > (or were) waiting for and why it doesn't complete.
> >
> > A typical cause of a hang like this is that the operation we're waiting
> > for actually did already complete in a different thread, but forgot to
> > call aio_wait_kick().
>
> no, that is not the case.
>
> > To confirm, if you have gdb attached to a hanging process, you could
> > manually call bdrv_drain_poll_top_level(bs, 0, 0) and check its result.
> > If it returns false,
>
> it return true, because there are about 30 in_flight request (block_backend). 
> But poll does not
> get any events ...
>
> > then a kick is missing somewhere. If it returns
> > true, some request is still waiting for completion somewhere and can be
> > inspected in gdb.
>
> How can I see/debug those waiting request?

Examine bs->tracked_requests list.

BdrvTrackedRequest has "Coroutine *co" field. It's a pointer of coroutine of 
this request. You may use qemu-gdb script to print request's coroutine back-trace:

gdb> source qemu_source/scripts/qemu-gdb.py

gdb> qemu coroutine CO_POINTER

- this will show, what exactly the request is doing now/waiting for.

> > > Thread 1 locks the BQL, while thread7 wants to aquire it to complete the read 
> > > in prepare_mmio_access():
> > >
> > > (gdb) source ./scripts/qemu-gdb.py
> > > (gdb) qemu tcg-lock-status
> > > Thread, BQL (iothread_mutex), Replay, Blocked?
> > > 10/31149, false, false, not blocked
> > > 8/30998, false, false, __lll_lock_wait waiting on 0x555556142e60 
> > > <qemu_global_mutex> from 30949
> > > 7/30997, false, false, __lll_lock_wait waiting on 0x555556142e60 
> > > <qemu_global_mutex> from 30949
> > > 6/30996, false, false, not blocked
> > > 4/30955, false, false, not blocked
> > > 3/30954, false, false, __lll_lock_wait waiting on 0x7fffe89151e0 from 30949
> > > 2/30953, false, false, not blocked
> > > 1/30949, true, false, not blocked
> > >
> > >
> > > (gdb) thread apply 7 bt
> > > Thread 7 (Thread 0x7fff669ff700 (LWP 30997)):
> > > #0  0x00007ffff5d9729c in __lll_lock_wait () at 
> > > ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:103
> > > #1  0x00007ffff5d90714 in __GI___pthread_mutex_lock (mutex=mutex@entry=0x555556142e60 
> > > <qemu_global_mutex>) at ../nptl/pthread_mutex_lock.c:80
> > > #2  0x0000555555c65013 in qemu_mutex_lock_impl (mutex=0x555556142e60 <qemu_global_mutex>, 
> > > file=0x555555c94008 "/home/dietmar/pve5-devel/mirror_qemu/exec.c", line=3089) at 
> > > util/qemu-thread-posix.c:78
> > > #3  0x00005555558480ee in qemu_mutex_lock_iothread_impl (file=file@entry=0x555555c94008 
> > > "/home/dietmar/pve5-devel/mirror_qemu/exec.c", line=line@entry=3089)
> > >      at /home/dietmar/pve5-devel/mirror_qemu/cpus.c:1831
> > > #4  0x0000555555802425 in prepare_mmio_access (mr=<optimized out>, mr=<optimized 
> > > out>) at /home/dietmar/pve5-devel/mirror_qemu/exec.c:3089
> > > #5  0x000055555580759f in flatview_read_continue
> > >      (fv=fv@entry=0x7fff5f9baf00, addr=addr@entry=375, attrs=..., 
> > > ptr=ptr@entry=0x7ffff7fbe000, len=len@entry=1, addr1=<optimized out>, l=<optimized 
> > > out>, mr=0x7fffe8e66e80)
> > >      at /home/dietmar/pve5-devel/mirror_qemu/exec.c:3188
> > > #6  0x0000555555807803 in flatview_read (fv=0x7fff5f9baf00, addr=375, 
> > > attrs=..., buf=0x7ffff7fbe000, len=1) at 
> > > /home/dietmar/pve5-devel/mirror_qemu/exec.c:3229
> > > #7  0x000055555580791b in address_space_read_full (as=<optimized out>, addr=<optimized 
> > > out>, attrs=..., buf=<optimized out>, len=<optimized out>) at 
> > > /home/dietmar/pve5-devel/mirror_qemu/exec.c:3242
> > > #8  0x0000555555807a25 in address_space_rw (as=<optimized out>, addr=addr@entry=375, 
> > > attrs=..., attrs@entry=..., buf=<optimized out>, len=len@entry=1, 
> > > is_write=is_write@entry=false)
> > >      at /home/dietmar/pve5-devel/mirror_qemu/exec.c:3270
> > > #9  0x0000555555865024 in kvm_handle_io (count=1, size=1, direction=<optimized out>, 
> > > data=<optimized out>, attrs=..., port=375) at 
> > > /home/dietmar/pve5-devel/mirror_qemu/accel/kvm/kvm-all.c:2140
> > > #10 0x0000555555865024 in kvm_cpu_exec (cpu=cpu@entry=0x7fffe89efb00) at 
> > > /home/dietmar/pve5-devel/mirror_qemu/accel/kvm/kvm-all.c:2386
> > > #11 0x000055555584835e in qemu_kvm_cpu_thread_fn (arg=0x7fffe89efb00) at 
> > > /home/dietmar/pve5-devel/mirror_qemu/cpus.c:1246
> > > #12 0x000055555584835e in qemu_kvm_cpu_thread_fn (arg=arg@entry=0x7fffe89efb00) 
> > > at /home/dietmar/pve5-devel/mirror_qemu/cpus.c:1218
> > > #13 0x0000555555c64e1a in qemu_thread_start (args=<optimized out>) at 
> > > util/qemu-thread-posix.c:519
> > > #14 0x00007ffff5d8dfa3 in start_thread (arg=<optimized out>) at 
> > > pthread_create.c:486
> > > #15 0x00007ffff5cbe4cf in clone () at 
> > > ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
> > > [...]
> >
> > > So the pattern is:
> > >
> > > 1.) Main thread has the BQL
> > > 2.) Main thread calls bdrv_drained_begin(bs);
> > > 3.) CPU thread want to complete read prepare_mmio_access(), but needs BQL
> > > 4.) deadlock
> > >
> > > Any ideas how to prevent that?
> >
> > What's going on in the vcpu thread (thread 7) is probably not part of
> > the problem. It does have to wait for the main thread, but it would only
> > really be part of the deadlock if the main thread would also wait for
> > the vcpu thread, which I don't think it does.
>
> Yes, I guess you are right. This read is triggered by the guest (not by 
> bdrv_drained_begin).


--
Best regards,
Vladimir