Jiri Lunacek
2011-Jun-13 08:48 UTC
[Gluster-users] Apache hung tasks still occur with glusterfs 3.2.1
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>
Justice London
2011-Jun-13 13:58 UTC
[Gluster-users] Apache hung tasks still occur with glusterfs 3.2.1
Disable io-cache and up the threads to 64 and your problems should
disappear. They did for me when I made both of these changes.
Justice London
From: gluster-users-bounces at gluster.org
[mailto:gluster-users-bounces at gluster.org] On Behalf Of Jiri Lunacek
Sent: Monday, June 13, 2011 1:49 AM
To: gluster-users at gluster.org
Subject: [Gluster-users] Apache hung tasks still occur with glusterfs 3.2.1
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(cli
ent3_1_fstat_cbk+0x2cb) [0x2aaaab1afa0b]
(-->/opt/glusterfs/3.2.1/lib64/glusterfs/3.2.1/xlator/cluster/replicate.so(a
fr_sh_data_fstat_cbk+0x17d) [0x2aaaab3e4c9d]
(-->/opt/glusterfs/3.2.1/lib64/glusterfs/3.2.1/xlator/cluster/replicate.so(a
fr_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(cli
ent3_1_fstat_cbk+0x2cb) [0x2aaaab1afa0b]
(-->/opt/glusterfs/3.2.1/lib64/glusterfs/3.2.1/xlator/cluster/replicate.so(a
fr_sh_data_fstat_cbk+0x17d) [0x2aaaab3e4c9d]
(-->/opt/glusterfs/3.2.1/lib64/glusterfs/3.2.1/xlator/cluster/replicate.so(a
fr_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.11
3
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/22c59b7d/attachment.html>
Anand Avati
2011-Jun-14 06:50 UTC
[Gluster-users] Apache hung tasks still occur with glusterfs 3.2.1
Can you get us the process state dump of the glusterfs client where httpd is hung? kill -USR1 <glusterfs pid> will generate /tmp/glusterdump.pid which is the dumpfile. Avati On Mon, Jun 13, 2011 at 2:18 PM, Jiri Lunacek <jiri.lunacek at hosting90.cz>wrote:> 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 > > > > _______________________________________________ > Gluster-users mailing list > Gluster-users at gluster.org > http://gluster.org/cgi-bin/mailman/listinfo/gluster-users > >-------------- next part -------------- An HTML attachment was scrubbed... URL: <http://supercolony.gluster.org/pipermail/gluster-users/attachments/20110614/415ca30a/attachment.html>