Re: [Gluster-devel] GlusterFS FUSE client hangs on rsyncing lots of file

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



With baul jianguo's help I am able to see that FLUSH fops are hanging for some reason.

pk1@localhost - ~/Downloads
17:02:13 :) ⚡ grep "unique=" client-dump1.txt
unique=3160758373
unique=2073075682
unique=1455047665
unique=0

pk1@localhost - ~/Downloads
17:02:21 :) ⚡ grep "unique=" client-dump-0.txt
unique=3160758373
unique=2073075682
unique=1455047665
unique=0

I will be debugging a bit more and post my findings.

Pranith
On 01/28/2016 03:18 PM, baul jianguo wrote:
the client glusterfs gdb info, main thread id is 70800。
  In the top output,70800 thread time 1263:30,70810 thread time
1321:10,other thread time too small。
(gdb) thread apply all bt



Thread 9 (Thread 0x7fc21acaf700 (LWP 70801)):

#0  0x00007fc21cc0c535 in sigwait () from /lib64/libpthread.so.0

#1  0x000000000040539b in glusterfs_sigwaiter (arg=<value optimized
out>) at glusterfsd.c:1653

#2  0x00007fc21cc04a51 in start_thread () from /lib64/libpthread.so.0

#3  0x00007fc21c56e93d in clone () from /lib64/libc.so.6



Thread 8 (Thread 0x7fc21a2ae700 (LWP 70802)):

#0  0x00007fc21cc08a0e in pthread_cond_timedwait@@GLIBC_2.3.2 () from
/lib64/libpthread.so.0

#1  0x00007fc21ded02bf in syncenv_task (proc=0x121ee60) at syncop.c:493

#2  0x00007fc21ded6300 in syncenv_processor (thdata=0x121ee60) at syncop.c:571

#3  0x00007fc21cc04a51 in start_thread () from /lib64/libpthread.so.0

#4  0x00007fc21c56e93d in clone () from /lib64/libc.so.6



Thread 7 (Thread 0x7fc2198ad700 (LWP 70803)):

#0  0x00007fc21cc08a0e in pthread_cond_timedwait@@GLIBC_2.3.2 () from
/lib64/libpthread.so.0

#1  0x00007fc21ded02bf in syncenv_task (proc=0x121f220) at syncop.c:493

#2  0x00007fc21ded6300 in syncenv_processor (thdata=0x121f220) at syncop.c:571

#3  0x00007fc21cc04a51 in start_thread () from /lib64/libpthread.so.0

#4  0x00007fc21c56e93d in clone () from /lib64/libc.so.6



Thread 6 (Thread 0x7fc21767d700 (LWP 70805)):

#0  0x00007fc21cc0bfbd in nanosleep () from /lib64/libpthread.so.0

#1  0x00007fc21deb16bc in gf_timer_proc (ctx=0x11f2010) at timer.c:170

#2  0x00007fc21cc04a51 in start_thread () from /lib64/libpthread.so.0

#3  0x00007fc21c56e93d in clone () from /lib64/libc.so.6



Thread 5 (Thread 0x7fc20fb1e700 (LWP 70810)):

#0  0x00007fc21c566987 in readv () from /lib64/libc.so.6

#1  0x00007fc21accbc55 in fuse_thread_proc (data=0x120f450) at
fuse-bridge.c:4752

#2  0x00007fc21cc04a51 in start_thread () from /lib64/libpthread.so.0

#3  0x00007fc21c56e93d in clone () from /lib64/libc.so.6 时间最多



Thread 4 (Thread 0x7fc20f11d700 (LWP 70811)): 少点

#0  0x00007fc21cc0b7dd in read () from /lib64/libpthread.so.0

#1  0x00007fc21acc0e73 in read (data=<value optimized out>) at
/usr/include/bits/unistd.h:45

#2  notify_kernel_loop (data=<value optimized out>) at fuse-bridge.c:3786

#3  0x00007fc21cc04a51 in start_thread () from /lib64/libpthread.so.0

#4  0x00007fc21c56e93d in clone () from /lib64/libc.so.6



Thread 3 (Thread 0x7fc1b16fe700 (LWP 206224)):

---Type <return> to continue, or q <return> to quit---

#0  0x00007fc21cc08a0e in pthread_cond_timedwait@@GLIBC_2.3.2 () from
/lib64/libpthread.so.0

#1  0x00007fc20e515e60 in iot_worker (data=0x19eeda0) at io-threads.c:157

#2  0x00007fc21cc04a51 in start_thread () from /lib64/libpthread.so.0

#3  0x00007fc21c56e93d in clone () from /lib64/libc.so.6



Thread 2 (Thread 0x7fc1b0bfb700 (LWP 214361)):

#0  0x00007fc21cc08a0e in pthread_cond_timedwait@@GLIBC_2.3.2 () from
/lib64/libpthread.so.0

#1  0x00007fc20e515e60 in iot_worker (data=0x19eeda0) at io-threads.c:157

#2  0x00007fc21cc04a51 in start_thread () from /lib64/libpthread.so.0

#3  0x00007fc21c56e93d in clone () from /lib64/libc.so.6



Thread 1 (Thread 0x7fc21e31e700 (LWP 70800)):

#0  0x00007fc21c56ef33 in epoll_wait () from /lib64/libc.so.6

#1  0x00007fc21deea3e7 in event_dispatch_epoll (event_pool=0x120dec0)
at event-epoll.c:428

#2  0x00000000004075e4 in main (argc=4, argv=0x7fff3dc93698) at
glusterfsd.c:1983

On Thu, Jan 28, 2016 at 5:29 PM, baul jianguo <roidinev@xxxxxxxxx> wrote:
http://pastebin.centos.org/38941/
client statedump,only the pid 27419,168030,208655 hang,you can search
this pid in the statedump file。

On Wed, Jan 27, 2016 at 4:35 PM, Pranith Kumar Karampuri
<pkarampu@xxxxxxxxxx> wrote:
Hi,
       If the hang appears on enabling client side io-threads then it could
be because of some race that is seen when io-threads is enabled on the
client side. 2 things will help us debug this issue:
1) thread apply all bt inside gdb (with debuginfo rpms/debs installed )
2) Complete statedump of the mount at two intervals preferably 10 seconds
apart. It becomes difficult to find out which ones are stuck vs the ones
that are on-going when we have just one statedump. If we have two, we can
find which frames are common in both of the statedumps and then take a
closer look there.

Feel free to ping me on #gluster-dev, nick: pranithk if you have the process
hung in that state and you guys don't mind me do a live debugging with you
guys. This option is the best of the lot!

Thanks a lot baul, Oleksandr for the debugging so far!

Pranith


On 01/25/2016 01:03 PM, baul jianguo wrote:
3.5.7 also hangs.only the flush op hung. Yes,off the
performance.client-io-threads ,no hang.

The hang does not relate the client kernel version.

One client statdump about flush op,any abnormal?

[global.callpool.stack.12]

uid=0

gid=0

pid=14432

unique=16336007098

lk-owner=77cb199aa36f3641

op=FLUSH

type=1

cnt=6



[global.callpool.stack.12.frame.1]

ref_count=1

translator=fuse

complete=0



[global.callpool.stack.12.frame.2]

ref_count=0

translator=datavolume-write-behind

complete=0

parent=datavolume-read-ahead

wind_from=ra_flush

wind_to=FIRST_CHILD (this)->fops->flush

unwind_to=ra_flush_cbk



[global.callpool.stack.12.frame.3]

ref_count=1

translator=datavolume-read-ahead

complete=0

parent=datavolume-open-behind

wind_from=default_flush_resume

wind_to=FIRST_CHILD(this)->fops->flush

unwind_to=default_flush_cbk



[global.callpool.stack.12.frame.4]

ref_count=1

translator=datavolume-open-behind

complete=0

parent=datavolume-io-threads

wind_from=iot_flush_wrapper

wind_to=FIRST_CHILD(this)->fops->flush

unwind_to=iot_flush_cbk



[global.callpool.stack.12.frame.5]

ref_count=1

translator=datavolume-io-threads

complete=0

parent=datavolume

wind_from=io_stats_flush

wind_to=FIRST_CHILD(this)->fops->flush

unwind_to=io_stats_flush_cbk



[global.callpool.stack.12.frame.6]

ref_count=1

translator=datavolume

complete=0

parent=fuse

wind_from=fuse_flush_resume

wind_to=xl->fops->flush

unwind_to=fuse_err_cbk



On Sun, Jan 24, 2016 at 5:35 AM, Oleksandr Natalenko
<oleksandr@xxxxxxxxxxxxxx> wrote:
With "performance.client-io-threads" set to "off" no hangs occurred in 3
rsync/rm rounds. Could that be some fuse-bridge lock race? Will bring
that
option to "on" back again and try to get full statedump.

On четвер, 21 січня 2016 р. 14:54:47 EET Raghavendra G wrote:
On Thu, Jan 21, 2016 at 10:49 AM, Pranith Kumar Karampuri <

pkarampu@xxxxxxxxxx> wrote:
On 01/18/2016 02:28 PM, Oleksandr Natalenko wrote:
XFS. Server side works OK, I'm able to mount volume again. Brick is
30%
full.
Oleksandr,

        Will it be possible to get the statedump of the client, bricks

output next time it happens?


https://github.com/gluster/glusterfs/blob/master/doc/debugging/statedump.m
d#how-to-generate-statedump
We also need to dump inode information. To do that you've to add
"all=yes"
to /var/run/gluster/glusterdump.options before you issue commands to get
statedump.

Pranith

On понеділок, 18 січня 2016 р. 15:07:18 EET baul jianguo wrote:
What is your brick file system? and the glusterfsd process and all
thread status?
I met same issue when client app such as rsync stay in D status,and
the brick process and relate thread also be in the D status.
And the brick dev disk util is 100% .

On Sun, Jan 17, 2016 at 6:13 AM, Oleksandr Natalenko

<oleksandr@xxxxxxxxxxxxxx> wrote:
Wrong assumption, rsync hung again.

On субота, 16 січня 2016 р. 22:53:04 EET Oleksandr Natalenko wrote:
One possible reason:

cluster.lookup-optimize: on
cluster.readdir-optimize: on

I've disabled both optimizations, and at least as of now rsync
still
does
its job with no issues. I would like to find out what option causes
such
a
behavior and why. Will test more.

On пʼятниця, 15 січня 2016 р. 16:09:51 EET Oleksandr Natalenko
wrote:
Another observation: if rsyncing is resumed after hang, rsync
itself
hangs a lot faster because it does stat of already copied files.
So,
the
reason may be not writing itself, but massive stat on GlusterFS
volume
as well.

15.01.2016 09:40, Oleksandr Natalenko написав:
While doing rsync over millions of files from ordinary partition
to
GlusterFS volume, just after approx. first 2 million rsync hang
happens, and the following info appears in dmesg:

===
[17075038.924481] INFO: task rsync:10310 blocked for more than
120
seconds.
[17075038.931948] "echo 0 >
/proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[17075038.940748] rsync           D ffff88207fc13680     0 10310
10309 0x00000080
[17075038.940752]  ffff8809c578be18 0000000000000086
ffff8809c578bfd8
0000000000013680
[17075038.940756]  ffff8809c578bfd8 0000000000013680
ffff880310cbe660
ffff881159d16a30
[17075038.940759]  ffff881e3aa25800 ffff8809c578be48
ffff881159d16b10
ffff88087d553980
[17075038.940762] Call Trace:
[17075038.940770]  [<ffffffff8160a1d9>] schedule+0x29/0x70
[17075038.940797]  [<ffffffffa023a53d>]
__fuse_request_send+0x13d/0x2c0
[fuse]
[17075038.940801]  [<ffffffffa023db30>] ?
fuse_get_req_nofail_nopages+0xc0/0x1e0 [fuse]
[17075038.940805]  [<ffffffff81098350>] ? wake_up_bit+0x30/0x30
[17075038.940809]  [<ffffffffa023a6d2>]
fuse_request_send+0x12/0x20
[fuse]
[17075038.940813]  [<ffffffffa024382f>] fuse_flush+0xff/0x150
[fuse]
[17075038.940817]  [<ffffffff811c45c4>] filp_close+0x34/0x80
[17075038.940821]  [<ffffffff811e4ed8>] __close_fd+0x78/0xa0
[17075038.940824]  [<ffffffff811c6103>] SyS_close+0x23/0x50
[17075038.940828]  [<ffffffff81614de9>]
system_call_fastpath+0x16/0x1b
===

rsync blocks in D state, and to kill it, I have to do umount
--lazy
on
GlusterFS mountpoint, and then kill corresponding client
glusterfs
process. Then rsync exits.

Here is GlusterFS volume info:

===
Volume Name: asterisk_records
Type: Distributed-Replicate
Volume ID: dc1fe561-fa3a-4f2e-8330-ec7e52c75ba4
Status: Started
Number of Bricks: 3 x 2 = 6
Transport-type: tcp
Bricks:
Brick1:

server1:/bricks/10_megaraid_0_3_9_x_0_4_3_hdd_r1_nolvm_hdd_storage_0
1
/as
te
risk/records Brick2:

server2:/bricks/10_megaraid_8_5_14_x_8_6_16_hdd_r1_nolvm_hdd_storage
_
01/
as
terisk/records Brick3:

server1:/bricks/11_megaraid_0_5_4_x_0_6_5_hdd_r1_nolvm_hdd_storage_0
2
/as
te
risk/records Brick4:

server2:/bricks/11_megaraid_8_7_15_x_8_8_20_hdd_r1_nolvm_hdd_storage
_
02/
as
terisk/records Brick5:

server1:/bricks/12_megaraid_0_7_6_x_0_13_14_hdd_r1_nolvm_hdd_storage
_
03/
as
terisk/records Brick6:

server2:/bricks/12_megaraid_8_9_19_x_8_13_24_hdd_r1_nolvm_hdd_storag
e
_03
/a
sterisk/records Options Reconfigured:
cluster.lookup-optimize: on
cluster.readdir-optimize: on
client.event-threads: 2
network.inode-lru-limit: 4096
server.event-threads: 4
performance.client-io-threads: on
storage.linux-aio: on
performance.write-behind-window-size: 4194304
performance.stat-prefetch: on
performance.quick-read: on
performance.read-ahead: on
performance.flush-behind: on
performance.write-behind: on
performance.io-thread-count: 2
performance.cache-max-file-size: 1048576
performance.cache-size: 33554432
features.cache-invalidation: on
performance.readdir-ahead: on
===

The issue reproduces each time I rsync such an amount of files.

How could I debug this issue better?
_______________________________________________
Gluster-users mailing list
Gluster-users@xxxxxxxxxxx
http://www.gluster.org/mailman/listinfo/gluster-users
_______________________________________________
Gluster-devel mailing list
Gluster-devel@xxxxxxxxxxx
http://www.gluster.org/mailman/listinfo/gluster-devel
_______________________________________________
Gluster-devel mailing list
Gluster-devel@xxxxxxxxxxx
http://www.gluster.org/mailman/listinfo/gluster-devel
_______________________________________________
Gluster-devel mailing list
Gluster-devel@xxxxxxxxxxx
http://www.gluster.org/mailman/listinfo/gluster-devel
_______________________________________________
Gluster-users mailing list
Gluster-users@xxxxxxxxxxx
http://www.gluster.org/mailman/listinfo/gluster-users
_______________________________________________
Gluster-devel mailing list
Gluster-devel@xxxxxxxxxxx
http://www.gluster.org/mailman/listinfo/gluster-devel


_______________________________________________
Gluster-users mailing list
Gluster-users@xxxxxxxxxxx
http://www.gluster.org/mailman/listinfo/gluster-users




[Index of Archives]     [Gluster Development]     [Linux Filesytems Development]     [Linux ARM Kernel]     [Linux ARM]     [Linux Omap]     [Fedora ARM]     [IETF Annouce]     [Bugtraq]     [Linux OMAP]     [Linux MIPS]     [eCos]     [Asterisk Internet PBX]     [Linux API]

  Powered by Linux