Re: [Qemu-block] AioContext locking vs. coroutines

[Vladimir Sementsov-Ogievskiy]

29.11.2018 13:42, Kevin Wolf wrote:
> Am 28.11.2018 um 21:13 hat Vladimir Sementsov-Ogievskiy geschrieben:
>> Hi all!
>>
>> We've faced the following mirror bug:
>>
>> Just run mirror on qcow2 image more than 1G, and qemu is in dead lock.
>>
>> Note: I've decided to send this as a patch with reproducer, to make it
>> easier to reproduce). No needs to commit this before mirror fix, but
>> after, commit message may be a bit shortened, may be even up to just
>> "iotests: add simple mirror test".
>>
>> Note2: if drop 'kvm' option from the test it still reproduces, but if
>> use iotests.VM() - does not (may be, because of qtest?). If add
>> iothread, it doesn't reproduce too. Also, it doesn't reproduce with raw
>> instead of qcow2 and doesn't reproduce for small images.
>>
>> So, here is the dead-lock:
>>
>>   (gdb) info thr
>>     Id   Target Id         Frame
>>     3    Thread 0x7fd7fd4ea700 (LWP 145412) "qemu-system-x86" syscall () at 
>> ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
>>     2    Thread 0x7fd7fc205700 (LWP 145416) "qemu-system-x86" 
>> __lll_lock_wait () at 
>> ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
>>   * 1    Thread 0x7fd8102cfcc0 (LWP 145411) "qemu-system-x86" 
>> __lll_lock_wait () at 
>> ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
>>   (gdb) bt
>>   #0  0x00007fd80e8864cd in __lll_lock_wait () at 
>> ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
>>   #1  0x00007fd80e881dcb in _L_lock_812 () at /lib64/libpthread.so.0
>>   #2  0x00007fd80e881c98 in __GI___pthread_mutex_lock (mutex=0x561032dce420 
>> <qemu_global_mutex>) at ../nptl/pthread_mutex_lock.c:79
>>   #3  0x0000561032654c3b in qemu_mutex_lock_impl (mutex=0x561032dce420 
>> <qemu_global_mutex>, file=0x5610327d8654 "util/main-loop.c", line=236) at 
>> util/qemu-thread-posix.c:66
>>   #4  0x00005610320cb327 in qemu_mutex_lock_iothread_impl 
>> (file=0x5610327d8654 "util/main-loop.c", line=236) at 
>> /work/src/qemu/up-mirror-dead-lock/cpus.c:1849
>>   #5  0x000056103265038f in os_host_main_loop_wait (timeout=480116000) at 
>> util/main-loop.c:236
>>   #6  0x0000561032650450 in main_loop_wait (nonblocking=0) at 
>> util/main-loop.c:497
>>   #7  0x00005610322575c9 in main_loop () at vl.c:1892
>>   #8  0x000056103225f3c7 in main (argc=13, argv=0x7ffcc8bb15a8, 
>> envp=0x7ffcc8bb1618) at vl.c:4648
>>   (gdb) p qemu_global_mutex
>>   $1 = {lock = {__data = {__lock = 2, __count = 0, __owner = 145416, 
>> __nusers = 1, __kind = 0, __spins = 0, __elision = 0, __list = {__prev = 
>> 0x0, __next = 0x0}},
>>       __size = "\002\000\000\000\000\000\000\000\b8\002\000\001", '\000' 
>> <repeats 26 times>, __align = 2}, file = 0x56103267bcb0 
>> "/work/src/qemu/up-mirror-dead-lock/exec.c", line = 3197, initialized = true}
>>
>>   So, we see, that thr1 is main loop, and now it wants BQL, which is
>>   owned by thr2.
>>
>>   (gdb) thr 2
>>   [Switching to thread 2 (Thread 0x7fd7fc205700 (LWP 145416))]
>>   #0  __lll_lock_wait () at 
>> ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
>>   135     2:      movl    %edx, %eax
>>   (gdb) bt
>>   #0  0x00007fd80e8864cd in __lll_lock_wait () at 
>> ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
>>   #1  0x00007fd80e881de6 in _L_lock_870 () at /lib64/libpthread.so.0
>>   #2  0x00007fd80e881cdf in __GI___pthread_mutex_lock (mutex=0x561034d25dc0) 
>> at ../nptl/pthread_mutex_lock.c:114
>>   #3  0x0000561032654c3b in qemu_mutex_lock_impl (mutex=0x561034d25dc0, 
>> file=0x5610327d81d1 "util/async.c", line=511) at util/qemu-thread-posix.c:66
>>   #4  0x000056103264d840 in aio_context_acquire (ctx=0x561034d25d60) at 
>> util/async.c:511
>>   #5  0x0000561032254554 in dma_blk_cb (opaque=0x7fd7f41463b0, ret=0) at 
>> dma-helpers.c:169
>>   #6  0x000056103225479d in dma_blk_io (ctx=0x561034d25d60, 
>> sg=0x561035a80210, offset=0, align=512, io_func=0x5610322547a3 
>> <dma_blk_read_io_func>, io_func_opaque=0x561034d40870, cb=0x561032340b35 
>> <ide_dma_cb>, opaque=0x561035a7fee8, dir=DMA_DIRECTION_FROM_DEVICE) at 
>> dma-helpers.c:227
>>   #7  0x0000561032254855 in dma_blk_read (blk=0x561034d40870, 
>> sg=0x561035a80210, offset=0, align=512, cb=0x561032340b35 <ide_dma_cb>, 
>> opaque=0x561035a7fee8) at dma-helpers.c:245
>>   #8  0x0000561032340e6e in ide_dma_cb (opaque=0x561035a7fee8, ret=0) at 
>> hw/ide/core.c:910
>>   #9  0x000056103234a912 in bmdma_cmd_writeb (bm=0x561035a81030, val=9) at 
>> hw/ide/pci.c:240
>>   #10 0x000056103234b5bd in bmdma_write (opaque=0x561035a81030, addr=0, 
>> val=9, size=1) at hw/ide/piix.c:76
>>   #11 0x00005610320e5763 in memory_region_write_accessor (mr=0x561035a81180, 
>> addr=0, value=0x7fd7fc204678, size=1, shift=0, mask=255, attrs=...) at 
>> /work/src/qemu/up-mirror-dead-lock/memory.c:504
>>   #12 0x00005610320e596d in access_with_adjusted_size (addr=0, 
>> value=0x7fd7fc204678, size=1, access_size_min=1, access_size_max=4, 
>> access_fn=
>>       0x5610320e5683 <memory_region_write_accessor>, mr=0x561035a81180, 
>> attrs=...) at /work/src/qemu/up-mirror-dead-lock/memory.c:570
>>   #13 0x00005610320e86ce in memory_region_dispatch_write (mr=0x561035a81180, 
>> addr=0, data=9, size=1, attrs=...) at 
>> /work/src/qemu/up-mirror-dead-lock/memory.c:1452
>>   #14 0x0000561032083770 in flatview_write_continue (fv=0x7fd7f4108090, 
>> addr=49216, attrs=..., buf=0x7fd810309000 "\t\371\061", len=1, addr1=0, l=1, 
>> mr=0x561035a81180)
>>       at /work/src/qemu/up-mirror-dead-lock/exec.c:3233
>>   #15 0x00005610320838cf in flatview_write (fv=0x7fd7f4108090, addr=49216, 
>> attrs=..., buf=0x7fd810309000 "\t\371\061", len=1) at 
>> /work/src/qemu/up-mirror-dead-lock/exec.c:3272
>>   #16 0x0000561032083bef in address_space_write (as=0x561032dcdc40 
>> <address_space_io>, addr=49216, attrs=..., buf=0x7fd810309000 "\t\371\061", 
>> len=1) at /work/src/qemu/up-mirror-dead-lock/exec.c:3362
>>   #17 0x0000561032083c40 in address_space_rw (as=0x561032dcdc40 
>> <address_space_io>, addr=49216, attrs=..., buf=0x7fd810309000 "\t\371\061", 
>> len=1, is_write=true) at /work/src/qemu/up-mirror-dead-lock/exec.c:3373
>>   #18 0x0000561032104766 in kvm_handle_io (port=49216, attrs=..., 
>> data=0x7fd810309000, direction=1, size=1, count=1) at 
>> /work/src/qemu/up-mirror-dead-lock/accel/kvm/kvm-all.c:1775
>>   #19 0x0000561032104f0e in kvm_cpu_exec (cpu=0x561034d60240) at 
>> /work/src/qemu/up-mirror-dead-lock/accel/kvm/kvm-all.c:2021
>>   #20 0x00005610320ca396 in qemu_kvm_cpu_thread_fn (arg=0x561034d60240) at 
>> /work/src/qemu/up-mirror-dead-lock/cpus.c:1281
>>   #21 0x00005610326557ab in qemu_thread_start (args=0x561034d81a70) at 
>> util/qemu-thread-posix.c:498
>>   #22 0x00007fd80e87fdd5 in start_thread (arg=0x7fd7fc205700) at 
>> pthread_create.c:308
>>   #23 0x00007fd804c97b3d in clone () at 
>> ../sysdeps/unix/sysv/linux/x86_64/clone.S:113
>>   (gdb) fr 2
>>   #2  0x00007fd80e881cdf in __GI___pthread_mutex_lock (mutex=0x561034d25dc0) 
>> at ../nptl/pthread_mutex_lock.c:114
>>   114           LLL_MUTEX_LOCK (mutex);
>>   (gdb) p *mutex
>>   $2 = {__data = {__lock = 2, __count = 16, __owner = 145411, __nusers = 1, 
>> __kind = 1, __spins = 0, __elision = 0, __list = {__prev = 0x0, __next = 
>> 0x0}},
>>     __size = 
>> "\002\000\000\000\020\000\000\000\003\070\002\000\001\000\000\000\001", 
>> '\000' <repeats 22 times>, __align = 68719476738}
>>
>>   And thr2 wants aio context mutex, which is owned by thr1. Classic
>>   dead-lock.
>>
>>   But who took aio context? Suppose that it is mirror and check:
>>
>>   (gdb) p blk_next(0)->root->bs->job
>>   $3 = (BlockJob *) 0x5610358e2520
>>   (gdb) p (MirrorBlockJob *)$3
>>   $4 = (MirrorBlockJob *) 0x5610358e2520
>>   [...]
>>   (gdb) p $4->target->root->bs->tracked_requests.lh_first->co
>>   $7 = (Coroutine *) 0x561035dd0860
>>   [...]
>>   (gdb) qemu coroutine 0x561035dd0860
>>   #0  0x0000561032670ab2 in qemu_coroutine_switch (from_=0x561035dd0860, 
>> to_=0x7fd8102cfb80, action=COROUTINE_YIELD) at util/coroutine-ucontext.c:218
>>   #1  0x000056103266f0fc in qemu_coroutine_yield () at 
>> util/qemu-coroutine.c:194
>>   #2  0x000056103266fb76 in qemu_co_mutex_lock_slowpath (ctx=0x561034d25d60, 
>> mutex=0x561035c5a4b0) at util/qemu-coroutine-lock.c:235
>>   #3  0x000056103266fc82 in qemu_co_mutex_lock (mutex=0x561035c5a4b0) at 
>> util/qemu-coroutine-lock.c:273
>>   #4  0x0000561032544f4e in qcow2_co_pwritev (bs=0x561035b86890, 
>> offset=531628032, bytes=1048576, qiov=0x561034fd08a8, flags=0) at 
>> block/qcow2.c:2063
>>   #5  0x000056103258e5df in bdrv_driver_pwritev (bs=0x561035b86890, 
>> offset=531628032, bytes=1048576, qiov=0x561034fd08a8, flags=0) at 
>> block/io.c:1092
>>   #6  0x000056103259004b in bdrv_aligned_pwritev (child=0x561035b178c0, 
>> req=0x7fd7a23eae30, offset=531628032, bytes=1048576, align=1, 
>> qiov=0x561034fd08a8, flags=0) at block/io.c:1719
>>   #7  0x0000561032590cb2 in bdrv_co_pwritev (child=0x561035b178c0, 
>> offset=531628032, bytes=1048576, qiov=0x561034fd08a8, flags=0) at 
>> block/io.c:1961
>>   #8  0x0000561032578478 in blk_co_pwritev (blk=0x561035dd0400, 
>> offset=531628032, bytes=1048576, qiov=0x561034fd08a8, flags=0) at 
>> block/block-backend.c:1203
>>   #9  0x00005610325866a0 in mirror_read_complete (op=0x561034fd08a0, ret=0) 
>> at block/mirror.c:232
>>   #10 0x0000561032586e1a in mirror_co_read (opaque=0x561034fd08a0) at 
>> block/mirror.c:370
>>   #11 0x000056103267081d in coroutine_trampoline (i0=903678048, i1=22032) at 
>> util/coroutine-ucontext.c:116
>>   #12 0x00007fd804be0fc0 in __start_context () at /lib64/libc.so.6
>>   #13 0x00007fd7fafff600 in  ()
>>   #14 0x0000000000000000 in  ()
>>
>>   Ok, look at mirror_read_complete:
>>   static void coroutine_fn mirror_read_complete(MirrorOp *op, int ret)
>>   {
>>       MirrorBlockJob *s = op->s;
>>
>>       aio_context_acquire(blk_get_aio_context(s->common.blk));
>>       if (ret < 0) {
>>           BlockErrorAction action;
>>
>>           bdrv_set_dirty_bitmap(s->dirty_bitmap, op->offset, op->bytes);
>>           action = mirror_error_action(s, true, -ret);
>>           if (action == BLOCK_ERROR_ACTION_REPORT && s->ret >= 0) {
>>               s->ret = ret;
>>           }
>>
>>           mirror_iteration_done(op, ret);
>>       } else {
>>           ret = blk_co_pwritev(s->target, op->offset,
>>                                op->qiov.size, &op->qiov, 0);
>>           mirror_write_complete(op, ret);
>>       }
>>       aio_context_release(blk_get_aio_context(s->common.blk));
>>   }
>>
>>   Line 232 if blk_co_pwritev. So, we acquired aio context and go to
>>   write, which may yield, which makes the dead-lock possible.
>>
>>   And bisect points to
>>   commit 2e1990b26e5aa1ba1a730aa6281df123bb7a71b6 (refs/bisect/bad)
>>   Author: Max Reitz <address@hidden>
>>   Date:   Wed Jun 13 20:18:11 2018 +0200
>>
>>       block/mirror: Convert to coroutines
>>
>>   So, yes, 3.0 has the bug.
>>
>>   Interesting thing is that pair of aio_context_acquire / release exists
>>   even before that patch, and it was added in 2.9:
>>   commit b9e413dd3756f71abe4e8cafe1d7a459ce74ccf4
>>   Author: Paolo Bonzini <address@hidden>
>>   Date:   Mon Feb 13 14:52:32 2017 +0100
>>
>>       block: explicitly acquire aiocontext in aio callbacks that need it
>>
>>   In 2.9 mirror_read_complete was a callback for blk_aio_preadv. But
>>   honestly, I don't understand why it needed to acquire the context: it
>>   is inserted to this context as a BH, why it need to additionally
>>   acquire the context?
> 
> BHs don't automatically take the AioContext lock of the AioContext from
> which they are run.


so, if I call aio_bh_schedule_oneshot(aio_contex, cb), I can't be sure, that 
this
cb will run in this aio_context, and I should acquire aio_context in cb code?

Then, what means the first parameter of aio_bh_schedule_oneshot(), and is text
in docs/devel/multiple-iothreads.txt wrong, which sais:

   Side note: the best way to schedule a function call across threads is to call
   aio_bh_schedule_oneshot().  No acquire/release or locking is needed.


> 
>>   Anyway, after 2e1990b26e5 mirror_read/write_complete are not
>>   callbacks, so, even if b9e413dd3 was OK, it doesn't relate to this
>>   place now.
> 
> I guess in this specific instance we can just remove the locking from
> mirror_read/write_complete becasue it's only locking an AioContext whose
> lock we already hold anyway because we're in a Coroutine owned by the
> AioContext, so yielding will release the lock and avoid the deadlock.
> 
> But more generally, does this mean that it is never correct to have an
> explicit aio_context_acquire/release() pair in coroutine context, at
> least for all practical cases where you call things that could yield?
> And if you're inside a coroutine and want to access something in a
> different AioContext, you need to drop out of the coroutine first?
> 
> If so, should aio_context_acquire() then assert that it's not called
> from coroutine context?
> 
> Paolo, will this restriction of coroutines be solved for good when you
> get your patches merged that remove the AioContext lock?
> 
> Kevin
> 


-- 
Best regards,
Vladimir