Deadlock between bdrv_drain_all_begin and prepare_mmio_access

Deadlock between bdrv_drain_all_begin and prepare_mmio_access

[Liang Yan]

Hello All,

I am facing a lock situation between main-loop thread 1 and vcpu thread 
4 when doing a qmp snapshot. QEMU is running on 6.0.x, checked the 
upstream code and did not see any big change since between. Guest is a 
Windows 10 VM. Unfortunately, I could not get into the windows vm or 
reproduce the issue by myself. No iothread is used here, native aio only.

 From the code,

-> AIO_WAIT_WHILE(NULL, bdrv_drain_all_poll());

--> aio_poll(qemu_get_aio_context(), true);

Mainloop mutex is locked when start snapshot in thread 1, vcpu released 
thread lock when address_space_rw and try to get thread lock again in 
prepare_mmio_access.

It seems main loop thread is stuck at aio_poll with blocking, but I can 
not figure out what the addr=4275044592 belongs to from mmio read.

I do not quite understand what really happens here, either block jobs 
never drained out or maybe a block io read from vcpu and cause a 
deadlock? I hope domain experts here could help figure out the root 
cause, thanks in advance and let me know if need any further information.


Regards,

Liang


(gdb) thread 1
[Switching to thread 1 (Thread 0x7f9ebcf96040 (LWP 358660))]
#0  0x00007f9ec6eb4ac6 in __ppoll (fds=0x562dda80bc90, nfds=2, 
timeout=<optimized out>, timeout@entry=0x0, sigmask=sigmask@entry=0x0) 
at ../sysdeps/unix/sysv/linux/ppoll.c:44
44    ../sysdeps/unix/sysv/linux/ppoll.c: No such file or directory.
(gdb) bt
#0  0x00007f9ec6eb4ac6 in __ppoll (fds=0x562dda80bc90, nfds=2, 
timeout=<optimized out>, timeout@entry=0x0, sigmask=sigmask@entry=0x0) 
at ../sysdeps/unix/sysv/linux/ppoll.c:44
#1  0x0000562dd7f5a409 in ppoll (__ss=0x0, __timeout=0x0, 
__nfds=<optimized out>, __fds=<optimized out>) at 
/usr/include/x86_64-linux-gnu/bits/poll2.h:77
#2  qemu_poll_ns (fds=<optimized out>, nfds=<optimized out>, 
timeout=timeout@entry=-1) at ../../util/qemu-timer.c:336
#3  0x0000562dd7f93de9 in fdmon_poll_wait (ctx=0x562dda193860, 
ready_list=0x7ffedaeb3f48, timeout=-1) at ../../util/fdmon-poll.c:80
#4  0x0000562dd7f6d05b in aio_poll (ctx=<optimized out>, 
blocking=blocking@entry=true) at ../../util/aio-posix.c:607
#5  0x0000562dd7e67e54 in bdrv_drain_all_begin () at ../../block/io.c:642
#6  bdrv_drain_all_begin () at ../../block/io.c:607
#7  0x0000562dd7e68a6d in bdrv_drain_all () at ../../block/io.c:693
#8  0x0000562dd7e54963 in qmp_transaction 
(dev_list=dev_list@entry=0x7ffedaeb4070, 
has_props=has_props@entry=false, props=0x562dda803910, props@entry=0x0, 
errp=errp@entry=0x7ffedaeb4128)
     at ../../blockdev.c:2348
#9  0x0000562dd7e54d5b in blockdev_do_action (errp=0x7ffedaeb4128, 
action=0x7ffedaeb4060) at ../../blockdev.c:1055
#10 qmp_blockdev_snapshot_sync (has_device=<optimized out>, 
device=<optimized out>, has_node_name=<optimized out>, 
node_name=<optimized out>, snapshot_file=<optimized out>,
     has_snapshot_node_name=<optimized out>, 
snapshot_node_name=0x562dda83c970 "hvd-snapshot", has_format=false, 
format=0x0, has_mode=false, mode=NEW_IMAGE_MODE_EXISTING, 
errp=0x7ffedaeb4128)
     at ../../blockdev.c:1083
#11 0x0000562dd7f0e5aa in qmp_marshal_blockdev_snapshot_sync 
(args=<optimized out>, ret=<optimized out>, errp=0x7f9ebc61ae90) at 
qapi/qapi-commands-block-core.c:221
#12 0x0000562dd7f5c5db in do_qmp_dispatch_bh (opaque=0x7f9ebc61aea0) at 
../../qapi/qmp-dispatch.c:131
#13 0x0000562dd7f5dc27 in aio_bh_call (bh=0x7f9e3000b760) at 
../../util/async.c:164
#14 aio_bh_poll (ctx=ctx@entry=0x562dda193860) at ../../util/async.c:164
#15 0x0000562dd7f6ca82 in aio_dispatch (ctx=0x562dda193860) at 
../../util/aio-posix.c:381
#16 0x0000562dd7f5da42 in aio_ctx_dispatch (source=<optimized out>, 
callback=<optimized out>, user_data=<optimized out>) at 
../../util/async.c:306
#17 0x00007f9ec7ade17d in g_main_context_dispatch () from 
/lib/x86_64-linux-gnu/libglib-2.0.so.0
#18 0x0000562dd7f4f320 in glib_pollfds_poll () at ../../util/main-loop.c:231
#19 os_host_main_loop_wait (timeout=<optimized out>) at 
../../util/main-loop.c:254
#20 main_loop_wait (nonblocking=nonblocking@entry=0) at 
../../util/main-loop.c:530
#21 0x0000562dd7d3cfd9 in qemu_main_loop () at ../../softmmu/runstate.c:725
#22 0x0000562dd7b7aa82 in main (argc=<optimized out>, argv=<optimized 
out>, envp=<optimized out>) at ../../softmmu/main.c:50


(gdb) thread 4
[Switching to thread 4 (Thread 0x7f9e377fd700 (LWP 358668))]
#0  __lll_lock_wait (futex=futex@entry=0x562dd8337a60 
<qemu_global_mutex>, private=0) at lowlevellock.c:52
52    lowlevellock.c: No such file or directory.
(gdb) bt
#0  __lll_lock_wait (futex=futex@entry=0x562dd8337a60 
<qemu_global_mutex>, private=0) at lowlevellock.c:52
#1  0x00007f9ec6f9f0a3 in __GI___pthread_mutex_lock 
(mutex=mutex@entry=0x562dd8337a60 <qemu_global_mutex>) at 
../nptl/pthread_mutex_lock.c:80
#2  0x0000562dd7f667c8 in qemu_mutex_lock_impl (mutex=0x562dd8337a60 
<qemu_global_mutex>, file=0x562dd804c76c "../../softmmu/physmem.c", 
line=2742) at ../../util/qemu-thread-posix.c:79
#3  0x0000562dd7dca8ce in qemu_mutex_lock_iothread_impl 
(file=file@entry=0x562dd804c76c "../../softmmu/physmem.c", 
line=line@entry=2742) at ../../softmmu/cpus.c:491
#4  0x0000562dd7da2e91 in prepare_mmio_access (mr=<optimized out>) at 
../../softmmu/physmem.c:2742
#5  0x0000562dd7da8bbb in flatview_read_continue 
(fv=fv@entry=0x7f9e2827a4c0, addr=addr@entry=4275044592, attrs=..., 
ptr=ptr@entry=0x7f9ebcef7028, len=len@entry=4, addr1=<optimized out>, 
l=<optimized out>,
     mr=0x562dda576f10) at ../../softmmu/physmem.c:2834
#6  0x0000562dd7da8df3 in flatview_read (fv=0x7f9e2827a4c0, 
addr=4275044592, attrs=..., buf=0x7f9ebcef7028, len=4) at 
../../softmmu/physmem.c:2875
#7  0x0000562dd7da8f1f in address_space_read_full (as=<optimized out>, 
addr=<optimized out>, attrs=..., buf=<optimized out>, len=<optimized 
out>) at ../../softmmu/physmem.c:2888
#8  0x0000562dd7da9045 in address_space_rw (as=<optimized out>, 
addr=<optimized out>, attrs=..., attrs@entry=..., 
buf=buf@entry=0x7f9ebcef7028, len=<optimized out>, is_write=<optimized out>)
     at ../../softmmu/physmem.c:2916
#9  0x0000562dd7dfd7a8 in kvm_cpu_exec (cpu=cpu@entry=0x7f9ebc42b010) at 
../../accel/kvm/kvm-all.c:2516
#10 0x0000562dd7d61c75 in kvm_vcpu_thread_fn 
(arg=arg@entry=0x7f9ebc42b010) at ../../accel/kvm/kvm-accel-ops.c:49
#11 0x0000562dd7f66523 in qemu_thread_start (args=<optimized out>) at 
../../util/qemu-thread-posix.c:521
#12 0x00007f9ec6f9c609 in start_thread (arg=<optimized out>) at 
pthread_create.c:477
#13 0x00007f9ec6ec1163 in clone () at 
../sysdeps/unix/sysv/linux/x86_64/clone.S:95

(gdb) print lock
$1 = {lock = {__data = {__lock = 0, __count = 0, __owner = 0, __nusers = 
0, __kind = 0, __spins = 0, __elision = 0, __list = {__prev = 0x0, 
__next = 0x0}}, __size = '\000' <repeats 39 times>, __align = 0},
   initialized = false}

(gdb) p *(pthread_mutex_t *)0x562dd8337a60
$3 = {__data = {__lock = 2, __count = 0, __owner = 358660, __nusers = 1, 
__kind = 0, __spins = 0, __elision = 0, __list = {__prev = 0x0, __next = 
0x0}},
   __size = "\002\000\000\000\000\000\000\000\004y\005\000\001", '\000' 
<repeats 26 times>, __align = 2}

Re: Deadlock between bdrv_drain_all_begin and prepare_mmio_access

[Kevin Wolf]

Am 24.07.2022 um 23:41 hat Liang Yan geschrieben:
> Hello All,
> 
> I am facing a lock situation between main-loop thread 1 and vcpu thread 4
> when doing a qmp snapshot. QEMU is running on 6.0.x, checked the upstream
> code and did not see any big change since between. Guest is a Windows 10 VM.
> Unfortunately, I could not get into the windows vm or reproduce the issue by
> myself. No iothread is used here, native aio only.
> 
> From the code,
> 
> -> AIO_WAIT_WHILE(NULL, bdrv_drain_all_poll());
> 
> --> aio_poll(qemu_get_aio_context(), true);
> 
> Mainloop mutex is locked when start snapshot in thread 1, vcpu released
> thread lock when address_space_rw and try to get thread lock again in
> prepare_mmio_access.
> 
> It seems main loop thread is stuck at aio_poll with blocking, but I can not
> figure out what the addr=4275044592 belongs to from mmio read.
> 
> I do not quite understand what really happens here, either block jobs never
> drained out or maybe a block io read from vcpu and cause a deadlock? I hope
> domain experts here could help figure out the root cause, thanks in advance
> and let me know if need any further information.

This does not look like a deadlock to me: Thread 4 is indeed waiting for
thread 1 to release the lock, but I don't think thread 1 is waiting in
any way for thread 4.

In thread 1, bdrv_drain_all_begin() waits for all in-flight I/O requests
to complete. So it looks a bit like some I/O request got stuck. If you
want to debug this a bit further, try to check what it is that makes
bdrv_drain_poll() still return true.

Please also add the QEMU command line you're using, especially the
configuration of the block device backends (for example, does this use
Linux AIO, the thread pool or io_uring?).

Kevin

Re: Deadlock between bdrv_drain_all_begin and prepare_mmio_access

[Liang Yan]

[-- Attachment #1: Type: text/plain, Size: 3082 bytes --]


On 8/2/22 08:35, Kevin Wolf wrote:
> Am 24.07.2022 um 23:41 hat Liang Yan geschrieben:
>> Hello All,
>>
>> I am facing a lock situation between main-loop thread 1 and vcpu thread 4
>> when doing a qmp snapshot. QEMU is running on 6.0.x, checked the upstream
>> code and did not see any big change since between. Guest is a Windows 10 VM.
>> Unfortunately, I could not get into the windows vm or reproduce the issue by
>> myself. No iothread is used here, native aio only.
>>
>>  From the code,
>>
>> -> AIO_WAIT_WHILE(NULL, bdrv_drain_all_poll());
>>
>> --> aio_poll(qemu_get_aio_context(), true);
>>
>> Mainloop mutex is locked when start snapshot in thread 1, vcpu released
>> thread lock when address_space_rw and try to get thread lock again in
>> prepare_mmio_access.
>>
>> It seems main loop thread is stuck at aio_poll with blocking, but I can not
>> figure out what the addr=4275044592 belongs to from mmio read.
>>
>> I do not quite understand what really happens here, either block jobs never
>> drained out or maybe a block io read from vcpu and cause a deadlock? I hope
>> domain experts here could help figure out the root cause, thanks in advance
>> and let me know if need any further information.
> This does not look like a deadlock to me: Thread 4 is indeed waiting for
> thread 1 to release the lock, but I don't think thread 1 is waiting in
> any way for thread 4.
>
> In thread 1, bdrv_drain_all_begin() waits for all in-flight I/O requests
> to complete. So it looks a bit like some I/O request got stuck. If you
> want to debug this a bit further, try to check what it is that makes
> bdrv_drain_poll() still return true.

Thanks for the reply.

I agree it is not a pure deadlock. thread 1 seems have more 
responsibility here.

Do you know if there is a way to check in-flight I/O requests here? Is 
it possible that the i/o request is the mmio_read from thread 4?

I could only see the addr=4275044592, but could not identify which 
address space it is belonged.


I am also pretty curious why bdrv_drain_poll() always return true.  Any 
chance that it is blocked in aio_poll(qemu_get_aio_context(), true)?

while((cond)) { \
if(ctx_) { \
aio_context_release(ctx_); \
} \
aio_poll(qemu_get_aio_context(), true);


As mentioned, I only have a dump file, could not reproduce it in my 
local environment.

Though, I have been working on a log patch to print all fd/aio-handlers 
that main-loop is dispatched.


> Please also add the QEMU command line you're using, especially the
> configuration of the block device backends (for example, does this use
> Linux AIO, the thread pool or io_uring?).

it uses native linux aio, and no extra io-thread is assigned here.

-blockdev 
{"driver":"file","filename":"****.raw","aio":"native","node-name":"libvirt-2-storage","cache":{"direct":true,"no-flush":false},"auto-read-only":true,"discard":"unmap"}

-device 
virtio-blk-pci,bus=pci.0,addr=0x6,drive=libvirt-2-format,id=virtio-disk0,bootindex=1,write-cache=on


Let me now if you need more information and thanks for looking into this 
issue.

~Liang

> Kevin
>
>

[-- Attachment #2: Type: text/html, Size: 5468 bytes --]