761834 – (GLUSTER-102) mem-pool: Crash with io-threads, dht and write-behind

Bug 761834 (GLUSTER-102) - mem-pool: Crash with io-threads, dht and write-behind

Summary: mem-pool: Crash with io-threads, dht and write-behind

Keywords:
Status:	CLOSED CURRENTRELEASE
Alias:	GLUSTER-102
Product:	GlusterFS
Classification:	Community
Component:	core
Sub Component:
Version:	mainline
Hardware:	All
OS:	Linux
Priority:	low
Severity:	medium
Target Milestone:	---
Assignee:	Shehjar Tikoo
QA Contact:
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2009-06-29 06:36 UTC by Shehjar Tikoo
Modified:	2009-08-12 06:00 UTC (History)
CC List:	2 users (show)
Fixed In Version:
Doc Type:	Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed:
Regression:	RTP
Mount Type:	---
Documentation:	---
CRM:
Verified Versions:
Dependent Products:

Attachments	(Terms of Use)
Logs and volfiles contributed by user (4.47 KB, application/x-bzip) 2009-06-29 03:40 UTC, Shehjar Tikoo	no flags	Details
View All Add an attachment (proposed patch, testcase, etc.)

Description Shehjar Tikoo 2009-06-29 03:37:59 UTC

Hi!

June 25 2009 21:28 Shehjar Tikoo (shehjart) wrote:
> > Thanks. I'd also need your server and client volfiles and logs.
I'll send it tomorrow from the office.

> > What application were you using when this crash took place?
That node was running an in-house CFD-solver, which constantly writes
log-file (fflush after each line) and once an hour solution files. The
crash took place after >48 hours of running, when another user tried
to submit his job using Sun Grid Engine (SGE) scheduler. SGE just
failed to create file for stdout redirection, and job didn't started.
It definitely was not high IO load or so.

The second crash was on the same node and the same user cased it.  :) 
This time the node was idle, the user submitted his job, it started.
His script creates many soft-links and compiles something. The script
finished normally as the user said. But next time I've checked the
node glusterFS client was down... So again I dont see here any
specific usage.

> > What version of GlusterFS is this? Is it a recent git checkout?
Yes it is. Pooled on 2009.06.16.

Best wishes,
  Andrey

Comment 1 Shehjar Tikoo 2009-06-29 03:38:35 UTC

Hi!

GlusterFS continue crashing in my setup.  :( 

The client crashed again while Grid Engine attempted to create file
for redirected stdout (no writing), but this time backtrace is
different:
------
Core was generated by `glusterfs -f /etc/glusterfs/client.vol -l
/var/log/glusterfs/client.log /home'.

Program terminated with signal 11, Segmentation fault.

#0  0x00002b978ba6656c in gf_print_trace (signum=11) at common-utils.c:381

381     common-utils.c: No such file or directory.

        in common-utils.c

(gdb) bt

#0  0x00002b978ba6656c in gf_print_trace (signum=11) at common-utils.c:381

#1  <signal handler called>

#2  0x00002b978ba6656c in gf_print_trace (signum=6) at common-utils.c:381

#3  <signal handler called>

#4  0x00002b978c0d6b45 in raise () from /lib64/libc.so.6

#5  0x00002b978c0d80e0 in abort () from /lib64/libc.so.6

#6  0x00002b978c10efbb in ?? () from /lib64/libc.so.6

#7  0x00002b978c11421d in ?? () from /lib64/libc.so.6

#8  0x00002b978c116506 in ?? () from /lib64/libc.so.6

#9  0x00002b978c117c0c in malloc () from /lib64/libc.so.6

#10 0x00002b978d2a41e7 in wb_sync (frame=0x657060, file=0x653660,
winds=0x7fff1f27af20)

    at write-behind.c:381

#11 0x00002b978d2a44ff in wb_do_ops (frame=0x657060, file=0x653660,
winds=0x7fff1f27af20,

    unwinds=<value optimized out>, other_requests=0x7fff1f27af00) at
write-behind.c:1579

#12 0x00002b978d2a4617 in wb_process_queue (frame=0x657060,
file=0x653660, flush_all=0 '\0')

    at write-behind.c:1624

#13 0x00002b978d2a7d81 in wb_sync_cbk (frame=0x657060, cookie=<value
optimized out>,

    this=<value optimized out>, op_ret=67, op_errno=0, stbuf=<value
optimized out>)

    at write-behind.c:338

#14 0x00002b978d0941e0 in iot_writev_cbk (frame=0x6570c0,
cookie=<value optimized out>,

    this=<value optimized out>, op_ret=67, op_errno=0,
stbuf=0x7fff1f27b060) at io-threads.c:1186

#15 0x00002b978ce7daae in dht_writev_cbk (frame=0x2aaaac01d200,
cookie=<value optimized out>,

    this=<value optimized out>, op_ret=67, op_errno=0,
stbuf=0x7fff1f27b060) at dht-common.c:1797

#16 0x00002b978cc6a6e9 in client_write_cbk (frame=0x2aaaac01b120,
hdr=<value optimized out>,

    hdrlen=<value optimized out>, iobuf=<value optimized out>) at
client-protocol.c:4363

#17 0x00002b978cc5683a in protocol_client_pollin (this=0x611d30, trans=0x625c00)

    at client-protocol.c:6230

#18 0x00002b978cc610bc in notify (this=0x3f6f, event=<value optimized
out>, data=0x625c00)

    at client-protocol.c:6274

#19 0x00002b978ba5d183 in xlator_notify (xl=0x611d30, event=2,
data=0x625c00) at xlator.c:820

#20 0x00002aaaaaaaff0b in socket_event_handler (fd=<value optimized
out>, idx=28, data=0x625c00,

    poll_in=1, poll_out=0, poll_err=0) at socket.c:813

#21 0x00002b978ba752aa in event_dispatch_epoll (event_pool=0x6094f0)
at event.c:804

#22 0x0000000000403f34 in main (argc=6, argv=0x7fff1f27bfc8) at
glusterfsd.c:1223
------


The server crashed during writing a large case file (~20Mb) by Fluent
CFD solver:
---------
Core was generated by `/usr/sbin/glusterfsd -f
/etc/glusterfs/server.vol -l /var/log/glusterfs/server.'.

Program terminated with signal 6, Aborted.

#0  0x00002b22d73dbb45 in raise () from /lib64/libc.so.6

(gdb) bt

#0  0x00002b22d73dbb45 in raise () from /lib64/libc.so.6

#1  0x00002b22d73dd0e0 in abort () from /lib64/libc.so.6

#2  0x00002b22d7413fbb in ?? () from /lib64/libc.so.6

#3  0x00002b22d741921d in ?? () from /lib64/libc.so.6

#4  0x00002b22d741b506 in ?? () from /lib64/libc.so.6

#5  0x00002b22d741c92b in calloc () from /lib64/libc.so.6

#6  0x00002b22d858c14a in get_frame_for_call (trans=0x681d50, hdr=0x659c30)

    at ../../../../libglusterfs/src/stack.h:264

#7  0x00002b22d858c496 in protocol_server_interpret (this=0x60fb20,
trans=0x681d50,

    hdr_p=0x659c30 "", hdrlen=60, iobuf=0x66b320) at server-protocol.c:7481

#8  0x00002b22d858c720 in protocol_server_pollin (this=0x60fb20, trans=0x681d50)

    at server-protocol.c:7763

#9  0x00002b22d858c7b2 in notify (this=0x60fb20, event=<value
optimized out>, data=0x6)

    at server-protocol.c:7819

#10 0x00002b22d6d62183 in xlator_notify (xl=0x60fb20, event=2,
data=0x681d50) at xlator.c:820

#11 0x00002aaaaaaaff0b in socket_event_handler (fd=<value optimized
out>, idx=47, data=0x681d50,

    poll_in=1, poll_out=0, poll_err=0) at socket.c:813

#12 0x00002b22d6d7a2aa in event_dispatch_epoll (event_pool=0x6094f0)
at event.c:804

#13 0x0000000000403f34 in main (argc=7, argv=0x7fffd3f77c48) at
glusterfsd.c:1223

-----------

Regards,
  Andrey

Comment 2 Shehjar Tikoo 2009-06-29 03:40:45 UTC

Created attachment 33 [details]
This is a test attachment

Comment 3 Shehjar Tikoo 2009-06-29 03:48:22 UTC

I am not able to reproduce this but the problem generally seems connected to mem-pool related memory corruption.

Another strange thing is that in one of the back-traces submitted:
Later glusterFS crashed again with different backtrace:

----------

Core was generated by `glusterfs -f /etc/glusterfs/client.vol -l
/var/log/glusterfs/client.log /home'.

Program terminated with signal 6, Aborted.

#0  0x00002ae6dfcd4b45 in raise () from /lib64/libc.so.6

(gdb) bt

#0  0x00002ae6dfcd4b45 in raise () from /lib64/libc.so.6

#1  0x00002ae6dfcd60e0 in abort () from /lib64/libc.so.6

#2  0x00002ae6dfd0cfbb in ?? () from /lib64/libc.so.6

#3  0x00002ae6dfd1221d in ?? () from /lib64/libc.so.6

#4  0x00002ae6dfd13f76 in free () from /lib64/libc.so.6

#5  0x00002ae6df673efd in mem_put (pool=0x631a90, ptr=0x2aaaac0bc520)
at mem-pool.c:191

@@@@@@@@
########
HERE: The only place mem_put is called in io-threads is inside iot_destroy_request but this function is missing from this trace. Anyhow, I'll keep looking at this.
########
@@@@@@@@

#6  0x00002ae6e0c992ce in iot_dequeue_ordered (worker=0x631a20) at
io-threads.c:2407

#7  0x00002ae6e0c99326 in iot_worker_ordered (arg=<value optimized out>)

    at io-threads.c:2421

#8  0x00002ae6dfa8e020 in start_thread () from /lib64/libpthread.so.0

#9  0x00002ae6dfd68f8d in clone () from /lib64/libc.so.6

#10 0x0000000000000000 in ?? ()

----------

Comment 4 Shehjar Tikoo 2009-06-29 06:36:44 UTC

As reported by user on gluster-devel:

Hi everybody!



Recently I've migrated our small 24-node HPC-cluster from glusterFS
1.3.8 unify to 2.0 distribute. It seems that performance really
increased a lot. Thanks for your work!

I use the following translators. On servers:
posix->locks->iothreads->protocol/server; on clients:
protocol/client->distribute->iothreads->write-behind. IO-threads
translator uses 4 threads, NO autoscaling.



Unfortunately, after upgrade I've got new issues. First, I've noticed
a very high memory usage. Now GlusterFS on the head node eats 737Mb of
RES memory and doesnt return it back. The memory usage have been
increased in the migration process by the command "cd
${namespace_export} && find . | (cd ${distribute_mount} && xargs -d
'\n' stat -c '%n')". Note that provided migrate-unify-to-distribute.sh
script (with "execute_on" function) doesn't work...



Second problem is more important. A client on one of the nodes has
crashed today with the following backtrace:

------

Core was generated by `glusterfs -f /etc/glusterfs/client.vol -l
/var/log/glusterfs/client.log /home'.

Program terminated with signal 11, Segmentation fault.

#0  0x00002b8039bec860 in ?? () from /lib64/libc.so.6

(gdb) bt

#0  0x00002b8039bec860 in ?? () from /lib64/libc.so.6

#1  0x00002b8039bedc0c in malloc () from /lib64/libc.so.6

#2  0x00002b8039548732 in fop_writev_stub (frame=<value optimized out>,

    fn=0x2b803ab6c160 <iot_writev_wrapper>, fd=0x2aaab001e8a0,
vector=0x2aaab0071d50,

    count=<value optimized out>, off=105432, iobref=0x2aaab0082d60) at
common-utils.h:166

#3  0x00002b803ab6ec00 in iot_writev (frame=0x4, this=0x6150c0,
fd=0x2aaab0082711,

    vector=0x2aaab0083060, count=3, offset=105432, iobref=0x2aaab0082d60)

    at io-threads.c:1212

#4  0x00002b803ad7a3de in wb_sync (frame=0x2aaab0034c40, file=0x2aaaac007280,

    winds=0x7fff717a5450) at write-behind.c:445

#5  0x00002b803ad7a4ff in wb_do_ops (frame=0x2aaab0034c40, file=0x2aaaac007280,

    winds=0x7fff717a5450, unwinds=<value optimized out>,
other_requests=0x7fff717a5430)

    at write-behind.c:1579

#6  0x00002b803ad7a617 in wb_process_queue (frame=0x2aaab0034c40,
file=0x2aaaac007280,

    flush_all=0 '\0') at write-behind.c:1624

#7  0x00002b803ad7dd81 in wb_sync_cbk (frame=0x2aaab0034c40,

    cookie=<value optimized out>, this=<value optimized out>,
op_ret=19, op_errno=0,

    stbuf=<value optimized out>) at write-behind.c:338

#8  0x00002b803ab6a1e0 in iot_writev_cbk (frame=0x2aaab00309d0,

    cookie=<value optimized out>, this=<value optimized out>,
op_ret=19, op_errno=0,

    stbuf=0x7fff717a5590) at io-threads.c:1186

#9  0x00002b803a953aae in dht_writev_cbk (frame=0x63e3e0,
cookie=<value optimized out>,

    this=<value optimized out>, op_ret=19, op_errno=0, stbuf=0x7fff717a5590)

    at dht-common.c:1797

#10 0x00002b803a7406e9 in client_write_cbk (frame=0x648a80, hdr=<value
optimized out>,

    hdrlen=<value optimized out>, iobuf=<value optimized out>) at
client-protocol.c:4363

#11 0x00002b803a72c83a in protocol_client_pollin (this=0x60ec70, trans=0x61a380)

    at client-protocol.c:6230

#12 0x00002b803a7370bc in notify (this=0x4, event=<value optimized
out>, data=0x61a380)

    at client-protocol.c:6274

#13 0x00002b8039533183 in xlator_notify (xl=0x60ec70, event=2, data=0x61a380)

    at xlator.c:820

#14 0x00002aaaaaaaff0b in socket_event_handler (fd=<value optimized out>, idx=4,

    data=0x61a380, poll_in=1, poll_out=0, poll_err=0) at socket.c:813

#15 0x00002b803954b2aa in event_dispatch_epoll (event_pool=0x6094f0)
at event.c:804

#16 0x0000000000403f34 in main (argc=6, argv=0x7fff717a64f8) at
glusterfsd.c:1223

----------



Later glusterFS crashed again with different backtrace:

----------

Core was generated by `glusterfs -f /etc/glusterfs/client.vol -l
/var/log/glusterfs/client.log /home'.

Program terminated with signal 6, Aborted.

#0  0x00002ae6dfcd4b45 in raise () from /lib64/libc.so.6

(gdb) bt

#0  0x00002ae6dfcd4b45 in raise () from /lib64/libc.so.6

#1  0x00002ae6dfcd60e0 in abort () from /lib64/libc.so.6

#2  0x00002ae6dfd0cfbb in ?? () from /lib64/libc.so.6

#3  0x00002ae6dfd1221d in ?? () from /lib64/libc.so.6

#4  0x00002ae6dfd13f76 in free () from /lib64/libc.so.6

#5  0x00002ae6df673efd in mem_put (pool=0x631a90, ptr=0x2aaaac0bc520)
at mem-pool.c:191

#6  0x00002ae6e0c992ce in iot_dequeue_ordered (worker=0x631a20) at
io-threads.c:2407

#7  0x00002ae6e0c99326 in iot_worker_ordered (arg=<value optimized out>)

    at io-threads.c:2421

#8  0x00002ae6dfa8e020 in start_thread () from /lib64/libpthread.so.0

#9  0x00002ae6dfd68f8d in clone () from /lib64/libc.so.6

#10 0x0000000000000000 in ?? ()

----------



Hope this backtraces help to find an issue...



Best regards,

  Andrey

Comment 5 Raghavendra G 2009-06-30 03:33:05 UTC

Won't a valgrind report be helpful here?

(In reply to comment #4)
> I am not able to reproduce this but the problem generally seems connected to
> mem-pool related memory corruption.
> 
> Another strange thing is that in one of the back-traces submitted:
> Later glusterFS crashed again with different backtrace:
> 
> ----------
> 
> Core was generated by `glusterfs -f /etc/glusterfs/client.vol -l
> /var/log/glusterfs/client.log /home'.
> 
> Program terminated with signal 6, Aborted.
> 
> #0  0x00002ae6dfcd4b45 in raise () from /lib64/libc.so.6
> 
> (gdb) bt
> 
> #0  0x00002ae6dfcd4b45 in raise () from /lib64/libc.so.6
> 
> #1  0x00002ae6dfcd60e0 in abort () from /lib64/libc.so.6
> 
> #2  0x00002ae6dfd0cfbb in ?? () from /lib64/libc.so.6
> 
> #3  0x00002ae6dfd1221d in ?? () from /lib64/libc.so.6
> 
> #4  0x00002ae6dfd13f76 in free () from /lib64/libc.so.6
> 
> #5  0x00002ae6df673efd in mem_put (pool=0x631a90, ptr=0x2aaaac0bc520)
> at mem-pool.c:191
> 
> @@@@@@@@
> ########
> HERE: The only place mem_put is called in io-threads is inside
> iot_destroy_request but this function is missing from this trace. Anyhow, I'll
> keep looking at this.
> ########
> @@@@@@@@
> 
> #6  0x00002ae6e0c992ce in iot_dequeue_ordered (worker=0x631a20) at
> io-threads.c:2407
> 
> #7  0x00002ae6e0c99326 in iot_worker_ordered (arg=<value optimized out>)
> 
>     at io-threads.c:2421
> 
> #8  0x00002ae6dfa8e020 in start_thread () from /lib64/libpthread.so.0
> 
> #9  0x00002ae6dfd68f8d in clone () from /lib64/libc.so.6
> 
> #10 0x0000000000000000 in ?? ()
> 
> ----------

Comment 6 Shehjar Tikoo 2009-07-04 06:06:30 UTC

(In reply to comment #4)
> I am not able to reproduce this but the problem generally seems connected to
> mem-pool related memory corruption.
> 

I can reproduce it now.

Note the default size of the mem-pool in io-threads:

#define IOT_REQUEST_MEMPOOL_SIZE        64

Any time the number of pending requests goes beyond 64, the mem-pool starts allocating from the heap. Next, when this heap-allocated memory is mem_put, the mem-pool tries to see if the address belongs to the pool. If it does, it is returned to the pool, otherwise, a FREE is called.

For our test case, the bug gets triggered when:
#define IOT_REQUEST_MEMPOOL_SIZE        2

So that any more requests than 2 entries from the mem-pool will be allocated from the heap. There is clearly something wrong in the way mem-pool does allocation and de-allocation when it runs out of memory.

Comment 7 Shehjar Tikoo 2009-07-04 07:42:36 UTC

Proposed fix: http://patches.gluster.com/patch/672/

Comment 8 Shehjar Tikoo 2009-07-19 06:00:11 UTC

Fix in repo:

http://git.savannah.gnu.org/cgit/gluster.git/commit/?id=7261ef381a2c3c7bf5ef0ecd2392f7cab9e60e37

Note You need to log in before you can comment on or make changes to this bug.