Joe Julian
2016-Feb-05 06:46 UTC
[Gluster-users] [Gluster-devel] GlusterFS FUSE client hangs on rsyncing lots of file
Interesting. I just encountered a hanging flush problem, too. Probably unrelated but if you want to give this a try a temporary workaround I found was to drop caches, "echo 3 > /proc/vm/drop_caches", on all the servers prior to the flush operation. On February 4, 2016 10:06:45 PM PST, Raghavendra G <raghavendra at gluster.com> wrote:>+soumyak, +rtalur. > >On Fri, Jan 29, 2016 at 2:34 PM, Pranith Kumar Karampuri < >pkarampu at redhat.com> wrote: > >> >> >> On 01/28/2016 05:05 PM, Pranith Kumar Karampuri wrote: >> >>> With baul jianguo's help I am able to see that FLUSH fops are >hanging for >>> some reason. >>> >>> pk1 at localhost - ~/Downloads >>> 17:02:13 :) ? grep "unique=" client-dump1.txt >>> unique=3160758373 >>> unique=2073075682 >>> unique=1455047665 >>> unique=0 >>> >>> pk1 at 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. >>> >> +Raghavendra G >> >> All the stubs are hung in write-behind. I checked that the statedumps >> doesn't have any writes in progress. May be because of some race, >flush fop >> is not resumed after write calls are complete? It seems this issue >happens >> only when io-threads is enabled on the client. >> >> Pranith >> >> >>> 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 at gmail.com> >>>> 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 at redhat.com> 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 at natalenko.name> 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 at redhat.com> 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 at natalenko.name> 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 at gluster.org >>>>>>>>>>>>>>>> http://www.gluster.org/mailman/listinfo/gluster-users >>>>>>>>>>>>>>>> >>>>>>>>>>>>>>> _______________________________________________ >>>>>>>>>>>>>>> Gluster-devel mailing list >>>>>>>>>>>>>>> Gluster-devel at gluster.org >>>>>>>>>>>>>>> http://www.gluster.org/mailman/listinfo/gluster-devel >>>>>>>>>>>>>>> >>>>>>>>>>>>>> _______________________________________________ >>>>>>>>>>>>>> Gluster-devel mailing list >>>>>>>>>>>>>> Gluster-devel at gluster.org >>>>>>>>>>>>>> http://www.gluster.org/mailman/listinfo/gluster-devel >>>>>>>>>>>>>> >>>>>>>>>>>>> _______________________________________________ >>>>>>>>>>>>> Gluster-devel mailing list >>>>>>>>>>>>> Gluster-devel at gluster.org >>>>>>>>>>>>> http://www.gluster.org/mailman/listinfo/gluster-devel >>>>>>>>>>>>> >>>>>>>>>>>> _______________________________________________ >>>>>>>>>>> Gluster-users mailing list >>>>>>>>>>> Gluster-users at gluster.org >>>>>>>>>>> http://www.gluster.org/mailman/listinfo/gluster-users >>>>>>>>>>> >>>>>>>>>> _______________________________________________ >>>>>>>>>> Gluster-devel mailing list >>>>>>>>>> Gluster-devel at gluster.org >>>>>>>>>> http://www.gluster.org/mailman/listinfo/gluster-devel >>>>>>>>>> >>>>>>>>> >>>>>>>> >>> _______________________________________________ >>> Gluster-devel mailing list >>> Gluster-devel at gluster.org >>> http://www.gluster.org/mailman/listinfo/gluster-devel >>> >> >> _______________________________________________ >> Gluster-devel mailing list >> Gluster-devel at gluster.org >> http://www.gluster.org/mailman/listinfo/gluster-devel >> > > > >-- >Raghavendra G > > >------------------------------------------------------------------------ > >_______________________________________________ >Gluster-devel mailing list >Gluster-devel at gluster.org >http://www.gluster.org/mailman/listinfo/gluster-devel-- Sent from my Android device with K-9 Mail. Please excuse my brevity. -------------- next part -------------- An HTML attachment was scrubbed... URL: <http://www.gluster.org/pipermail/gluster-users/attachments/20160204/e0eacb8c/attachment.html>
Raghavendra Gowdappa
2016-Oct-14 02:59 UTC
[Gluster-users] [Gluster-devel] GlusterFS FUSE client hangs on rsyncing lots of file
I've a patch [1], which I think fixes the problem in write-behind. If possible can anyone of you please let me know whether it fixes the issue (with client.io-threads turned on)? [1] http://review.gluster.org/15579 ----- Original Message -----> From: "Joe Julian" <joe at julianfamily.org> > To: "Raghavendra G" <raghavendra at gluster.com>, "Pranith Kumar Karampuri" <pkarampu at redhat.com>, "Soumya Koduri" > <skoduri at redhat.com>, rtalur at redhat.com > Cc: gluster-users at gluster.org, "Gluster Devel" <gluster-devel at gluster.org> > Sent: Friday, February 5, 2016 12:16:01 PM > Subject: Re: [Gluster-users] [Gluster-devel] GlusterFS FUSE client hangs on rsyncing lots of file > > Interesting. I just encountered a hanging flush problem, too. Probably > unrelated but if you want to give this a try a temporary workaround I found > was to drop caches, "echo 3 > /proc/vm/drop_caches", on all the servers > prior to the flush operation. > > On February 4, 2016 10:06:45 PM PST, Raghavendra G <raghavendra at gluster.com> > wrote: > > > +soumyak, +rtalur. > > On Fri, Jan 29, 2016 at 2:34 PM, Pranith Kumar Karampuri < > pkarampu at redhat.com > wrote: > > > > > On 01/28/2016 05:05 PM, Pranith Kumar Karampuri wrote: > > > With baul jianguo's help I am able to see that FLUSH fops are hanging for > some reason. > > pk1 at localhost - ~/Downloads > 17:02:13 :) ? grep "unique=" client-dump1.txt > unique=3160758373 > unique= 2073075682 > unique=1455047665 > unique=0 > > pk1 at 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. > +Raghavendra G > > All the stubs are hung in write-behind. I checked that the statedumps doesn't > have any writes in progress. May be because of some race, flush fop is not > resumed after write calls are complete? It seems this issue happens only > when io-threads is enabled on the client. > > Pranith > > > > > 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 at gmail.com > 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 at redhat.com > 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 at natalenko.name > 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 at redhat.com > 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 at natalenko.name > 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 at gluster.org > http://www.gluster.org/mailman/listinfo/gluster-users > _______________________________________________ > Gluster-devel mailing list > Gluster-devel at gluster.org > http://www.gluster.org/mailman/listinfo/gluster-devel > _______________________________________________ > Gluster-devel mailing list > Gluster-devel at gluster.org > http://www.gluster.org/mailman/listinfo/gluster-devel > _______________________________________________ > Gluster-devel mailing list > Gluster-devel at gluster.org > http://www.gluster.org/mailman/listinfo/gluster-devel > _______________________________________________ > Gluster-users mailing list > Gluster-users at gluster.org > http://www.gluster.org/mailman/listinfo/gluster-users > _______________________________________________ > Gluster-devel mailing list > Gluster-devel at gluster.org > http://www.gluster.org/mailman/listinfo/gluster-devel > > > _______________________________________________ > Gluster-devel mailing list > Gluster-devel at gluster.org > http://www.gluster.org/mailman/listinfo/gluster-devel > > _______________________________________________ > Gluster-devel mailing list > Gluster-devel at gluster.org > http://www.gluster.org/mailman/listinfo/gluster-devel > > > > -- > Raghavendra G > > > > > > Gluster-devel mailing list > Gluster-devel at gluster.org > http://www.gluster.org/mailman/listinfo/gluster-devel > > -- > Sent from my Android device with K-9 Mail. Please excuse my brevity. > > _______________________________________________ > Gluster-users mailing list > Gluster-users at gluster.org > http://www.gluster.org/mailman/listinfo/gluster-users