[Gluster-users] Apache hung tasks still occur with glusterfs 3.2.1

Jiri Lunacek jiri.lunacek at hosting90.cz
Mon Jun 13 08:48:30 UTC 2011 

Hi all.

We have been having problems with hung tasks of apache reading from glusterfs 2-replica volume ever since upgrading to 3.2.0. The problems were identical to those described here: http://gluster.org/pipermail/gluster-users/2011-May/007697.html

Yesterday we updated to 3.2.1.

A good thing is that the hung tasks stopped appearing when gluster is in "intact" operation, i.e. when there are no modifications to the gluster configs at all.
Today we modified some other volume exported by the same cluster (but not sharing anything with the volume used by the apache process). And, once again, two requests of apache reading from glusterfs volume are stuck.

Any help with this issue would be very appreciated as right now we have to nightly-reboot the machine as the processes re stuck in iowait -> unkillable.

I really do not want to go through the downgrade to 3.1.4 since it seems from the mailing list that it may not go exactly smooth. We are exporting millions of files and any large operation on the exported filesystem takes days.

I am attaching tech info on the problem.

client:
Centos 5.6
2.6.18-238.9.1.el5
fuse-2.7.4-8.el5
glusterfs-fuse-3.2.1-1
glusterfs-core-3.2.1-1

servers:
Centos 5.6
2.6.18-194.32.1.el5
fuse-2.7.4-8.el5
glusterfs-fuse-3.2.1-1
glusterfs-core-3.2.1-1

dmesg:
INFO: task httpd:1246 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
httpd         D ffff81000101d7a0     0  1246   2394          1247  1191 (NOTLB)
 ffff81013ee7dc38 0000000000000082 0000000000000092 ffff81013ee7dcd8
 ffff81013ee7dd04 000000000000000a ffff810144d0f7e0 ffff81019fc28100
 0000308f8b444727 00000000000014ee ffff810144d0f9c8 000000038006e608
Call Trace:
 [<ffffffff8006ec4e>] do_gettimeofday+0x40/0x90
 [<ffffffff80028c5a>] sync_page+0x0/0x43
 [<ffffffff800637ca>] io_schedule+0x3f/0x67
 [<ffffffff80028c98>] sync_page+0x3e/0x43
 [<ffffffff8006390e>] __wait_on_bit_lock+0x36/0x66
 [<ffffffff8003ff27>] __lock_page+0x5e/0x64
 [<ffffffff800a2921>] wake_bit_function+0x0/0x23
 [<ffffffff8003fd85>] pagevec_lookup+0x17/0x1e
 [<ffffffff800cc666>] invalidate_inode_pages2_range+0x73/0x1bd
 [<ffffffff8004fc94>] finish_wait+0x32/0x5d
 [<ffffffff884b9798>] :fuse:wait_answer_interruptible+0xb6/0xbd
 [<ffffffff800a28f3>] autoremove_wake_function+0x0/0x2e
 [<ffffffff8009a485>] recalc_sigpending+0xe/0x25
 [<ffffffff8001decc>] sigprocmask+0xb7/0xdb
 [<ffffffff884bd456>] :fuse:fuse_finish_open+0x36/0x62
 [<ffffffff884bda11>] :fuse:fuse_open_common+0x147/0x158
 [<ffffffff884bda22>] :fuse:fuse_open+0x0/0x7
 [<ffffffff8001eb99>] __dentry_open+0xd9/0x1dc
 [<ffffffff8002766e>] do_filp_open+0x2a/0x38
 [<ffffffff8001a061>] do_sys_open+0x44/0xbe
 [<ffffffff8005d28d>] tracesys+0xd5/0xe0

INFO: task httpd:1837 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
httpd         D ffff810001004420     0  1837   2394          1856  1289 (NOTLB)
 ffff81013c6f9c38 0000000000000086 ffff81013c6f9bf8 00000000fffffffe
 ffff810170ce7000 000000000000000a ffff81019c0ae7a0 ffffffff80311b60
 0000308c0f83d792 0000000000000ec4 ffff81019c0ae988 000000008006e608
Call Trace:
 [<ffffffff8006ec4e>] do_gettimeofday+0x40/0x90
 [<ffffffff80028c5a>] sync_page+0x0/0x43
 [<ffffffff800637ca>] io_schedule+0x3f/0x67
 [<ffffffff80028c98>] sync_page+0x3e/0x43
 [<ffffffff8006390e>] __wait_on_bit_lock+0x36/0x66
 [<ffffffff8003ff27>] __lock_page+0x5e/0x64
 [<ffffffff800a2921>] wake_bit_function+0x0/0x23
 [<ffffffff8003fd85>] pagevec_lookup+0x17/0x1e
 [<ffffffff800cc666>] invalidate_inode_pages2_range+0x73/0x1bd
 [<ffffffff8004fc94>] finish_wait+0x32/0x5d
 [<ffffffff884b9798>] :fuse:wait_answer_interruptible+0xb6/0xbd
 [<ffffffff800a28f3>] autoremove_wake_function+0x0/0x2e
 [<ffffffff8009a485>] recalc_sigpending+0xe/0x25
 [<ffffffff8001decc>] sigprocmask+0xb7/0xdb
 [<ffffffff884bd456>] :fuse:fuse_finish_open+0x36/0x62
 [<ffffffff884bda11>] :fuse:fuse_open_common+0x147/0x158
 [<ffffffff884bda22>] :fuse:fuse_open+0x0/0x7
 [<ffffffff8001eb99>] __dentry_open+0xd9/0x1dc
 [<ffffffff8002766e>] do_filp_open+0x2a/0x38
 [<ffffffff8001a061>] do_sys_open+0x44/0xbe
 [<ffffffff8005d28d>] tracesys+0xd5/0xe0

INFO: task httpd:383 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
httpd         D ffff81019fa21100     0   383   2394           534       (NOTLB)
 ffff81013e497c08 0000000000000082 ffff810183eb8910 ffffffff884b9219
 ffff81019e41c600 0000000000000009 ffff81019b1e2100 ffff81019fa21100
 0000308c0e2c2bfb 0000000000016477 ffff81019b1e22e8 000000038006e608
Call Trace:
 [<ffffffff884b9219>] :fuse:flush_bg_queue+0x2b/0x48
 [<ffffffff8006ec4e>] do_gettimeofday+0x40/0x90
 [<ffffffff8005a9f9>] getnstimeofday+0x10/0x28
 [<ffffffff80028c5a>] sync_page+0x0/0x43
 [<ffffffff800637ca>] io_schedule+0x3f/0x67
 [<ffffffff80028c98>] sync_page+0x3e/0x43
 [<ffffffff8006390e>] __wait_on_bit_lock+0x36/0x66
 [<ffffffff8003ff27>] __lock_page+0x5e/0x64
 [<ffffffff800a2921>] wake_bit_function+0x0/0x23
 [<ffffffff8000c48d>] do_generic_mapping_read+0x1df/0x359
 [<ffffffff8000d279>] file_read_actor+0x0/0x159
 [<ffffffff8000c753>] __generic_file_aio_read+0x14c/0x198
 [<ffffffff800c8c45>] generic_file_read+0xac/0xc5
 [<ffffffff800a28f3>] autoremove_wake_function+0x0/0x2e
 [<ffffffff80130778>] selinux_file_permission+0x9f/0xb4
 [<ffffffff8000b78d>] vfs_read+0xcb/0x171
 [<ffffffff80011d34>] sys_read+0x45/0x6e
 [<ffffffff8005d28d>] tracesys+0xd5/0xe0

possibly relevant log messages:
[2011-06-13 09:09:14.985576] W [socket.c:1494:__socket_proto_state_machine] 0-glusterfs: reading from socket failed. Error (Transport endpoint is not connected), peer (81.0.225.122:24007)
[2011-06-13 09:09:25.741055] I [glusterfsd-mgmt.c:637:mgmt_getspec_cbk] 0-: No change in volfile, continuing
[2011-06-13 09:59:00.644130] I [afr-common.c:639:afr_lookup_self_heal_check] 0-isifa1-replicate-0: size differs for /data/foto/thumbs/3140/31409780.jpg 
[2011-06-13 09:59:00.644269] I [afr-common.c:801:afr_lookup_done] 0-isifa1-replicate-0: background  meta-data data self-heal triggered. path: /data/foto/thumbs/3140/31409780.jpg
[2011-06-13 09:59:00.822524] W [dict.c:437:dict_ref] (-->/opt/glusterfs/3.2.1/lib64/glusterfs/3.2.1/xlator/protocol/client.so(client3_1_fstat_cbk+0x2cb) [0x2aaaab1afa0b] (-->/opt/glusterfs/3.2.1/lib64/glusterfs/3.2.1/xlator/cluster/replicate.so(afr_sh_data_fstat_cbk+0x17d) [0x2aaaab3e4c9d] (-->/opt/glusterfs/3.2.1/lib64/glusterfs/3.2.1/xlator/cluster/replicate.so(afr_sh_data_fix+0x1fc) [0x2aaaab3e493c]))) 0-dict: dict is NULL
[2011-06-13 09:59:00.824323] I [afr-common.c:639:afr_lookup_self_heal_check] 0-isifa1-replicate-0: size differs for /data/foto/thumbs/3140/31409781.jpg 
[2011-06-13 09:59:00.824356] I [afr-common.c:801:afr_lookup_done] 0-isifa1-replicate-0: background  meta-data data self-heal triggered. path: /data/foto/thumbs/3140/31409781.jpg
[2011-06-13 09:59:00.826494] I [afr-self-heal-common.c:1557:afr_self_heal_completion_cbk] 0-isifa1-replicate-0: background  meta-data data self-heal completed on /data/foto/thumbs/3140/31409780.jpg
[2011-06-13 09:59:00.830902] W [dict.c:437:dict_ref] (-->/opt/glusterfs/3.2.1/lib64/glusterfs/3.2.1/xlator/protocol/client.so(client3_1_fstat_cbk+0x2cb) [0x2aaaab1afa0b] (-->/opt/glusterfs/3.2.1/lib64/glusterfs/3.2.1/xlator/cluster/replicate.so(afr_sh_data_fstat_cbk+0x17d) [0x2aaaab3e4c9d] (-->/opt/glusterfs/3.2.1/lib64/glusterfs/3.2.1/xlator/cluster/replicate.so(afr_sh_data_fix+0x1fc) [0x2aaaab3e493c]))) 0-dict: dict is NULL


gluster-server volume config:
volume isifa1-posix
    type storage/posix
    option directory /mnt/data/isifa1
end-volume

volume isifa1-access-control
    type features/access-control
    subvolumes isifa1-posix
end-volume

volume isifa1-locks
    type features/locks
    subvolumes isifa1-access-control
end-volume

volume isifa1-io-threads
    type performance/io-threads
    subvolumes isifa1-locks
end-volume

volume isifa1-marker
    type features/marker
    option volume-uuid 39d5c509-ad39-4b24-a272-c33e212cf912
    option timestamp-file /etc/glusterd/vols/isifa1/marker.tstamp
    option xtime off
    option quota off
    subvolumes isifa1-io-threads
end-volume

volume /mnt/data/isifa1
    type debug/io-stats
    option latency-measurement off
    option count-fop-hits off
    subvolumes isifa1-marker
end-volume

volume isifa1-server
    type protocol/server
    option transport-type tcp
    option auth.addr./mnt/data/isifa1.allow 81.0.225.120,81.0.225.121,81.0.225.90,81.0.225.117,81.0.225.118,82.208.17.113
    subvolumes /mnt/data/isifa1
end-volume

gluster-fuse config:
volume isifa1-client-0
    type protocol/client
    option remote-host isifa-data1
    option remote-subvolume /mnt/data/isifa1
    option transport-type tcp
end-volume

volume isifa1-client-1
    type protocol/client
    option remote-host isifa-data2
    option remote-subvolume /mnt/data/isifa1
    option transport-type tcp
end-volume

volume isifa1-replicate-0
    type cluster/replicate
    subvolumes isifa1-client-0 isifa1-client-1
end-volume

volume isifa1-write-behind
    type performance/write-behind
    subvolumes isifa1-replicate-0
end-volume

volume isifa1-read-ahead
    type performance/read-ahead
    subvolumes isifa1-write-behind
end-volume

volume isifa1-io-cache
    type performance/io-cache
    subvolumes isifa1-read-ahead
end-volume

volume isifa1-quick-read
    type performance/quick-read
    subvolumes isifa1-io-cache
end-volume

volume isifa1-stat-prefetch
    type performance/stat-prefetch
    subvolumes isifa1-quick-read
end-volume

volume isifa1
    type debug/io-stats
    option latency-measurement off
    option count-fop-hits off
    subvolumes isifa1-stat-prefetch
end-volume


-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://supercolony.gluster.org/pipermail/gluster-users/attachments/20110613/62729d01/attachment.html>

More information about the Gluster-users mailing list