Re: [Qemu-devel] Intermittent hang of iotest 194 (bdrv_drain_all after non-shared storage migration)

[Max Reitz]

On 2017-11-09 05:21, Fam Zheng wrote:
> On Thu, 11/09 01:48, Max Reitz wrote:
>> Hi,
>>
>> More exciting news from the bdrv_drain() front!
>>
>> I've noticed in the past that iotest 194 sometimes hangs.  I usually run
>> the tests on tmpfs, but I've just now verified that it happens on my SSD
>> just as well.
>>
>> So the reproducer is a plain:
>>
>> while ./check -raw 194; do; done
> 
> I cannot produce it on my machine.

Hm, too bad.  I see it both on my work laptop (with Fedora) and my
desktop (with Arch)...

>> (No difference between raw or qcow2, though.)
>>
>> And then, after a couple of runs (or a couple ten), it will just hang.
>> The reason is that the source VM lingers around and doesn't quit
>> voluntarily -- the test itself was successful, but it just can't exit.
>>
>> If you force it to exit by killing the VM (e.g. through pkill -11 qemu),
>> this is the backtrace:
>>
>> #0  0x00007f7cfc297e06 in ppoll () at /lib64/libc.so.6
>> #1  0x0000563b846bcac9 in ppoll (__ss=0x0, __timeout=0x0,
>> __nfds=<optimized out>, __fds=<optimized out>) at
>> /usr/include/bits/poll2.h:77
> 
> Looking at the 0 timeout it seems we are in the aio_poll(ctx, blocking=false);
> branches of BDRV_POLL_WHILE? Is it a busy loop? If so I wonder what is making
> progress and causing the return value to be true in aio_poll().
> 
>> #2  0x0000563b846bcac9 in qemu_poll_ns (fds=<optimized out>,
>> nfds=<optimized out>, timeout=<optimized out>) at util/qemu-timer.c:322
>> #3  0x0000563b846be711 in aio_poll (address@hidden,
>> blocking=<optimized out>) at util/aio-posix.c:629
>> #4  0x0000563b8463afa4 in bdrv_drain_recurse
>> (address@hidden, address@hidden) at block/io.c:201
>> #5  0x0000563b8463baff in bdrv_drain_all_begin () at block/io.c:381
>> #6  0x0000563b8463bc99 in bdrv_drain_all () at block/io.c:411
>> #7  0x0000563b8459888b in block_migration_cleanup (opaque=<optimized
>> out>) at migration/block.c:714
>> #8  0x0000563b845883be in qemu_savevm_state_cleanup () at
>> migration/savevm.c:1251
>> #9  0x0000563b845811fd in migration_thread (opaque=0x563b856f1da0) at
>> migration/migration.c:2298
>> #10 0x00007f7cfc56f36d in start_thread () at /lib64/libpthread.so.0
>> #11 0x00007f7cfc2a3e1f in clone () at /lib64/libc.so.6
>>
>>
>> And when you make bdrv_drain_all_begin() print what we are trying to
>> drain, you can see that it's the format node (managed by the "raw"
>> driver in this case).
> 
> So what is the value of bs->in_flight?

gdb:
> (gdb) print bs->in_flight 
> $3 = 2307492233

"That's weird, why would it..."

> (gdb) print *bs
> $4 = {open_flags = -1202160144, read_only = 161, encrypted = 85, sg = false, 
> probed = false, force_share = 96, implicit = 159, drv = 0x0, opaque = 0x0, 
> aio_context = 0x8989898989898989, aio_notifiers = {lh_first = 
> 0x8989898989898989}, 
>   walking_aio_notifiers = 137, filename = '\211' <repeats 4096 times>, 
> backing_file = '\211' <repeats 4096 times>, backing_format = '\211' <repeats 
> 16 times>, full_open_options = 0x8989898989898989, 
>   exact_filename = '\211' <repeats 4096 times>, backing = 0x8989898989898989, 
> file = 0x8989898989898989, bl = {request_alignment = 2307492233, max_pdiscard 
> = -1987475063, pdiscard_alignment = 2307492233, 
>     max_pwrite_zeroes = -1987475063, pwrite_zeroes_alignment = 2307492233, 
> opt_transfer = 2307492233, max_transfer = 2307492233, min_mem_alignment = 
> 9910603678816504201, opt_mem_alignment = 9910603678816504201, max_iov = 
> -1987475063}, 
>   supported_write_flags = 2307492233, supported_zero_flags = 2307492233, 
> node_name = '\211' <repeats 32 times>, node_list = {tqe_next = 
> 0x8989898989898989, tqe_prev = 0x8989898989898989}, bs_list = {tqe_next = 
> 0x8989898989898989, 
>     tqe_prev = 0x8989898989898989}, monitor_list = {tqe_next = 
> 0x8989898989898989, tqe_prev = 0x8989898989898989}, refcnt = -1987475063, 
> op_blockers = {{lh_first = 0x8989898989898989} <repeats 16 times>}, job = 
> 0x8989898989898989, 
>   inherits_from = 0x8989898989898989, children = {lh_first = 
> 0x8989898989898989}, parents = {lh_first = 0x8989898989898989}, options = 
> 0x8989898989898989, explicit_options = 0x8989898989898989, detect_zeroes = 
> 2307492233, 
>   backing_blocker = 0x8989898989898989, total_sectors = -8536140394893047415, 
> before_write_notifiers = {notifiers = {lh_first = 0x8989898989898989}}, 
> write_threshold_offset = 9910603678816504201, write_threshold_notifier = 
> {notify = 
>     0x8989898989898989, node = {le_next = 0x8989898989898989, le_prev = 
> 0x8989898989898989}}, dirty_bitmap_mutex = {lock = {__data = {__lock = 
> -1987475063, __count = 2307492233, __owner = -1987475063, __nusers = 
> 2307492233, 
>         __kind = -1987475063, __spins = -30327, __elision = -30327, __list = 
> {__prev = 0x8989898989898989, __next = 0x8989898989898989}}, __size = '\211' 
> <repeats 40 times>, __align = -8536140394893047415}, initialized = 137}, 
>   dirty_bitmaps = {lh_first = 0x8989898989898989}, wr_highest_offset = {value 
> = 9910603678816504201}, copy_on_read = -1987475063, in_flight = 2307492233, 
> serialising_in_flight = 2307492233, wakeup = 137, io_plugged = 2307492233, 
>   enable_write_cache = -1987475063, quiesce_counter = -1987475063, write_gen 
> = 2307492233, reqs_lock = {locked = 2307492233, ctx = 0x8989898989898989, 
> from_push = {slh_first = 0x8989898989898989}, to_pop = {
>       slh_first = 0x8989898989898989}, handoff = 2307492233, sequence = 
> 2307492233, holder = 0x8989898989898989}, tracked_requests = {lh_first = 
> 0x8989898989898989}, flush_queue = {entries = {sqh_first = 
> 0x8989898989898989, 
>       sqh_last = 0x8989898989898989}}, active_flush_req = 160, flushed_gen = 
> 0}
"Oh."

*sigh*

OK, I'll look into it...

Max

>> So I thought, before I put more time into this, let's ask whether the
>> test author has any ideas. :-)
> 
> Fam
>

signature.asc
Description: OpenPGP digital signature