On Thu, 11/09 20:31, Max Reitz wrote:
> On 2017-11-09 16:30, Fam Zheng wrote:
> > On Thu, 11/09 16:14, Max Reitz wrote:
> >> 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 (ctx=ctx@entry=0x563b856e3e80,
> >>>> blocking=<optimized out>) at util/aio-posix.c:629
> >>>> #4 0x0000563b8463afa4 in bdrv_drain_recurse
> >>>> (bs=bs@entry=0x563b865568a0, begin=begin@entry=true) 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...
> >
> > OK, I'll let you.. Just one more thing: could it relate to the
> > use-after-free
> > bug reported on block_job_defer_to_main_loop()?
> >
> > https://lists.gnu.org/archive/html/qemu-devel/2017-11/msg01144.html
>
> Thanks for the heads-up; I think it's a different issue, though.
>
> What appears to be happening is that the mirror job completes and then
> drains its BDS. While that is happening, a bdrv_drain_all() comes in
> from block_migration_cleanup().
>
> That now tries to drain the mirror node. However, that node cannot be
> drained until the job is truly gone now, so that is what's happening:
> mirror_exit() is called, it cleans up, destroys the mirror node, and
> returns.
>
> Now bdrv_drain_all() can go on, specifically the BDRV_POLL_WHILE() on
> the mirror node. However, oops, that node is gone now... So that's
> where the issue seems to be. :-/
>
> Maybe all that we need to do is wrap the bdrv_drain_recurse() call in
> bdrv_drain_all_begin() in a bdrv_ref()/bdrv_unref() pair? Having run
> 194 for a couple of minutes, that seems to indeed work -- until it dies
> because of an invalid BB pointer in bdrv_next(). I guess that is
> because bdrv_next() does not guard against deleted BDSs.
>
> Copying all BDS into an own list (in both bdrv_drain_all_begin() and
> bdrv_drain_all_end()), with a strong reference to every single one, and
> then draining them really seems to work, though. (Survived 9000
> iterations, that seems good enough for something that usually fails
> after, like, 5.)
Yes, that makes sense. I'm curious if the patch in
https://lists.gnu.org/archive/html/qemu-devel/2017-11/msg01649.html
would also work?
Fam
