[Gluster-users] query about glusterfs 3.12-3 write-behind.c coredump
Hi,
Could you help to check this coredump?
We are using glusterfs 3.12-3(3 replicated bricks solution ) to do stability
testing under high CPU load like 80% by stress and doing I/O.
After several hours, coredump happened in glusterfs side .
[Current thread is 1 (Thread 0x737d2700 (LWP 3696))]
Missing separate debuginfos, use: dnf debuginfo-install
rcp-pack-glusterfs-1.8.1_11_g99e9ca6-RCP2.wf28.x86_64
(gdb) bt
#0 0x70d5c845 in wb_fulfill (wb_inode=0x7fffd406b3b0,
liabilities=0x7fffdc234b50) at write-behind.c:1148
#1 0x70d5e4d5 in wb_process_queue (wb_inode=0x7fffd406b3b0) at
write-behind.c:1718
#2 0x70d5eda7 in wb_writev (frame=0x7fffe0086290, this=0x7fffec014b00,
fd=0x7fffe4034070, vector=0x7fffdc445720, count=1, offset=67108863,
flags=32770, iobref=0x7fffdc00d550, xdata=0x0)
at write-behind.c:1825
#3 0x70b51fcb in du_writev_resume (ret=0, frame=0x7fffdc0305a0,
opaque=0x7fffdc0305a0) at disk-usage.c:490
#4 0x77b3510d in synctask_wrap () at syncop.c:377
#5 0x760d0660 in ?? () from /lib64/libc.so.6
#6 0x in ?? ()
(gdb) p wb_inode
$1 = (wb_inode_t *) 0x7fffd406b3b0
(gdb) frame 2
#2 0x70d5eda7 in wb_writev (frame=0x7fffe0086290, this=0x7fffec014b00,
fd=0x7fffe4034070, vector=0x7fffdc445720, count=1, offset=67108863,
flags=32770, iobref=0x7fffdc00d550, xdata=0x0)
at write-behind.c:1825
1825 in write-behind.c
(gdb) p *fd
$2 = {pid = 18154, flags = 32962, refcount = 0, inode_list = {next =
0x7fffe4034080, prev = 0x7fffe4034080}, inode = 0x0, lock = {spinlock = 0,
mutex = {__data = {__lock = 0, __count = 0, __owner = 0,
__nusers = 0, __kind = -1, __spins = 0, __elision = 0, __list = {__prev
= 0x0, __next = 0x0}}, __size = '\000' , "\377\377\377\377",
'\000' , __align = 0}},
_ctx = 0x7fffe4022930, xl_count = 17, lk_ctx = 0x7fffe40350e0, anonymous =
_gf_false}
(gdb) p fd
$3 = (fd_t *) 0x7fffe4034070
(gdb) p wb_inode->this
$1 = (xlator_t *) 0xff00
After adding test log I found the FOP sequence in write-behind xlator side was
mass as bellow showing. In the FUSE side the FLUSH is after write2, but in the
WB side, FLUSH is between write2 'wb_do_unwinds' and 'wb_fulfill'.
So I think this should has problem. I think it's possible that the FLUSH and
later RELEASE operation will destroy the fd , it will cause
'wb_in->this(0xff00)'. Do you think so?
And I think our new adding disk-usage xlator's synctask_new will dealy the
write operation, but the FLUSH operation without this delay(because not invoked
the disk-usage xlator).
Do you agree with my speculation ? and how to fix?(we don't want to move the
disk-usage xlator)
Problematic FOP sequence :
FUSE side: WB side:
Write 1write1
Write2 do unwind
Write 2FLUSH
Release(destroy fd)
FLUSHwrite2 (wb_fulfill) then coredump.
Release
int
wb_fulfill (wb_inode_t *wb_inode, list_head_t *liabilities)
{
wb_request_t *req = NULL;
wb_request_t *head= NULL;
wb_request_t *tmp = NULL;
wb_conf_t *conf= NULL;
off_t expected_offset = 0;
size_t curr_aggregate = 0;
size_t vector_count = 0;
intret = 0;
conf = wb_inode->this->private; --> this line coredump
list_for_each_entry_safe (req, tmp, liabilities, winds) {
list_del_init (&req->winds);
volume ccs-write-behind
68: type performance/write-behind
69: subvolumes ccs-dht
70: end-volume
71:
72: volume ccs-disk-usage --> we add a new xlator here
for write op ,just for checking if disk if full. And synctask_new for write.
73: type performance/disk-usage
74: subvolumes ccs-write-behind
75: end-volume
76:
77: volume ccs-read-ahead
78: type performance/read-ahead
79: subvolumes ccs-disk-usage
80: end-volume
Ps. Part of Our new translator code
int
du_writev (call_frame_t *frame, xlator_t *this, fd_t *fd,
struct iovec *vector, int count, off_t off, uint32_t flags,
struct iobref *iobref, dict_t *xdata)
{
int op_errno = -1;
int ret = -1;
du_local_t *local = NULL;
loc_t tmp_loc = {0,};
VALIDATE_OR_GOTO (frame, err);
VALIDATE_OR_GOTO (this, err);
VALIDATE_OR_GOTO (fd, err);
tmp_loc.gfid[15] = 1;
tmp_loc.inode = fd->inode;
tmp_loc.parent = fd->inode;
local = du_local_init (frame, &tmp_loc, fd, GF_FOP_WRITE);
if (!local) {
op_errno = ENOMEM;
goto err;
}
local->vector = iov_dup (vector, count);
local->offset = off;
local->count = count;
local->flags = flags;
local->iobref = iobref_ref (iobref);
ret = synctask_new(this->ctx->env,
du_get_du_info,du_writev_resume,frame,frame);
if(ret)
{
op_errno = -1;
Re: [Gluster-users] query about glusterfs 3.12-3 write-behind.c coredump
On Wed, Jan 30, 2019 at 7:35 AM Li, Deqian (NSB - CN/Hangzhou) <
deqian...@nokia-sbell.com> wrote:
> Hi,
>
>
>
> Could you help to check this coredump?
>
> We are using glusterfs 3.12-3(3 replicated bricks solution ) to do
> stability testing under high CPU load like 80% by stress and doing I/O.
>
> After several hours, coredump happened in glusterfs side .
>
>
>
> [Current thread is 1 (Thread 0x737d2700 (LWP 3696))]
>
> Missing separate debuginfos, use: dnf debuginfo-install
> rcp-pack-glusterfs-1.8.1_11_g99e9ca6-RCP2.wf28.x86_64
>
> (gdb) bt
>
> #0 0x70d5c845 in wb_fulfill (wb_inode=0x7fffd406b3b0,
> liabilities=0x7fffdc234b50) at write-behind.c:1148
>
> #1 0x70d5e4d5 in wb_process_queue (wb_inode=0x7fffd406b3b0) at
> write-behind.c:1718
>
> #2 0x70d5eda7 in wb_writev (frame=0x7fffe0086290,
> this=0x7fffec014b00, fd=0x7fffe4034070, vector=0x7fffdc445720, count=1,
> offset=67108863, flags=32770, iobref=0x7fffdc00d550, xdata=0x0)
>
> at write-behind.c:1825
>
> #3 0x70b51fcb in du_writev_resume (ret=0, frame=0x7fffdc0305a0,
> opaque=0x7fffdc0305a0) at disk-usage.c:490
>
> #4 0x77b3510d in synctask_wrap () at syncop.c:377
>
> #5 0x760d0660 in ?? () from /lib64/libc.so.6
>
> #6 0x in ?? ()
>
> (gdb) p wb_inode
>
> $1 = (wb_inode_t *) 0x7fffd406b3b0
>
> (gdb) frame 2
>
> #2 0x70d5eda7 in wb_writev (frame=0x7fffe0086290,
> this=0x7fffec014b00, fd=0x7fffe4034070, vector=0x7fffdc445720, count=1,
> offset=67108863, flags=32770, iobref=0x7fffdc00d550, xdata=0x0)
>
> at write-behind.c:1825
>
> 1825 in write-behind.c
>
> (gdb) p *fd
>
> $2 = {pid = 18154, flags = 32962, refcount = 0, inode_list = {next =
> 0x7fffe4034080, prev = 0x7fffe4034080}, inode = 0x0, lock = {spinlock = 0,
> mutex = {__data = {__lock = 0, __count = 0, __owner = 0,
>
> __nusers = 0, __kind = -1, __spins = 0, __elision = 0, __list =
> {__prev = 0x0, __next = 0x0}}, __size = '\000' ,
> "\377\377\377\377", '\000' , __align = 0}},
>
> _ctx = 0x7fffe4022930, xl_count = 17, lk_ctx = 0x7fffe40350e0, anonymous
> = _gf_false}
>
> (gdb) p fd
>
> $3 = (fd_t *) 0x7fffe4034070
>
>
>
> (gdb) p wb_inode->this
>
> $1 = (xlator_t *) 0xff00
>
>
>
> After adding test log I found the FOP sequence in write-behind xlator
> side was mass as bellow showing. In the FUSE side the FLUSH is after
> write2, but in the WB side, FLUSH is between write2 ‘wb_do_unwinds’ and
> ‘wb_fulfill’.
>
> So I think this should has problem. I think it’s possible that the FLUSH
> and later RELEASE operation will destroy the fd , it will cause
> ‘wb_in->this(0xff00)’. Do you think so?
>
> And I think our new adding disk-usage xlator’s synctask_new will dealy the
> write operation, but the FLUSH operation without this delay(because not
> invoked the disk-usage xlator).
>
>
>
> Do you agree with my speculation ? and how to fix?(we don’t want to move
> the disk-usage xlator)
>
>
>
>
>
> Problematic FOP sequence :
>
>
>
> FUSE side: WB side:
>
>
>
> Write 1write1
>
> Write2 do unwind
>
> Write 2FLUSH
>
> Release(destroy fd)
>
> FLUSHwrite2 (wb_fulfill) then coredump.
>
> Release
>
>
>
>
>
> int
>
> wb_fulfill (wb_inode_t *wb_inode, list_head_t *liabilities)
>
> {
>
> wb_request_t *req = NULL;
>
> wb_request_t *head= NULL;
>
> wb_request_t *tmp = NULL;
>
> wb_conf_t *conf= NULL;
>
> off_t expected_offset = 0;
>
> size_t curr_aggregate = 0;
>
> size_t vector_count = 0;
>
> intret = 0;
>
>
>
> conf = wb_inode->this->private; à this line coredump
>
>
>
> list_for_each_entry_safe (req, tmp, liabilities, winds) {
>
> list_del_init (&req->winds);
>
>
>
> ….
>
>
>
>
>
> volume ccs-write-behind
>
> 68: type performance/write-behind
>
> 69: subvolumes ccs-dht
>
> 70: end-volume
>
> 71:
>
> * 72: volume ccs-disk-usage **à we add a new xlator
> here for write op ,just for checking if disk if full. And synctask_new for
> write.*
>
> *73: type performance/disk-usage*
>
> *74: subvolumes ccs-write-behind*
>
> *75: end-volume*
>
> 76:
>
> 77: volume ccs-read-ahead
>
> 78: type performance/read-ahead
>
> 79: subvolumes ccs-disk-usage
>
> 80: end-volume
>
>
>
>
>
>
>
> Ps. Part of Our new translator code
>
>
>
> int
>
> du_writev (call_frame_t *frame, xlator_t *this, fd_t *fd,
>
> struct iovec *vector, int count, off_t off, uint32_t flags,
>
> struct iobref *iobref, dict_t *xdata)
>
> {
>
> int op_errno = -1;
>
> int ret = -1;
>
> du_local_t *local = NULL;
>
> loc_t tmp_loc = {0,};
>
>
>
> VALIDATE_OR_GOTO (frame, err);
>
> VALIDATE_OR_GOTO (this, err);
>
> VALIDATE_OR_GOTO (fd, err);
>
>
Re: [Gluster-users] query about glusterfs 3.12-3 write-behind.c coredump
Hi,
Yes, thanks very much for your quick response.
I attach the whole file, not very big.
Br,
Li Deqian
From: Raghavendra Gowdappa
Sent: Wednesday, January 30, 2019 11:00 AM
To: Li, Deqian (NSB - CN/Hangzhou)
Cc: gluster-users
Subject: Re: query about glusterfs 3.12-3 write-behind.c coredump
On Wed, Jan 30, 2019 at 7:35 AM Li, Deqian (NSB - CN/Hangzhou)
mailto:deqian...@nokia-sbell.com>> wrote:
Hi,
Could you help to check this coredump?
We are using glusterfs 3.12-3(3 replicated bricks solution ) to do stability
testing under high CPU load like 80% by stress and doing I/O.
After several hours, coredump happened in glusterfs side .
[Current thread is 1 (Thread 0x737d2700 (LWP 3696))]
Missing separate debuginfos, use: dnf debuginfo-install
rcp-pack-glusterfs-1.8.1_11_g99e9ca6-RCP2.wf28.x86_64
(gdb) bt
#0 0x70d5c845 in wb_fulfill (wb_inode=0x7fffd406b3b0,
liabilities=0x7fffdc234b50) at write-behind.c:1148
#1 0x70d5e4d5 in wb_process_queue (wb_inode=0x7fffd406b3b0) at
write-behind.c:1718
#2 0x70d5eda7 in wb_writev (frame=0x7fffe0086290, this=0x7fffec014b00,
fd=0x7fffe4034070, vector=0x7fffdc445720, count=1, offset=67108863,
flags=32770, iobref=0x7fffdc00d550, xdata=0x0)
at write-behind.c:1825
#3 0x70b51fcb in du_writev_resume (ret=0, frame=0x7fffdc0305a0,
opaque=0x7fffdc0305a0) at disk-usage.c:490
#4 0x77b3510d in synctask_wrap () at syncop.c:377
#5 0x760d0660 in ?? () from /lib64/libc.so.6
#6 0x in ?? ()
(gdb) p wb_inode
$1 = (wb_inode_t *) 0x7fffd406b3b0
(gdb) frame 2
#2 0x70d5eda7 in wb_writev (frame=0x7fffe0086290, this=0x7fffec014b00,
fd=0x7fffe4034070, vector=0x7fffdc445720, count=1, offset=67108863,
flags=32770, iobref=0x7fffdc00d550, xdata=0x0)
at write-behind.c:1825
1825 in write-behind.c
(gdb) p *fd
$2 = {pid = 18154, flags = 32962, refcount = 0, inode_list = {next =
0x7fffe4034080, prev = 0x7fffe4034080}, inode = 0x0, lock = {spinlock = 0,
mutex = {__data = {__lock = 0, __count = 0, __owner = 0,
__nusers = 0, __kind = -1, __spins = 0, __elision = 0, __list = {__prev
= 0x0, __next = 0x0}}, __size = '\000' , "\377\377\377\377",
'\000' , __align = 0}},
_ctx = 0x7fffe4022930, xl_count = 17, lk_ctx = 0x7fffe40350e0, anonymous =
_gf_false}
(gdb) p fd
$3 = (fd_t *) 0x7fffe4034070
(gdb) p wb_inode->this
$1 = (xlator_t *) 0xff00
After adding test log I found the FOP sequence in write-behind xlator side was
mass as bellow showing. In the FUSE side the FLUSH is after write2, but in the
WB side, FLUSH is between write2 ‘wb_do_unwinds’ and ‘wb_fulfill’.
So I think this should has problem. I think it’s possible that the FLUSH and
later RELEASE operation will destroy the fd , it will cause
‘wb_in->this(0xff00)’. Do you think so?
And I think our new adding disk-usage xlator’s synctask_new will dealy the
write operation, but the FLUSH operation without this delay(because not invoked
the disk-usage xlator).
Do you agree with my speculation ? and how to fix?(we don’t want to move the
disk-usage xlator)
Problematic FOP sequence :
FUSE side: WB side:
Write 1write1
Write2 do unwind
Write 2FLUSH
Release(destroy fd)
FLUSHwrite2 (wb_fulfill) then coredump.
Release
int
wb_fulfill (wb_inode_t *wb_inode, list_head_t *liabilities)
{
wb_request_t *req = NULL;
wb_request_t *head= NULL;
wb_request_t *tmp = NULL;
wb_conf_t *conf= NULL;
off_t expected_offset = 0;
size_t curr_aggregate = 0;
size_t vector_count = 0;
intret = 0;
conf = wb_inode->this->private; --> this line coredump
list_for_each_entry_safe (req, tmp, liabilities, winds) {
list_del_init (&req->winds);
….
volume ccs-write-behind
68: type performance/write-behind
69: subvolumes ccs-dht
70: end-volume
71:
72: volume ccs-disk-usage --> we add a new xlator here
for write op ,just for checking if disk if full. And synctask_new for write.
73: type performance/disk-usage
74: subvolumes ccs-write-behind
75: end-volume
76:
77: volume ccs-read-ahead
78: type performance/read-ahead
79: subvolumes ccs-disk-usage
80: end-volume
Ps. Part of Our new translator code
int
du_writev (call_frame_t *frame, xlator_t *this, fd_t *fd,
struct iovec *vector, int count, off_t off, uint32_t flags,
struct iobref *iobref, dict_t *xdata)
{
int op_errno = -1;
int ret = -1;
du_local_t *local = NULL;
loc_t tmp_loc = {0,};
VALIDATE_OR_GOTO (frame, err);
VALIDATE_OR_GOTO (this, err);
VALIDATE_OR_GOTO (fd, err);
tmp_loc.gfid[15] = 1;
tmp_loc.inode = fd->inode;
tmp_loc.parent = fd->inode;
local = du_local_init (
Re: [Gluster-users] query about glusterfs 3.12-3 write-behind.c coredump
On Wed, Jan 30, 2019 at 7:35 AM Li, Deqian (NSB - CN/Hangzhou) <
deqian...@nokia-sbell.com> wrote:
> Hi,
>
>
>
> Could you help to check this coredump?
>
> We are using glusterfs 3.12-3(3 replicated bricks solution ) to do
> stability testing under high CPU load like 80% by stress and doing I/O.
>
> After several hours, coredump happened in glusterfs side .
>
>
>
> [Current thread is 1 (Thread 0x737d2700 (LWP 3696))]
>
> Missing separate debuginfos, use: dnf debuginfo-install
> rcp-pack-glusterfs-1.8.1_11_g99e9ca6-RCP2.wf28.x86_64
>
> (gdb) bt
>
> #0 0x70d5c845 in wb_fulfill (wb_inode=0x7fffd406b3b0,
> liabilities=0x7fffdc234b50) at write-behind.c:1148
>
> #1 0x70d5e4d5 in wb_process_queue (wb_inode=0x7fffd406b3b0) at
> write-behind.c:1718
>
> #2 0x70d5eda7 in wb_writev (frame=0x7fffe0086290,
> this=0x7fffec014b00, fd=0x7fffe4034070, vector=0x7fffdc445720, count=1,
> offset=67108863, flags=32770, iobref=0x7fffdc00d550, xdata=0x0)
>
> at write-behind.c:1825
>
> #3 0x70b51fcb in du_writev_resume (ret=0, frame=0x7fffdc0305a0,
> opaque=0x7fffdc0305a0) at disk-usage.c:490
>
> #4 0x77b3510d in synctask_wrap () at syncop.c:377
>
> #5 0x760d0660 in ?? () from /lib64/libc.so.6
>
> #6 0x in ?? ()
>
> (gdb) p wb_inode
>
> $1 = (wb_inode_t *) 0x7fffd406b3b0
>
> (gdb) frame 2
>
> #2 0x70d5eda7 in wb_writev (frame=0x7fffe0086290,
> this=0x7fffec014b00, fd=0x7fffe4034070, vector=0x7fffdc445720, count=1,
> offset=67108863, flags=32770, iobref=0x7fffdc00d550, xdata=0x0)
>
> at write-behind.c:1825
>
> 1825 in write-behind.c
>
> (gdb) p *fd
>
> $2 = {pid = 18154, flags = 32962, refcount = 0, inode_list = {next =
> 0x7fffe4034080, prev = 0x7fffe4034080}, inode = 0x0, lock = {spinlock = 0,
> mutex = {__data = {__lock = 0, __count = 0, __owner = 0,
>
> __nusers = 0, __kind = -1, __spins = 0, __elision = 0, __list =
> {__prev = 0x0, __next = 0x0}}, __size = '\000' ,
> "\377\377\377\377", '\000' , __align = 0}},
>
> _ctx = 0x7fffe4022930, xl_count = 17, lk_ctx = 0x7fffe40350e0, anonymous
> = _gf_false}
>
> (gdb) p fd
>
> $3 = (fd_t *) 0x7fffe4034070
>
>
>
> (gdb) p wb_inode->this
>
> $1 = (xlator_t *) 0xff00
>
>
>
> After adding test log I found the FOP sequence in write-behind xlator
> side was mass as bellow showing. In the FUSE side the FLUSH is after
> write2, but in the WB side, FLUSH is between write2 ‘wb_do_unwinds’ and
> ‘wb_fulfill’.
>
> So I think this should has problem.
>
wb_do_unwinds the write after caching it. Once the write response is
unwound, kernel issues a FLUSH. So, this is a valid sequence of operations
and nothing wrong.
I think it’s possible that the FLUSH and later RELEASE operation will
> destroy the fd , it will cause ‘wb_in->this(0xff00)’. Do you
> think so?
>
> And I think our new adding disk-usage xlator’s synctask_new will dealy the
> write operation, but the FLUSH operation without this delay(because not
> invoked the disk-usage xlator).
>
Flush and release wait for completion of any on-going writes. So, unless
write-behind has unwound the write, it won't see a flush. By the time write
is unwound, write-behind makes sure to take references on objects it uses
(like fds, iobref etc). So, I don't see a problem there.
>
> Do you agree with my speculation ? and how to fix?(we don’t want to move
> the disk-usage xlator)
>
I've still not found the RCA. We can discuss about the fix once RCA is
found.
>
>
>
> Problematic FOP sequence :
>
>
>
> FUSE side: WB side:
>
>
>
> Write 1write1
>
> Write2 do unwind
>
> Write 2FLUSH
>
> Release(destroy fd)
>
> FLUSHwrite2 (wb_fulfill) then coredump.
>
> Release
>
>
>
>
>
> int
>
> wb_fulfill (wb_inode_t *wb_inode, list_head_t *liabilities)
>
> {
>
> wb_request_t *req = NULL;
>
> wb_request_t *head= NULL;
>
> wb_request_t *tmp = NULL;
>
> wb_conf_t *conf= NULL;
>
> off_t expected_offset = 0;
>
> size_t curr_aggregate = 0;
>
> size_t vector_count = 0;
>
> intret = 0;
>
>
>
> conf = wb_inode->this->private; à this line coredump
>
>
>
> list_for_each_entry_safe (req, tmp, liabilities, winds) {
>
> list_del_init (&req->winds);
>
>
>
> ….
>
>
>
>
>
> volume ccs-write-behind
>
> 68: type performance/write-behind
>
> 69: subvolumes ccs-dht
>
> 70: end-volume
>
> 71:
>
> * 72: volume ccs-disk-usage **à we add a new xlator
> here for write op ,just for checking if disk if full. And synctask_new for
> write.*
>
> *73: type performance/disk-usage*
>
> *74: subvolumes ccs-write-behind*
>
> *75: end-volume*
>
> 76:
>
> 77: volume ccs-read-ahead
>
> 78: type performance/read-ahead
>
> 79: subvolumes ccs-disk-usage
>
> 80: end-volume
>
>
Re: [Gluster-users] query about glusterfs 3.12-3 write-behind.c coredump
On Wed, Jan 30, 2019 at 9:44 AM Raghavendra Gowdappa
wrote:
>
>
> On Wed, Jan 30, 2019 at 7:35 AM Li, Deqian (NSB - CN/Hangzhou) <
> deqian...@nokia-sbell.com> wrote:
>
>> Hi,
>>
>>
>>
>> Could you help to check this coredump?
>>
>> We are using glusterfs 3.12-3(3 replicated bricks solution ) to do
>> stability testing under high CPU load like 80% by stress and doing I/O.
>>
>> After several hours, coredump happened in glusterfs side .
>>
>>
>>
>> [Current thread is 1 (Thread 0x737d2700 (LWP 3696))]
>>
>> Missing separate debuginfos, use: dnf debuginfo-install
>> rcp-pack-glusterfs-1.8.1_11_g99e9ca6-RCP2.wf28.x86_64
>>
>> (gdb) bt
>>
>> #0 0x70d5c845 in wb_fulfill (wb_inode=0x7fffd406b3b0,
>> liabilities=0x7fffdc234b50) at write-behind.c:1148
>>
>> #1 0x70d5e4d5 in wb_process_queue (wb_inode=0x7fffd406b3b0) at
>> write-behind.c:1718
>>
>> #2 0x70d5eda7 in wb_writev (frame=0x7fffe0086290,
>> this=0x7fffec014b00, fd=0x7fffe4034070, vector=0x7fffdc445720, count=1,
>> offset=67108863, flags=32770, iobref=0x7fffdc00d550, xdata=0x0)
>>
>> at write-behind.c:1825
>>
>> #3 0x70b51fcb in du_writev_resume (ret=0, frame=0x7fffdc0305a0,
>> opaque=0x7fffdc0305a0) at disk-usage.c:490
>>
>> #4 0x77b3510d in synctask_wrap () at syncop.c:377
>>
>> #5 0x760d0660 in ?? () from /lib64/libc.so.6
>>
>> #6 0x in ?? ()
>>
>> (gdb) p wb_inode
>>
>> $1 = (wb_inode_t *) 0x7fffd406b3b0
>>
>> (gdb) frame 2
>>
>> #2 0x70d5eda7 in wb_writev (frame=0x7fffe0086290,
>> this=0x7fffec014b00, fd=0x7fffe4034070, vector=0x7fffdc445720, count=1,
>> offset=67108863, flags=32770, iobref=0x7fffdc00d550, xdata=0x0)
>>
>> at write-behind.c:1825
>>
>> 1825 in write-behind.c
>>
>> (gdb) p *fd
>>
>> $2 = {pid = 18154, flags = 32962, refcount = 0, inode_list = {next =
>> 0x7fffe4034080, prev = 0x7fffe4034080}, inode = 0x0, lock = {spinlock = 0,
>> mutex = {__data = {__lock = 0, __count = 0, __owner = 0,
>>
>> __nusers = 0, __kind = -1, __spins = 0, __elision = 0, __list =
>> {__prev = 0x0, __next = 0x0}}, __size = '\000' ,
>> "\377\377\377\377", '\000' , __align = 0}},
>>
>> _ctx = 0x7fffe4022930, xl_count = 17, lk_ctx = 0x7fffe40350e0,
>> anonymous = _gf_false}
>>
>> (gdb) p fd
>>
>> $3 = (fd_t *) 0x7fffe4034070
>>
>>
>>
>> (gdb) p wb_inode->this
>>
>> $1 = (xlator_t *) 0xff00
>>
>>
>>
>> After adding test log I found the FOP sequence in write-behind xlator
>> side was mass as bellow showing. In the FUSE side the FLUSH is after
>> write2, but in the WB side, FLUSH is between write2 ‘wb_do_unwinds’ and
>> ‘wb_fulfill’.
>>
>> So I think this should has problem.
>>
>
> wb_do_unwinds the write after caching it.
>
* wb_do_unwinds unwind the write after caching it.
Once the write response is unwound, kernel issues a FLUSH. So, this is a
> valid sequence of operations and nothing wrong.
>
> I think it’s possible that the FLUSH and later RELEASE operation will
>> destroy the fd , it will cause ‘wb_in->this(0xff00)’. Do you
>> think so?
>>
>> And I think our new adding disk-usage xlator’s synctask_new will dealy
>> the write operation, but the FLUSH operation without this delay(because not
>> invoked the disk-usage xlator).
>>
>
> Flush and release wait for completion of any on-going writes. So, unless
> write-behind has unwound the write, it won't see a flush. By the time write
> is unwound, write-behind makes sure to take references on objects it uses
> (like fds, iobref etc). So, I don't see a problem there.
>
>
>>
>> Do you agree with my speculation ? and how to fix?(we don’t want to move
>> the disk-usage xlator)
>>
>
> I've still not found the RCA. We can discuss about the fix once RCA is
> found.
>
>
>>
>>
>>
>> Problematic FOP sequence :
>>
>>
>>
>> FUSE side: WB side:
>>
>>
>>
>> Write 1write1
>>
>> Write2 do unwind
>>
>> Write 2FLUSH
>>
>> Release(destroy fd)
>>
>> FLUSHwrite2 (wb_fulfill) then coredump.
>>
>> Release
>>
>>
>>
>>
>>
>> int
>>
>> wb_fulfill (wb_inode_t *wb_inode, list_head_t *liabilities)
>>
>> {
>>
>> wb_request_t *req = NULL;
>>
>> wb_request_t *head= NULL;
>>
>> wb_request_t *tmp = NULL;
>>
>> wb_conf_t *conf= NULL;
>>
>> off_t expected_offset = 0;
>>
>> size_t curr_aggregate = 0;
>>
>> size_t vector_count = 0;
>>
>> intret = 0;
>>
>>
>>
>> conf = wb_inode->this->private; à this line coredump
>>
>>
>>
>> list_for_each_entry_safe (req, tmp, liabilities, winds) {
>>
>> list_del_init (&req->winds);
>>
>>
>>
>> ….
>>
>>
>>
>>
>>
>> volume ccs-write-behind
>>
>> 68: type performance/write-behind
>>
>> 69: subvolumes ccs-dht
>>
>> 70: end-volume
>>
>> 71:
>>
>> * 72: volume ccs-disk-usage **à we add a new xlator
>> he
Re: [Gluster-users] query about glusterfs 3.12-3 write-behind.c coredump
Hi,
>>Once the write response is unwound, kernel issues a FLUSH. So, this is a
>>valid sequence of operations and nothing wrong.
I think I need to explain more of my meaning.
I added test log into wb_process_queue() etc, found the 4 logs as bellow.
I mean normally the log order should be 1,4,2,3, because 1,4 are for one
‘write’, but now it is 1,2,3,4, I think it’s abnormal (maybe caused by high CPU
load or disk-usage xlator).
And I think after FLUSH(2,3) the ‘fd’ will be destroyed then caused‘4’
incorrect pointer. Do you agree with this speculation?
Here ‘refcount’ means ‘fd-> refcount’.
1.[2019-01-28 04:23:26.751555] E [MSGID: 131007]
[write-behind.c:1237:wb_do_unwinds] 0-ldq before do un wind :
wb_in->this(0x7fc544014b10),wb_in(0x7fc5140a9b40),fop=WRITE,
fd=0x7fc53c054280,refcount:8, threadid:3320
2.[2019-01-28 04:23:26.778756] E [fuse-bridge.c:2562:fuse_flush]
0-glusterfs-fuse: 1674240:ldq FLUSH fd 0x7fc53c054280,threadid:5649
3.[2019-01-28 04:23:26.786131] E [MSGID: 131007]
[write-behind.c:1715:wb_do_winds] 0-ldq before do wind :
wb_in->this(0x7fc544014b10),wb_in(0x7fc5140a9b40),fop=FLUSH,
fd=0x7fc53c054280,refcount:14, threadid:5646
4. [2019-01-28 04:23:26.798515] E [MSGID: 131007]
[write-behind.c:1755:wb_process_queue] 0-ldq before fulfill :
wb_in->this(0xff00),wb_in(0x7fc5140a9b40), threadid:3320
>>Flush and release wait for completion of any on-going writes. So, unless
>>write-behind has unwound the write, it won't see a flush. By the time write
>>is unwound, write-behind makes sure to take references on objects it uses
>>(like fds, iobref etc).
In the wb_process_queue(), we can see after wb_do_unwinds() still need to do
wb_do_winds(),wb_fulfill().
Do you think after one ‘write’ operation executed ‘wb_do_unwinds()’, it will
wake up the OP in FUSE queue like ‘FLUSH’ , and ‘FLUSH’ can finish it’s job and
next release the ‘fd’. Then the thread of previous ‘write’ continue to do
‘wb_full()’ then coredump?
And do you have more detail document about the glusterfs write-behind,
especially how the the ‘fd->refcount’ add and descrease.
Thanks.
Ps the debug code in red.
void
wb_process_queue (wb_inode_t *wb_inode)
{
list_head_t tasks= {0, };
list_head_t lies = {0, };
list_head_t liabilities = {0, };
int wind_failure = 0;
INIT_LIST_HEAD (&tasks);
INIT_LIST_HEAD (&lies);
INIT_LIST_HEAD (&liabilities);
do {
gf_log_callingfn (wb_inode->this->name, GF_LOG_DEBUG,
"processing queues");
LOCK (&wb_inode->lock);
{
__wb_preprocess_winds (wb_inode);
__wb_pick_winds (wb_inode, &tasks, &liabilities);
__wb_pick_unwinds (wb_inode, &lies);
}
UNLOCK (&wb_inode->lock);
wb_do_unwinds (wb_inode, &lies);
wb_do_winds (wb_inode, &tasks);
gf_msg ("ldq before fulfill ", GF_LOG_ERROR, 0,
WRITE_BEHIND_MSG_RES_UNAVAILABLE,
"wb_in->this(%p),wb_in(%p), threadid:%ld",
wb_inode->this,wb_inode,
syscall(SYS_gettid));
/* If there is an error in wb_fulfill before winding write
* requests, we would miss invocation of wb_process_queue
* from wb_fulfill_cbk. So, retry processing again.
*/
wind_failure = wb_fulfill (wb_inode, &liabilities);
gf_msg ("ldq after fulfill ", GF_LOG_ERROR, 0,
WRITE_BEHIND_MSG_RES_UNAVAILABLE,
"wb_in->this(%p),wb_in(%p), thid:%ld",
wb_inode->this,wb_inode,syscall(SYS_gettid));
} while (wind_failure);
return;
}
void
wb_do_unwinds (wb_inode_t *wb_inode, list_head_t *lies)
{
wb_request_t *req = NULL;
wb_request_t *tmp = NULL;
call_frame_t *frame = NULL;
struct iatt buf = {0, };
list_for_each_entry_safe (req, tmp, lies, unwinds) {
frame = req->stub->frame;
STACK_UNWIND_STRICT (writev, frame, req->op_ret, req->op_errno,
&buf, &buf, NULL); /* :O */
req->stub->frame = NULL;
list_del_init (&req->unwinds);
if(req->fd)
gf_msg ("ldq before do un wind ", GF_LOG_ERROR, 0,
WRITE_BEHIND_MSG_RES_UNAVAILABLE,
"wb_in->this(%p),wb_in(%p),fop=%s, fd=%p,refcount:%d,
threadid:%ld",
wb_inode->this,wb_inode,gf_fop_list[req->fop],
req->fd,req->fd->refcount,syscall(SYS_gettid));
wb_request_unref (req);
}
