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

Tue Dec 9 04:16:45 UTC 2014

Justin,

I could only get a chance to look into this yesterday as last week I was
in RHEL 7 training. I've some interesting facts to share which is as
follows:

When I execute the script which sets options for two different volumes
(one in background) in a loop, after few iterations the memory
consumption of glusterd jumps to more than 1G. The iteration cycle of
the occurrence is not fixed though. However there is a constant increase
in memory consumption in every iteration which proves that there is
certainly a memory leak here. I am going to spend some time today to
debug it further and hope to get the root cause.

~Atin

On 12/09/2014 03:43 AM, Justin Clift wrote:
> How's this investigation stuff going? :)
> 
> + Justin
> 
> 
> ----- Original Message -----
>> 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
>>
> 