[Gluster-devel] Spurious regression of tests/basic/mgmt_v3-locks.t

Wed Dec 3 16:23:17 UTC 2014

On 12/03/2014 07:36 PM, Justin Clift wrote:
> On Tue, 02 Dec 2014 10:05:36 +0530
> Atin Mukherjee <amukherj at redhat.com> wrote:
> <snip>
>> Its on my radar, I am in progress of analysing it. The last patch set
>> was on the clean up part of the test cases, I felt the changes could
>> have solved it, but I am afraid it didn't. I tried to reproduce it
>> multiple times in my local set up but couldn't. Initial analysis finds
>> out that one of glusterd node got disconnect when multiple volume set
>> transactions were in progress, reason is still unknown.  I will keep
>> you posted once I find any significant details.
> 
> The worrying thing (to me), is that this could be a bug that's happening
> for people in real world usage, and not just something happening in our
> regression testing.
Agreed Justin. It looks like a bug only.
I found something significant now. I wrote a small script to execute two
volume set commands in parallel (for two different volumes) in a loop of
1000 iterations and I figured out glusterd hung after few iterations.
Glusterd was not dead but it didn't respond at all.

Following is the backtrace:

Thread 6 (Thread 0x7f6f6ecf5700 (LWP 30417)):
#0  0x00007f6f76d67fbd in nanosleep () from /lib64/libpthread.so.0
#1  0x00007f6f77a04014 in gf_timer_proc (ctx=0x1396010) at timer.c:170
#2  0x00007f6f76d60f33 in start_thread () from /lib64/libpthread.so.0
#3  0x00007f6f766a7ded in clone () from /lib64/libc.so.6

Thread 5 (Thread 0x7f6f6e4f4700 (LWP 30418)):
#0  0x00007f6f76d684f1 in sigwait () from /lib64/libpthread.so.0
#1  0x00000000004079e7 in glusterfs_sigwaiter (arg=<optimized out>) at
glusterfsd.c:1728
#2  0x00007f6f76d60f33 in start_thread () from /lib64/libpthread.so.0
#3  0x00007f6f766a7ded in clone () from /lib64/libc.so.6

Thread 4 (Thread 0x7f6f6dcf3700 (LWP 30419)):
#0  0x00007f6f76d6759d in __lll_lock_wait () from /lib64/libpthread.so.0
#1  0x00007f6f76d63194 in _L_lock_874 () from /lib64/libpthread.so.0
#2  0x00007f6f76d63093 in pthread_mutex_lock () from /lib64/libpthread.so.0
#3  0x00007f6f766e2612 in _dl_addr () from /lib64/libc.so.6
#4  0x00007f6f766b67d5 in backtrace_symbols_fd () from /lib64/libc.so.6
#5  0x00007f6f779fdc88 in gf_backtrace_fillframes (
    buf=buf at entry=0x13eb280 "(-->
/usr/local/lib/libglusterfs.so.0(synctask_yield+0x2c)[0x7f6f77a21cac]
(--> /usr/local/lib/libglusterfs.so.0(+0x57dc9)[0x7f6f77a21dc9] (-->
/usr/local/lib/libglusterfs.so.0(synclock_lock+0x16)[0x7"...) at
common-utils.c:3335
---Type <return> to continue, or q <return> to quit---
#6  0x00007f6f77a03631 in gf_backtrace_save (
    buf=buf at entry=0x13eb280 "(-->
/usr/local/lib/libglusterfs.so.0(synctask_yield+0x2c)[0x7f6f77a21cac]
(--> /usr/local/lib/libglusterfs.so.0(+0x57dc9)[0x7f6f77a21dc9] (-->
/usr/local/lib/libglusterfs.so.0(synclock_lock+0x16)[0x7"...) at
common-utils.c:3391
#7  0x00007f6f77a21cac in synctask_yield (task=task at entry=0x13eadf0) at
syncop.c:296
#8  0x00007f6f77a21dc9 in __synclock_lock (lock=lock at entry=0x13e0138) at
syncop.c:760
#9  0x00007f6f77a24586 in synclock_lock (lock=lock at entry=0x13e0138) at
syncop.c:784
#10 0x00007f6f6ca3242d in glusterd_big_locked_cbk (req=0x13e34ec,
iov=0x0, count=0,
    myframe=0x7f6f759ff24c, fn=0x7f6f6ca766d0 <_gd_syncop_stage_op_cbk>)
    at glusterd-rpc-ops.c:207
#11 0x00007f6f777be9ff in rpc_clnt_submit (rpc=rpc at entry=0x13e3260,
    prog=prog at entry=0x7f6f6cce9ca0 <gd_mgmt_prog>, procnum=procnum at entry=3,
    cbkfn=cbkfn at entry=0x7f6f6ca75330 <gd_syncop_stage_op_cbk>,
    proghdr=proghdr at entry=0x17eb970, proghdrcount=proghdrcount at entry=1,
    progpayload=progpayload at entry=0x0,
progpayloadcount=progpayloadcount at entry=0,
    iobref=iobref at entry=0x7f6f4bd4a9c0, frame=frame at entry=0x7f6f759ff24c,
    rsphdr=rsphdr at entry=0x0, rsphdr_count=rsphdr_count at entry=0,
    rsp_payload=rsp_payload at entry=0x0,
rsp_payload_count=rsp_payload_count at entry=0,
    rsp_iobref=rsp_iobref at entry=0x0) at rpc-clnt.c:1601
#12 0x00007f6f6ca76470 in gd_syncop_submit_request (rpc=0x13e3260,
    req=req at entry=0x7f6f60239830, local=local at entry=0x17ebaa0,
    cookie=cookie at entry=0x13e2770, prog=0x7f6f6cce9ca0 <gd_mgmt_prog>,
    procnum=procnum at entry=3, cbkfn=cbkfn at entry=0x7f6f6ca75330
<gd_syncop_stage_op_cbk>,
---Type <return> to continue, or q <return> to quit---
    xdrproc=0x7f6f775a4910 <xdr_gd1_mgmt_stage_op_req>) at
glusterd-syncop.c:198
#13 0x00007f6f6ca773d6 in gd_syncop_mgmt_stage_op
(peerinfo=peerinfo at entry=0x13e2770,
    args=args at entry=0x17ebaa0,
    my_uuid=my_uuid at entry=0x13deff8
"y\205mKLMF\340\241\366\340\037#\227$x/var/lib/glusterd",
recv_uuid=recv_uuid at entry=0x17eba90 "", op=op at entry=11,
    dict_out=dict_out at entry=0x7f6f754045e4,
op_ctx=op_ctx at entry=0x7f6f754045e4)
    at glusterd-syncop.c:749
#14 0x00007f6f6ca77d4b in gd_stage_op_phase (peers=peers at entry=0x13defe0,
    op=<optimized out>, op_ctx=op_ctx at entry=0x7f6f754045e4,
req_dict=0x7f6f754045e4,
    op_errstr=op_errstr at entry=0x17ec2a8, npeers=npeers at entry=1) at
glusterd-syncop.c:1169
#15 0x00007f6f6ca790b8 in gd_sync_task_begin
(op_ctx=op_ctx at entry=0x7f6f754045e4,
    req=req at entry=0x13da238) at glusterd-syncop.c:1619
#16 0x00007f6f6ca7928c in glusterd_op_begin_synctask
(req=req at entry=0x13da238,
    op=op at entry=GD_OP_SET_VOLUME, dict=0x7f6f754045e4) at
glusterd-syncop.c:1680
#17 0x00007f6f6c9e52e6 in __glusterd_handle_set_volume
(req=req at entry=0x13da238)
    at glusterd-handler.c:1762
#18 0x00007f6f6c9f1d60 in glusterd_big_locked_handler (req=0x13da238,
    actor_fn=0x7f6f6c9e4dd0 <__glusterd_handle_set_volume>) at
glusterd-handler.c:79
#19 0x00007f6f77a21d32 in synctask_wrap (old_task=<optimized out>) at
syncop.c:335
#20 0x00007f6f765faa00 in ?? () from /lib64/libc.so.6
#21 0x0000000000000000 in ?? ()

Thread 3 (Thread 0x7f6f6d4f2700 (LWP 30420)):
---Type <return> to continue, or q <return> to quit---
#0  0x00007f6f76d650c9 in pthread_cond_timedwait@@GLIBC_2.3.2 () from
/lib64/libpthread.so.0
#1  0x00007f6f77a237ef in syncenv_task (proc=proc at entry=0x13bfe90) at
syncop.c:535
#2  0x00007f6f77a24370 in syncenv_processor (thdata=0x13bfe90) at
syncop.c:613
#3  0x00007f6f76d60f33 in start_thread () from /lib64/libpthread.so.0
#4  0x00007f6f766a7ded in clone () from /lib64/libc.so.6

Thread 2 (Thread 0x7f6f6564a700 (LWP 30546)):
#0  0x00007f6f76d64d20 in pthread_cond_wait@@GLIBC_2.3.2 () from
/lib64/libpthread.so.0
#1  0x00007f6f6ca7a183 in hooks_worker (args=<optimized out>) at
glusterd-hooks.c:502
#2  0x00007f6f76d60f33 in start_thread () from /lib64/libpthread.so.0
#3  0x00007f6f766a7ded in clone () from /lib64/libc.so.6

Thread 1 (Thread 0x7f6f77e7c740 (LWP 30416)):
#0  0x00007f6f766e26bf in _dl_addr () from /lib64/libc.so.6
#1  0x00007f6f766b67d5 in backtrace_symbols_fd () from /lib64/libc.so.6
#2  0x00007f6f779fdc88 in gf_backtrace_fillframes (
    buf=buf at entry=0x1396378 "(-->
/usr/local/lib/libglusterfs.so.0(_gf_log_callingfn+0x15c)[0x7f6f779ea1bc] (-->
/usr/local/lib/libgfrpc.so.0(saved_frames_unwind+0x1c2)[0x7f6f777bd942]
(--> /usr/local/lib/libgfrpc.so.0(saved_fram"...) at common-utils.c:3335
#3  0x00007f6f77a03631 in gf_backtrace_save (buf=buf at entry=0x0) at
common-utils.c:3391
#4  0x00007f6f779ea1bc in _gf_log_callingfn (domain=0x13e62b0 "management",
    file=file at entry=0x7f6f777c4746 "rpc-clnt.c",
    function=function at entry=0x7f6f777c4ff0 <__FUNCTION__.13438>
"saved_frames_unwind",
---Type <return> to continue, or q <return> to quit---
    line=line at entry=362, level=level at entry=GF_LOG_ERROR,
    fmt=fmt at entry=0x7f6f777c4930 "forced unwinding frame type(%s)
op(%s(%d)) called at %s (xid=0x%x)") at logging.c:822
#5  0x00007f6f777bd942 in saved_frames_unwind
(saved_frames=saved_frames at entry=0x13e71e0)
    at rpc-clnt.c:353
#6  0x00007f6f777bda3e in saved_frames_destroy (frames=0x13e71e0) at
rpc-clnt.c:383
#7  0x00007f6f777bf22c in rpc_clnt_connection_cleanup
(conn=conn at entry=0x13e3290)
    at rpc-clnt.c:536
#8  0x00007f6f777bf9c8 in rpc_clnt_notify (trans=<optimized out>,
mydata=0x13e3290,
    event=<optimized out>, data=<optimized out>) at rpc-clnt.c:843
#9  0x00007f6f777bbd33 in rpc_transport_notify (this=this at entry=0x13e62f0,
    event=event at entry=RPC_TRANSPORT_DISCONNECT, data=data at entry=0x13e62f0)
    at rpc-transport.c:516
#10 0x00007f6f66850962 in socket_event_poll_err (this=0x13e62f0) at
socket.c:1161
#11 socket_event_handler (fd=<optimized out>, idx=3,
data=data at entry=0x13e62f0, poll_in=1,
    poll_out=4, poll_err=<optimized out>) at socket.c:2353
#12 0x00007f6f77a3dd82 in event_dispatch_epoll_handler (i=<optimized
out>, events=0x13e0700,
    event_pool=0x13b43c0) at event-epoll.c:384
#13 event_dispatch_epoll (event_pool=0x13b43c0) at event-epoll.c:445
#14 0x0000000000404e89 in main (argc=1, argv=0x7fff7a929408) at
glusterfsd.c:2046

>From the backtrace I could figure out problematic area is in Thread 1 &
4, probably a deadlock. Need to analyse it, I will be in a training for
the entire week, will jump into it in early next week.

~Atin

> 
> Until we've figured it out / understand the root cause, we don't know.
> 
> :(
> 
> + Justin
> 