risc-v: 0.789 TCG: 0.743 ppc: 0.731 peripherals: 0.728 hypervisor: 0.728 x86: 0.713 KVM: 0.713 i386: 0.700 operating system: 0.696 vnc: 0.682 VMM: 0.657 mistranslation: 0.649 user-level: 0.648 graphic: 0.630 device: 0.623 register: 0.620 debug: 0.611 arm: 0.595 performance: 0.591 permissions: 0.580 semantic: 0.577 virtual: 0.539 architecture: 0.534 assembly: 0.529 alpha: 0.529 network: 0.525 PID: 0.512 kernel: 0.485 boot: 0.478 socket: 0.462 files: 0.459 [RESEND][BUG FIX HELP] QEMU main thread endlessly hangs in __ppoll() Hi Genius, I am a user of QEMU v4.2.0 and stuck in an interesting bug, which may still exist in the mainline. Thanks in advance to heroes who can take a look and share understanding. The qemu main thread endlessly hangs in the handle of the qmp statement: {'execute': 'human-monitor-command', 'arguments':{ 'command-line': 'drive_del replication0' } } and we have the call trace looks like: #0 0x00007f3c22045bf6 in __ppoll (fds=0x555611328410, nfds=1, timeout=, timeout@entry=0x7ffc56c66db0, sigmask=sigmask@entry=0x0) at ../sysdeps/unix/sysv/linux/ppoll.c:44 #1 0x000055561021f415 in ppoll (__ss=0x0, __timeout=0x7ffc56c66db0, __nfds=, __fds=) at /usr/include/x86_64-linux-gnu/bits/poll2.h:77 #2 qemu_poll_ns (fds=, nfds=, timeout=) at util/qemu-timer.c:348 #3 0x0000555610221430 in aio_poll (ctx=ctx@entry=0x5556113010f0, blocking=blocking@entry=true) at util/aio-posix.c:669 #4 0x000055561019268d in bdrv_do_drained_begin (poll=true, ignore_bds_parents=false, parent=0x0, recursive=false, bs=0x55561138b0a0) at block/io.c:430 #5 bdrv_do_drained_begin (bs=0x55561138b0a0, recursive=, parent=0x0, ignore_bds_parents=, poll=) at block/io.c:396 #6 0x000055561017b60b in quorum_del_child (bs=0x55561138b0a0, child=0x7f36dc0ce380, errp=) at block/quorum.c:1063 #7 0x000055560ff5836b in qmp_x_blockdev_change (parent=0x555612373120 "colo-disk0", has_child=, child=0x5556112df3e0 "children.1", has_node=, node=0x0, errp=0x7ffc56c66f98) at blockdev.c:4494 #8 0x00005556100f8f57 in qmp_marshal_x_blockdev_change (args=, ret=, errp=0x7ffc56c67018) at qapi/qapi-commands-block-core.c:1538 #9 0x00005556101d8290 in do_qmp_dispatch (errp=0x7ffc56c67010, allow_oob=, request=, cmds=0x5556109c69a0 ) at qapi/qmp-dispatch.c:132 #10 qmp_dispatch (cmds=0x5556109c69a0 , request=, allow_oob=) at qapi/qmp-dispatch.c:175 #11 0x00005556100d4c4d in monitor_qmp_dispatch (mon=0x5556113a6f40, req=) at monitor/qmp.c:145 #12 0x00005556100d5437 in monitor_qmp_bh_dispatcher (data=) at monitor/qmp.c:234 #13 0x000055561021dbec in aio_bh_call (bh=0x5556112164bGrateful0) at util/async.c:117 #14 aio_bh_poll (ctx=ctx@entry=0x5556112151b0) at util/async.c:117 #15 0x00005556102212c4 in aio_dispatch (ctx=0x5556112151b0) at util/aio-posix.c:459 #16 0x000055561021dab2 in aio_ctx_dispatch (source=, callback=, user_data=) at util/async.c:260 #17 0x00007f3c22302fbd in g_main_context_dispatch () from /lib/x86_64-linux-gnu/libglib-2.0.so.0 #18 0x0000555610220358 in glib_pollfds_poll () at util/main-loop.c:219 #19 os_host_main_loop_wait (timeout=) at util/main-loop.c:242 #20 main_loop_wait (nonblocking=) at util/main-loop.c:518 #21 0x000055560ff600fe in main_loop () at vl.c:1814 #22 0x000055560fddbce9 in main (argc=, argv=, envp=) at vl.c:4503 We found that we're doing endless check in the line of block/io.c:bdrv_do_drained_begin(): BDRV_POLL_WHILE(bs, bdrv_drain_poll_top_level(bs, recursive, parent)); and it turns out that the bdrv_drain_poll() always get true from: - bdrv_parent_drained_poll(bs, ignore_parent, ignore_bds_parents) - AND atomic_read(&bs->in_flight) I personally think this is a deadlock issue in the a QEMU block layer (as we know, we have some #FIXME comments in related codes, such as block permisson update). Any comments are welcome and appreciated. --- thx,likexu On 2/28/21 9:39 PM, Like Xu wrote: Hi Genius, I am a user of QEMU v4.2.0 and stuck in an interesting bug, which may still exist in the mainline. Thanks in advance to heroes who can take a look and share understanding. Do you have a test case that reproduces on 5.2? It'd be nice to know if it was still a problem in the latest source tree or not. --js The qemu main thread endlessly hangs in the handle of the qmp statement: {'execute': 'human-monitor-command', 'arguments':{ 'command-line': 'drive_del replication0' } } and we have the call trace looks like: #0 0x00007f3c22045bf6 in __ppoll (fds=0x555611328410, nfds=1, timeout=, timeout@entry=0x7ffc56c66db0, sigmask=sigmask@entry=0x0) at ../sysdeps/unix/sysv/linux/ppoll.c:44 #1 0x000055561021f415 in ppoll (__ss=0x0, __timeout=0x7ffc56c66db0, __nfds=, __fds=) at /usr/include/x86_64-linux-gnu/bits/poll2.h:77 #2 qemu_poll_ns (fds=, nfds=, timeout=) at util/qemu-timer.c:348 #3 0x0000555610221430 in aio_poll (ctx=ctx@entry=0x5556113010f0, blocking=blocking@entry=true) at util/aio-posix.c:669 #4 0x000055561019268d in bdrv_do_drained_begin (poll=true, ignore_bds_parents=false, parent=0x0, recursive=false, bs=0x55561138b0a0) at block/io.c:430 #5 bdrv_do_drained_begin (bs=0x55561138b0a0, recursive=, parent=0x0, ignore_bds_parents=, poll=) at block/io.c:396 #6 0x000055561017b60b in quorum_del_child (bs=0x55561138b0a0, child=0x7f36dc0ce380, errp=) at block/quorum.c:1063 #7 0x000055560ff5836b in qmp_x_blockdev_change (parent=0x555612373120 "colo-disk0", has_child=, child=0x5556112df3e0 "children.1", has_node=, node=0x0, errp=0x7ffc56c66f98) at blockdev.c:4494 #8 0x00005556100f8f57 in qmp_marshal_x_blockdev_change (args=, ret=, errp=0x7ffc56c67018) at qapi/qapi-commands-block-core.c:1538 #9 0x00005556101d8290 in do_qmp_dispatch (errp=0x7ffc56c67010, allow_oob=, request=, cmds=0x5556109c69a0 ) at qapi/qmp-dispatch.c:132 #10 qmp_dispatch (cmds=0x5556109c69a0 , request=, allow_oob=) at qapi/qmp-dispatch.c:175 #11 0x00005556100d4c4d in monitor_qmp_dispatch (mon=0x5556113a6f40, req=) at monitor/qmp.c:145 #12 0x00005556100d5437 in monitor_qmp_bh_dispatcher (data=) at monitor/qmp.c:234 #13 0x000055561021dbec in aio_bh_call (bh=0x5556112164bGrateful0) at util/async.c:117 #14 aio_bh_poll (ctx=ctx@entry=0x5556112151b0) at util/async.c:117 #15 0x00005556102212c4 in aio_dispatch (ctx=0x5556112151b0) at util/aio-posix.c:459 #16 0x000055561021dab2 in aio_ctx_dispatch (source=, callback=, user_data=) at util/async.c:260 #17 0x00007f3c22302fbd in g_main_context_dispatch () from /lib/x86_64-linux-gnu/libglib-2.0.so.0 #18 0x0000555610220358 in glib_pollfds_poll () at util/main-loop.c:219 #19 os_host_main_loop_wait (timeout=) at util/main-loop.c:242 #20 main_loop_wait (nonblocking=) at util/main-loop.c:518 #21 0x000055560ff600fe in main_loop () at vl.c:1814 #22 0x000055560fddbce9 in main (argc=, argv=, envp=) at vl.c:4503 We found that we're doing endless check in the line of block/io.c:bdrv_do_drained_begin():     BDRV_POLL_WHILE(bs, bdrv_drain_poll_top_level(bs, recursive, parent)); and it turns out that the bdrv_drain_poll() always get true from: - bdrv_parent_drained_poll(bs, ignore_parent, ignore_bds_parents) - AND atomic_read(&bs->in_flight) I personally think this is a deadlock issue in the a QEMU block layer (as we know, we have some #FIXME comments in related codes, such as block permisson update). Any comments are welcome and appreciated. --- thx,likexu Hi John, Thanks for your comment. On 2021/3/5 7:53, John Snow wrote: On 2/28/21 9:39 PM, Like Xu wrote: Hi Genius, I am a user of QEMU v4.2.0 and stuck in an interesting bug, which may still exist in the mainline. Thanks in advance to heroes who can take a look and share understanding. Do you have a test case that reproduces on 5.2? It'd be nice to know if it was still a problem in the latest source tree or not. We narrowed down the source of the bug, which basically came from the following qmp usage: {'execute': 'human-monitor-command', 'arguments':{ 'command-line': 'drive_del replication0' } } One of the test cases is the COLO usage (docs/colo-proxy.txt). This issue is sporadic,the probability may be 1/15 for a io-heavy guest. I believe it's reproducible on 5.2 and the latest tree. --js The qemu main thread endlessly hangs in the handle of the qmp statement: {'execute': 'human-monitor-command', 'arguments':{ 'command-line': 'drive_del replication0' } } and we have the call trace looks like: #0 0x00007f3c22045bf6 in __ppoll (fds=0x555611328410, nfds=1, timeout=, timeout@entry=0x7ffc56c66db0, sigmask=sigmask@entry=0x0) at ../sysdeps/unix/sysv/linux/ppoll.c:44 #1 0x000055561021f415 in ppoll (__ss=0x0, __timeout=0x7ffc56c66db0, __nfds=, __fds=) at /usr/include/x86_64-linux-gnu/bits/poll2.h:77 #2 qemu_poll_ns (fds=, nfds=, timeout=) at util/qemu-timer.c:348 #3 0x0000555610221430 in aio_poll (ctx=ctx@entry=0x5556113010f0, blocking=blocking@entry=true) at util/aio-posix.c:669 #4 0x000055561019268d in bdrv_do_drained_begin (poll=true, ignore_bds_parents=false, parent=0x0, recursive=false, bs=0x55561138b0a0) at block/io.c:430 #5 bdrv_do_drained_begin (bs=0x55561138b0a0, recursive=, parent=0x0, ignore_bds_parents=, poll=) at block/io.c:396 #6 0x000055561017b60b in quorum_del_child (bs=0x55561138b0a0, child=0x7f36dc0ce380, errp=) at block/quorum.c:1063 #7 0x000055560ff5836b in qmp_x_blockdev_change (parent=0x555612373120 "colo-disk0", has_child=, child=0x5556112df3e0 "children.1", has_node=, node=0x0, errp=0x7ffc56c66f98) at blockdev.c:4494 #8 0x00005556100f8f57 in qmp_marshal_x_blockdev_change (args=, ret=, errp=0x7ffc56c67018) at qapi/qapi-commands-block-core.c:1538 #9 0x00005556101d8290 in do_qmp_dispatch (errp=0x7ffc56c67010, allow_oob=, request=, cmds=0x5556109c69a0 ) at qapi/qmp-dispatch.c:132 #10 qmp_dispatch (cmds=0x5556109c69a0 , request=, allow_oob=) at qapi/qmp-dispatch.c:175 #11 0x00005556100d4c4d in monitor_qmp_dispatch (mon=0x5556113a6f40, req=) at monitor/qmp.c:145 #12 0x00005556100d5437 in monitor_qmp_bh_dispatcher (data=) at monitor/qmp.c:234 #13 0x000055561021dbec in aio_bh_call (bh=0x5556112164bGrateful0) at util/async.c:117 #14 aio_bh_poll (ctx=ctx@entry=0x5556112151b0) at util/async.c:117 #15 0x00005556102212c4 in aio_dispatch (ctx=0x5556112151b0) at util/aio-posix.c:459 #16 0x000055561021dab2 in aio_ctx_dispatch (source=, callback=, user_data=) at util/async.c:260 #17 0x00007f3c22302fbd in g_main_context_dispatch () from /lib/x86_64-linux-gnu/libglib-2.0.so.0 #18 0x0000555610220358 in glib_pollfds_poll () at util/main-loop.c:219 #19 os_host_main_loop_wait (timeout=) at util/main-loop.c:242 #20 main_loop_wait (nonblocking=) at util/main-loop.c:518 #21 0x000055560ff600fe in main_loop () at vl.c:1814 #22 0x000055560fddbce9 in main (argc=, argv=, envp=) at vl.c:4503 We found that we're doing endless check in the line of block/io.c:bdrv_do_drained_begin():      BDRV_POLL_WHILE(bs, bdrv_drain_poll_top_level(bs, recursive, parent)); and it turns out that the bdrv_drain_poll() always get true from: - bdrv_parent_drained_poll(bs, ignore_parent, ignore_bds_parents) - AND atomic_read(&bs->in_flight) I personally think this is a deadlock issue in the a QEMU block layer (as we know, we have some #FIXME comments in related codes, such as block permisson update). Any comments are welcome and appreciated. --- thx,likexu On 3/4/21 10:08 PM, Like Xu wrote: Hi John, Thanks for your comment. On 2021/3/5 7:53, John Snow wrote: On 2/28/21 9:39 PM, Like Xu wrote: Hi Genius, I am a user of QEMU v4.2.0 and stuck in an interesting bug, which may still exist in the mainline. Thanks in advance to heroes who can take a look and share understanding. Do you have a test case that reproduces on 5.2? It'd be nice to know if it was still a problem in the latest source tree or not. We narrowed down the source of the bug, which basically came from the following qmp usage: {'execute': 'human-monitor-command', 'arguments':{ 'command-line': 'drive_del replication0' } } One of the test cases is the COLO usage (docs/colo-proxy.txt). This issue is sporadic,the probability may be 1/15 for a io-heavy guest. I believe it's reproducible on 5.2 and the latest tree. Can you please test and confirm that this is the case, and then file a bug report on the LP: https://launchpad.net/qemu and include: - The exact commit you used (current origin/master debug build would be the most ideal.) - Which QEMU binary you are using (qemu-system-x86_64?) - The shortest command line you are aware of that reproduces the problem - The host OS and kernel version - An updated call trace - Any relevant commands issued prior to the one that caused the hang; or detailed reproduction steps if possible. Thanks, --js