Bug 764428 (GLUSTER-2696)

Server and client on a same machine.
$ uname -a
Linux repository 2.6.18-194.32.1.el5 #1 SMP Wed Jan 5 17:52:25 EST 2011 x86_64 x86_64 x86_64 GNU/Linux
$ cat /etc/redhat-release
CentOS release 5.5 (Final)

Given volfile:
+------------------------------------------------------------------------------+
  1: volume smb01-part01-posix
  2: 	type storage/posix
  3: 	option directory /mnt/gluster01/smb01.part01
  4: 	option background-unlink yes
  5: end-volume
  6: 
  7: volume smb01-part01-acl
  8: 	type features/access-control
  9: 	subvolumes smb01-part01-posix
 10: end-volume
 11: 
 12: volume smb01-part01-locks
 13: 	type features/locks
 14: 	option mandatory-locks on
 15: 	subvolumes smb01-part01-acl
 16: end-volume
 17: 
 18: volume smb01-part01
 19: 	type performance/io-threads
 20: 	subvolumes smb01-part01-locks
 21: end-volume
 22: 
 23: volume smb01-part02-posix
 24: 	type storage/posix
 25: 	option directory /mnt/gluster02/smb01.part02
 26: 	option background-unlink yes
 27: end-volume
 28: 
 29: volume smb01-part02-acl
 30: 	type features/access-control
 31: 	subvolumes smb01-part02-posix
 32: end-volume
 33: 
 34: volume smb01-part02-locks
 35: 	type features/locks
 36: 	option mandatory-locks on
 37: 	subvolumes smb01-part02-acl
 38: end-volume
 39: 
 40: volume smb01-part02
 41: 	type performance/io-threads
 42: 	subvolumes smb01-part02-locks
 43: end-volume
 44: 
 45: volume smb01-part03-posix
 46: 	type storage/posix
 47: 	option directory /mnt/gluster03/smb01.part03
 48: 	option background-unlink yes
 49: end-volume
 50: 
 51: volume smb01-part03-acl
 52: 	type features/access-control
 53: 	subvolumes smb01-part03-posix
 54: end-volume
 55: 
 56: volume smb01-part03-locks
 57: 	type features/locks
 58: 	option mandatory-locks on
 59: 	subvolumes smb01-part03-acl
 60: end-volume
 61: 
 62: volume smb01-part03
 63: 	type performance/io-threads
 64: 	subvolumes smb01-part03-locks
 65: end-volume
 66: 
 67: volume smb01-client
 68: 	type cluster/distribute
 69: 	option lookup-unhashed auto
 70: 	subvolumes smb01-part01 smb01-part02 smb01-part03
 71: end-volume
 72: 
 73: volume smb01-write-behind
 74: 	type performance/write-behind
 75: 	option cache-size 2560KB
 76: 	subvolumes smb01-client
 77: end-volume
 78: 
 79: volume smb01-read-ahead
 80: 	type performance/read-ahead
 81: 	subvolumes smb01-write-behind
 82: end-volume
 83: 
 84: volume smb01-io-cache
 85: 	type performance/io-cache
 86: 	subvolumes smb01-read-ahead
 87: end-volume
 88: 
 89: volume smb01-io-stats
 90: 	type debug/io-stats
 91: 	option latency-measurement on
 92: 	subvolumes smb01-io-cache
 93: end-volume
 94: 
 95: volume smb01
 96: 	type performance/stat-prefetch
 97: 	subvolumes smb01-io-stats
 98: end-volume

+------------------------------------------------------------------------------+
pending frames:
frame : type(1) op(STAT)

patchset: v3.1.3
signal received: 11
time of crash: 2011-04-08 09:25:04
configuration details:
argp 1
backtrace 1
dlfcn 1
fdatasync 1
libpthread 1
llistxattr 1
setfsid 1
spinlock 1
epoll.h 1
xattr.h 1
st_atim.tv_nsec 1
package-string: glusterfs 3.1.3
/lib64/libc.so.6[0x3afde302d0]
/opt/glusterfs/3.1.3/lib64/glusterfs/3.1.3/xlator/performance/io-threads.so(iot_stat_wrapper+0x6b)[0x2aaac200a05b]
/opt/glusterfs/3.1.3/lib64/libglusterfs.so.0(call_resume+0x6a6)[0x2b60f0983ca6]
/opt/glusterfs/3.1.3/lib64/glusterfs/3.1.3/xlator/performance/io-threads.so(iot_worker+0x119)[0x2aaac200f119]
/lib64/libpthread.so.0[0x3afe60673d]
/lib64/libc.so.6(clone+0x6d)[0x3afded3f6d]
---------

Without io-threads all works stable with uptime more then a week, but latency is terrible. With io-threads (as shown in volfile) two instance of command 'du -hs /mnt/smb01' throw a segfault within several minites.

Launch a GDB:
# gdb /opt/glusterfs/3.1.3/sbin/glusterfs core.27743
Core was generated by `/opt/glusterfs/3.1.3/sbin/glusterfs --log-level=NORMAL --direct-io-mode=off --v'.
Program terminated with signal 11, Segmentation fault.
#0  0x00002aaac200a05b in iot_stat_wrapper (frame=0x2aaabd6bf070, this=0x1d587ee0, loc=0x2b60f1c87a6c)
    at io-threads.c:1079
1079            STACK_WIND (frame, iot_stat_cbk,
(gdb) bt full
#0  0x00002aaac200a05b in iot_stat_wrapper (frame=0x2aaabd6bf070, this=0x1d587ee0, loc=0x2b60f1c87a6c)
    at io-threads.c:1079
        _new = <value optimized out>
        old_THIS = <value optimized out>
        __FUNCTION__ = "iot_stat_wrapper"
#1  0x00002b60f0983ca6 in call_resume_wind (stub=0x2b60f1c87a34) at call-stub.c:2138
        __FUNCTION__ = "call_resume_wind"
#2  call_resume (stub=0x2b60f1c87a34) at call-stub.c:3870
        old_THIS = 0x1d587ee0
        __FUNCTION__ = "call_resume"
#3  0x00002aaac200f119 in iot_worker (data=0x2aaab7019490) at io-threads.c:129
        conf = <value optimized out>
        this = <value optimized out>
        stub = 0x2b60f1c87a34
        sleep_till = {tv_sec = 1302233224, tv_nsec = 0}
        ret = <value optimized out>
        timeout = 0 '\000'
        bye = 0 '\000'
        __FUNCTION__ = "iot_worker"
#4  0x0000003afe60673d in start_thread () from /lib64/libpthread.so.0
No symbol table info available.
#5  0x0000003afded3f6d in clone () from /lib64/libc.so.6
No symbol table info available.

(gdb) x/38i iot_stat_wrapper
0x2aaac2009ff0 <iot_stat_wrapper>:      mov    %rbx,-0x20(%rsp)
0x2aaac2009ff5 <iot_stat_wrapper+5>:    mov    %rbp,-0x18(%rsp)
0x2aaac2009ffa <iot_stat_wrapper+10>:   mov    %rdi,%rbx
0x2aaac2009ffd <iot_stat_wrapper+13>:   mov    %r12,-0x10(%rsp)
0x2aaac200a002 <iot_stat_wrapper+18>:   mov    %r13,-0x8(%rsp)
0x2aaac200a007 <iot_stat_wrapper+23>:   sub    $0x28,%rsp
0x2aaac200a00b <iot_stat_wrapper+27>:   mov    (%rdi),%rax
0x2aaac200a00e <iot_stat_wrapper+30>:   mov    %rsi,%r12
0x2aaac200a011 <iot_stat_wrapper+33>:   mov    %rdx,%r13
0x2aaac200a014 <iot_stat_wrapper+36>:   mov    0x10(%rax),%rax
0x2aaac200a018 <iot_stat_wrapper+40>:   mov    0x20(%rax),%rdi
0x2aaac200a01c <iot_stat_wrapper+44>:   callq  0x2aaac20057e8 <mem_get0@plt>
0x2aaac200a021 <iot_stat_wrapper+49>:   test   %rax,%rax
0x2aaac200a024 <iot_stat_wrapper+52>:   mov    %rax,%rbp
0x2aaac200a027 <iot_stat_wrapper+55>:   je     0x2aaac200a0e5 <iot_stat_wrapper+245>
0x2aaac200a02d <iot_stat_wrapper+61>:   mov    (%rbx),%rax
0x2aaac200a030 <iot_stat_wrapper+64>:   mov    %rax,0x0(%rbp)
0x2aaac200a034 <iot_stat_wrapper+68>:   mov    (%rbx),%rdx
0x2aaac200a037 <iot_stat_wrapper+71>:   mov    0x98(%rdx),%rax
0x2aaac200a03e <iot_stat_wrapper+78>:   mov    %rax,0x10(%rbp)
0x2aaac200a042 <iot_stat_wrapper+82>:   mov    %rdx,%rax
0x2aaac200a045 <iot_stat_wrapper+85>:   add    $0x88,%rax
0x2aaac200a04b <iot_stat_wrapper+91>:   mov    %rax,0x18(%rbp)
0x2aaac200a04f <iot_stat_wrapper+95>:   mov    0x98(%rdx),%rax
0x2aaac200a056 <iot_stat_wrapper+102>:  test   %rax,%rax
0x2aaac200a059 <iot_stat_wrapper+105>:  je     0x2aaac200a05f <iot_stat_wrapper+111>
0x2aaac200a05b <iot_stat_wrapper+107>:  mov    %rbp,0x18(%rax)
0x2aaac200a05f <iot_stat_wrapper+111>:  mov    0x28(%r12),%rax
0x2aaac200a064 <iot_stat_wrapper+116>:  lea    0x3c(%rbp),%rdi
0x2aaac200a068 <iot_stat_wrapper+120>:  mov    %rbp,0x98(%rdx)
0x2aaac200a06f <iot_stat_wrapper+127>:  xor    %esi,%esi
0x2aaac200a071 <iot_stat_wrapper+129>:  mov    %rbx,0x8(%rbp)
0x2aaac200a075 <iot_stat_wrapper+133>:  mov    %rbp,0x40(%rbp)
0x2aaac200a079 <iot_stat_wrapper+137>:  mov    (%rax),%rax
0x2aaac200a07c <iot_stat_wrapper+140>:  mov    %rax,0x28(%rbp)
0x2aaac200a080 <iot_stat_wrapper+144>:
    mov    0x207de1(%rip),%rax        # 0x2aaac2211e68 <iot_schedule_fast+2147072>
0x2aaac200a087 <iot_stat_wrapper+151>:  mov    %rax,0x30(%rbp)
0x2aaac200a08b <iot_stat_wrapper+155>:  callq  0x2aaac20057a8 <pthread_spin_init@plt>

This dump correspond to
---------
iot_stat_wrapper (call_frame_t *frame, xlator_t *this, loc_t *loc)
{
	STACK_WIND (frame, iot_stat_cbk,
		    FIRST_CHILD(this),
		    FIRST_CHILD(this)->fops->stat,
		    loc);
---------
which unroll as
#define STACK_WIND(frame, rfn, obj, fn, params ...)			\
	do {								\
		call_frame_t *_new = NULL;				\
                xlator_t     *old_THIS = NULL;                          \
                                                                        \
		 _new = mem_get0 (frame->root->pool->frame_mem_pool);     \
                if (!_new) {                                            \
                        gf_log ("stack", GF_LOG_ERROR, "alloc failed"); \
                        break;                                          \
                }                                                       \
		typeof(fn##_cbk) tmp_cbk = rfn;				\
		_new->root = frame->root;				\
		_new->next = frame->root->frames.next;			\
		_new->prev = &frame->root->frames;			\
		if (frame->root->frames.next)				\
			frame->root->frames.next->prev = _new;		\
		frame->root->frames.next = _new;			\
		_new->this = obj;					\
		_new->ret = (ret_fn_t) tmp_cbk;				\
		_new->parent = frame;					\
		_new->cookie = _new;					\
		LOCK_INIT (&_new->lock);				\

Segfault point:
(gdb) p/a $rip
$13 = 0x2aaac200a05b <iot_stat_wrapper+107>

Code region is:
0x2aaac200a04f <iot_stat_wrapper+95>:   mov    0x98(%rdx),%rax
0x2aaac200a056 <iot_stat_wrapper+102>:  test   %rax,%rax
0x2aaac200a059 <iot_stat_wrapper+105>:  je     0x2aaac200a05f <iot_stat_wrapper+111>
0x2aaac200a05b <iot_stat_wrapper+107>:  mov    %rbp,0x18(%rax)

		if (frame->root->frames.next)				\
			frame->root->frames.next->prev = _new;		\

Printing a registers content (_new are optimized and stored in rbp):
(gdb) p/a $rbp
$15 = 0x2aaaafe32f90
(gdb) p frame->root
$16 = (call_stack_t *) 0x2b60f1a5e024
(gdb) p frame->root->frames.next
$19 = (call_frame_t *) 0x1c577590
(gdb) p frame->root->frames.next->prev
$20 = (call_frame_t *) 0x2b60f1a5e0ac
(gdb) p/a $rdx
$21 = 0x2b60f1a5e024
(gdb) x/a $rdx+0x98
0x2b60f1a5e0bc: 0x1c577590
(gdb) p/a $rax
$22 = 0xb50f40c0

Oops. Why 0x98(%rdx) != %rax in %rip point? It's fantastic.

(gdb) x/a $rax+0x18
0xb50f40d8:     Cannot access memory at address 0xb50f40d8

Total 4 io-threads running (as shown in volfile I'm using a 3 posix volume, i.e. 1/1/2 threads per volumes running before crash):
# gdb /opt/glusterfs/3.1.3/sbin/glusterfs core.27743 --ex 'thread apply all bt full'|grep iot_worker
#1  0x00002aaac200f080 in iot_worker (data=0x1b4dcde0) at io-threads.c:101
        __FUNCTION__ = "iot_worker"
#1  0x00002aaac200f080 in iot_worker (data=0x1ee24430) at io-threads.c:101
        __FUNCTION__ = "iot_worker"
#1  0x00002aaac200f080 in iot_worker (data=0x2aaab7019490) at io-threads.c:101
        __FUNCTION__ = "iot_worker"
#3  0x00002aaac200f119 in iot_worker (data=0x2aaab7019490) at io-threads.c:129
        __FUNCTION__ = "iot_worker"

Crash in thread with conf:
(gdb) p *((iot_conf_t *)this->private)
$53 = {mutex = {__data = {__lock = 0, __count = 0, __owner = 0, __nusers = 1, __kind = 0, __spins = 0, __list = {
        __prev = 0x0, __next = 0x0}}, __size = '\000' <repeats 12 times>, "\001", '\000' <repeats 26 times>,
    __align = 0}, cond = {__data = {__lock = 0, __futex = 620591, __total_seq = 310296, __wakeup_seq = 310295,
      __woken_seq = 310295, __mutex = 0x2aaab7019490, __nwaiters = 2, __broadcast_seq = 0},
    __size = "\000\000\000\000/x\t\000\030?\004\000\000\000\000\000\027?\004\000\000\000\000\000\027?\004\000\000\00
0\000\000?"\001·Є*\000\000\002\000\000\000\000\000\000", __align = 2665418049191936}, max_count = 16,
  curr_count = 2, sleep_count = 1, idle_time = 120, reqs = {{next = 0x2aaab70194f8, prev = 0x2aaab70194f8}, {
      next = 0x2aaab7019508, prev = 0x2aaab7019508}, {next = 0x2aaab7019518, prev = 0x2aaab7019518}},
  queue_size = 0, w_attr = {
    __size = '\000' <repeats 17 times>, "\020", '\000' <repeats 16 times>, "\020", '\000' <repeats 20 times>,
    __align = 0}, this = 0x1d587ee0}