Re: [Qemu-devel] [Questions] NBD issue or CoMutex->holder issue?

2016-10-11 Thread Changlong Xie 

On 10/11/2016 06:47 PM, Paolo Bonzini wrote:

the free_sema->queue head, so set free_sema->holder as
>revelant coroutine.

NBD is using the CoMutex in a way that wasn't anticipated.  The simplest
fix is to change it to CoQueue, which is like a condition variable.
Instead of locking if in_flight >= MAX_NBD_REQUESTS - 1, wait on the
queue while in_flight == MAX_NBD_REQUESTS.  Instead of unlocking, use
qemu_co_queue_next to wake up one request.



Thanks for your explanation! will send out a patch later.


Thanks
-Xie


Thanks for the report!

Paolo


>For example if there are N(N=26 and MAX_NBD_REQUESTS=16) nbd write
>requests, so we'll invoke nbd_client_co_pwritev 26 times.
>time request No   Actions
>1 1   in_flight=1, Coroutine=C1
>2 2   in_flight=2, Coroutine=C2

Re: [Qemu-devel] [Questions] NBD issue or CoMutex->holder issue?

2016-10-11 Thread Paolo Bonzini 


On 11/10/2016 12:35, Changlong Xie wrote:
> For nbd client, if request number is large than MAX_NBD_REQUESTS(16), we
> will queue the rest requests into free_sema->queue.
> When nbd client receives one reply,  it will unlock free_sema, then pop
> the free_sema->queue head, so set free_sema->holder as
> revelant coroutine.

NBD is using the CoMutex in a way that wasn't anticipated.  The simplest
fix is to change it to CoQueue, which is like a condition variable.
Instead of locking if in_flight >= MAX_NBD_REQUESTS - 1, wait on the
queue while in_flight == MAX_NBD_REQUESTS.  Instead of unlocking, use
qemu_co_queue_next to wake up one request.

Thanks for the report!

Paolo

> For example if there are N(N=26 and MAX_NBD_REQUESTS=16) nbd write
> requests, so we'll invoke nbd_client_co_pwritev 26 times.
> time request No   Actions
> 1 1   in_flight=1, Coroutine=C1
> 2 2   in_flight=2, Coroutine=C2
> ...   ...
> 1515  in_flight=15, Coroutine=C15
> 1616  in_flight=16, Coroutine=C16,
> free_sema->holder=C16, mutex->locked=true
> 1717  in_flight=16, Coroutine=C17, queue C17 into
> free_sema->queue
> 1818  in_flight=16, Coroutine=C18, queue C18 into
> free_sema->queue
> ...   ...
> 26N   in_flight=16, Coroutine=C26, queue C26 into
> free_sema->queue
> 
> Once nbd client recieves request No.16' reply, we will re-enter request
> C16. It's ok, because it's equal to 'free_sema->holder'.
> time request No   Actions
> 2716  in_flight=15, Coroutine=C16,
> free_sema->holder=C16, mutex->locked=false
> 
> Then nbd_coroutine_end invokes qemu_co_mutex_unlock, what will pop
> coroutines from free_sema->queue's head and enter C17. More
> free_sema->holder is C17 now.
> time request No   Actions
> 2817  in_flight=16, Coroutine=C17,
> free_sema->holder=C17, mutex->locked=true
> 
> In above scenario, we only recieves request No.16' reply. So as time go
> on, nbd client will almostly recieves replies from requests
> 1 to 15 rather than request 17 who owns C17. In this case, we will
> encounter Assertion "`mutex->holder == self' failed" in nbd_coroutine_end.
> For example, if nbd client recieves request No.15' reply:
> time request No  Actions
> 29   15(most case)   in_flight=15, Coroutine=C15,
> free_sema->holder=C17, mutex->locked = false
> 
> qemu-system-x86_64: util/qemu-coroutine-lock.c:148:
> qemu_co_mutex_unlock: Assertion `mutex->holder == self' failed.
> 
> This is introduced by Kevin's patch
> commit 0e438cdc932a785de72166af4641aafa103a6670
> Author: Kevin Wolf 
> Date:   Thu Aug 11 17:45:06 2016 +0200
> 
> coroutine: Let CoMutex remember who holds it
> 
> In cases of deadlocks, knowing who holds a given CoMutex is really
> helpful for debugging. Keeping the information around doesn't cost much
> and allows us to add another assertion to keep the code correct, so
> let's just add it.
> 
> Signed-off-by: Kevin Wolf 
> Reviewed-by: Paolo Bonzini 
> Reviewed-by: Stefan Hajnoczi 
> 
> Any ideas? Is it a nbd bug or should we revert commit 0e438cdc?
> 
> Thanks
> -Xie
> 
>

[Qemu-devel] [Questions] NBD issue or CoMutex->holder issue?

2016-10-11 Thread Changlong Xie 

Hi all

Recently during test COLO, i encounter some problems. Here is the backtrace

qemu-system-x86_64: util/qemu-coroutine-lock.c:148: 
qemu_co_mutex_unlock: Assertion `mutex->holder == self' failed.

[New Thread 0x7fff0e7fc700 (LWP 20936)]

Program received signal SIGABRT, Aborted.
0x75cac5d7 in raise () from /lib64/libc.so.6
Missing separate debuginfos, use: debuginfo-install 
glib2-2.40.0-4.el7.x86_64 glibc-2.17-78.el7.x86_64 
gmp-6.0.0-11.el7.x86_64 gnutls-3.3.8-12.el7.x86_64 
keyutils-libs-1.5.8-3.el7.x86_64 krb5-libs-1.12.2-14.el7.x86_64 
libcom_err-1.42.9-7.el7.x86_64 libffi-3.0.13-11.el7.x86_64 
libgcc-4.8.3-9.el7.x86_64 libselinux-2.2.2-6.el7.x86_64 
libstdc++-4.8.3-9.el7.x86_64 libtasn1-3.8-2.el7.x86_64 
nettle-2.7.1-4.el7.x86_64 openssl-libs-1.0.1e-42.el7.x86_64 
p11-kit-0.20.7-3.el7.x86_64 pcre-8.32-14.el7.x86_64 
pixman-0.32.4-3.el7.x86_64 trousers-0.3.11.2-3.el7.x86_64 
xz-libs-5.1.2-9alpha.el7.x86_64 zlib-1.2.7-13.el7.x86_64

(gdb) bt
#0  0x75cac5d7 in raise () from /lib64/libc.so.6
#1  0x75cadcc8 in abort () from /lib64/libc.so.6
#2  0x75ca5546 in __assert_fail_base () from /lib64/libc.so.6
#3  0x75ca55f2 in __assert_fail () from /lib64/libc.so.6
#4  0x55bdb096 in qemu_co_mutex_unlock (mutex=0x56899490) at 
util/qemu-coroutine-lock.c:148
#5  0x55b5663f in nbd_coroutine_end (s=0x56899450, 
request=0x7fffea5ff940) at block/nbd-client.c:227
#6  0x55b56931 in nbd_client_co_pwritev (bs=0x56890800, 
offset=4820434944, bytes=4096, qiov=0x5688db80, flags=0) at 
block/nbd-client.c:288
#7  0x55b4f8c7 in bdrv_driver_pwritev (bs=0x56890800, 
offset=4820434944, bytes=4096, qiov=0x5688db80, flags=0) at 
block/io.c:843
#8  0x55b50e23 in bdrv_aligned_pwritev (bs=0x56890800, 
req=0x7fffea5ffb70, offset=4820434944, bytes=4096, align=1, 
qiov=0x5688db80, flags=0)

at block/io.c:1322
#9  0x55b51ac4 in bdrv_co_pwritev (child=0x5698e020, 
offset=4820434944, bytes=4096, qiov=0x5688db80, flags=0) at 
block/io.c:1571
#10 0x55b51b8b in bdrv_co_do_writev (child=0x5698e020, 
sector_num=9414912, nb_sectors=8, qiov=0x5688db80, flags=0) at 
block/io.c:1595
#11 0x55b51bda in bdrv_co_writev (child=0x5698e020, 
sector_num=9414912, nb_sectors=8, qiov=0x5688db80) at block/io.c:1604
#12 0x55b60c61 in replication_co_writev (bs=0x56d76b30, 
sector_num=9414912, remaining_sectors=8, qiov=0x5688db80) at 
block/replication.c:250
#13 0x55b4fa3a in bdrv_driver_pwritev (bs=0x56d76b30, 
offset=4820434944, bytes=4096, qiov=0x5688db80, flags=0) at 
block/io.c:862
#14 0x55b50e23 in bdrv_aligned_pwritev (bs=0x56d76b30, 
req=0x7fffea5ffef0, offset=4820434944, bytes=4096, align=512, 
qiov=0x5688db80, flags=0)

at block/io.c:1322
#15 0x55b51ac4 in bdrv_co_pwritev (child=0x56a5e160, 
offset=4820434944, bytes=4096, qiov=0x5688db80, flags=0) at 
block/io.c:1571
#16 0x55b52ae5 in bdrv_co_do_rw (opaque=0x575e7860) at 
block/io.c:2137
#17 0x55bdb6bb in coroutine_trampoline (i0=1470076720, i1=21845) 
at util/coroutine-ucontext.c:79

#18 0x75cbe0f0 in ?? () from /lib64/libc.so.6
#19 0x7fffd320 in ?? ()

And I found you can easily reproduce it with nbd enable.

For nbd client, if request number is large than MAX_NBD_REQUESTS(16), we 
will queue the rest requests into free_sema->queue.
When nbd client receives one reply,  it will unlock free_sema, then pop 
the free_sema->queue head, so set free_sema->holder as

revelant coroutine.

For example if there are N(N=26 and MAX_NBD_REQUESTS=16) nbd write 
requests, so we'll invoke nbd_client_co_pwritev 26 times.
time request No   Actions 


1 1   in_flight=1, Coroutine=C1
2 2   in_flight=2, Coroutine=C2
...   ...
1515  in_flight=15, Coroutine=C15
1616  in_flight=16, Coroutine=C16, 
free_sema->holder=C16, mutex->locked=true
1717  in_flight=16, Coroutine=C17, queue C17 into 
free_sema->queue
1818  in_flight=16, Coroutine=C18, queue C18 into 
free_sema->queue

...   ...
26N   in_flight=16, Coroutine=C26, queue C26 into 
free_sema->queue


Once nbd client recieves request No.16' reply, we will re-enter request 
C16. It's ok, because it's equal to 'free_sema->holder'.

time request No   Actions
2716  in_flight=15, Coroutine=C16, 
free_sema->holder=C16, mutex->locked=false


Then nbd_coroutine_end invokes qemu_co_mutex_unlock, what will pop 
coroutines from free_sema->queue's head and enter C17. More

free_sema->holder is C17 now.
time request No   Actions
2817  in_flight=16, Coroutine=C17, 
free_sema->holder=C17, mutex->locked=true


In above scenario, we only recieves request No.16' reply. So as time go 
on, nbd client will almostly recieves replies from requests
1 to 15 rather than req