Christian Marnitz
2009-Oct-22 21:29 UTC
[Gluster-users] [page.c:168:ra_fault_cbk] readahead: wasted copy:
Hi, we have 8 storage-bricks (distributed, replicated) and 10 clients connected to it. 4 clients are Webservers and look the same files. We got an hang of the servers(no df, lsof, strace to the glusterfs show epoll(wait 3)) until we kill hard the glusterfs-process. On debug-level we found massive of these errors: --- [2009-10-22 12:02:31] N [client-protocol.c:5733:client_setvolume_cbk] remote8: Connected to 10.10.10.17:6997, attached to remote volume 'brick'. [2009-10-22 12:02:31] N [client-protocol.c:5733:client_setvolume_cbk] remote8: Connected to 10.10.10.17:6997, attached to remote volume 'brick'. [2009-10-22 12:02:31] N [client-protocol.c:5733:client_setvolume_cbk] remote2: Connected to 10.10.10.11:6997, attached to remote volume 'brick'. [2009-10-22 12:02:31] D [afr-self-heal-entry.c:2034:afr_sh_entry_lock_cbk] replicate2: locking inode of /system/BS/lighttpd on child 0 failed: Resource temporarily unavailable [2009-10-22 12:03:45] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 524288[+131072] file=0x7f16dc00d360 [2009-10-22 12:03:45] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 655360[+131072] file=0x7f16dc00d360 [2009-10-22 12:03:46] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 393216[+131072] file=0x7f16dc010a90 [2009-10-22 12:03:46] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 393216[+131072] file=0x7f16dc00e7f0 [2009-10-22 12:07:45] D [client-protocol.c:4913:client_lookup_cbk] remote7: LOOKUP 352981290/custom_editing.res.bin (/custom_editing.res.bin): inode number changed from 56009082 to 56008868 [2009-10-22 12:07:45] D [client-protocol.c:4913:client_lookup_cbk] remote8: LOOKUP 352981290/custom_editing.res.bin (/custom_editing.res.bin): inode number changed from 18891130 to 18890916 [2009-10-22 12:07:45] D [fuse-bridge.c:296:need_fresh_lookup] fuse-bridge: revalidate of /.res.bin failed (Stale NFS file handle) [2009-10-22 12:07:45] D [fuse-bridge.c:296:need_fresh_lookup] fuse-bridge: revalidate of /medias.bin failed (No such file or directory) [2009-10-22 12:07:45] D [client-protocol.c:4913:client_lookup_cbk] remote5: LOOKUP 448071307/navigation_access_2.bin (/store.bin): inode number changed from 44122884 to 44122451 [2009-10-22 12:07:45] D [client-protocol.c:4913:client_lookup_cbk] remote6: LOOKUP 448071307/navigation_access_2.bin (/store.bin): inode number changed from 19931912 to 19931479 [2009-10-22 12:07:45] D [fuse-bridge.c:296:need_fresh_lookup] fuse-bridge: revalidate of /store.bin failed (Stale NFS file handle) [2009-10-22 12:07:45] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 524288[+131072] file=0x685df0 [2009-10-22 12:07:45] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 655360[+131072] file=0x685df0 [2009-10-22 12:07:45] D [client-protocol.c:4913:client_lookup_cbk] remote7: LOOKUP 448071307/navigationdeu_deu_production_editing.xml.bin (/editing.xml.bin): inode number changed from 56008917 to 56008914 [2009-10-22 12:07:45] D [client-protocol.c:4913:client_lookup_cbk] remote8: LOOKUP 448071307/navigationdeu_deu_production_editing.xml.bin (/editing.xml.bin): inode number changed from 18890965 to 18890962 [2009-10-22 12:07:45] D [fuse-bridge.c:296:need_fresh_lookup] fuse-bridge: revalidate of /editing.xml.bin failed (Stale NFS file handle) [2009-10-22 12:07:45] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 393216[+131072] file=0x7f16d4010b90 [2009-10-22 12:07:45] D [client-protocol.c:4913:client_lookup_cbk] remote1: LOOKUP 448071307/editing.xml.bin (/editing.xml.bin): inode number changed from 52986060 to 52986007 [2009-10-22 12:07:45] D [client-protocol.c:4913:client_lookup_cbk] remote2: LOOKUP 448071307/editing.xml.bin (/editing.xml.bin): inode number changed from 66445516 to 66445463 [2009-10-22 12:07:45] D [fuse-bridge.c:296:need_fresh_lookup] fuse-bridge: revalidate of /editing.xml.bin failed (Stale NFS file handle) [2009-10-22 12:07:45] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 393216[+131072] file=0x7f16dc016600 [2009-10-22 12:10:45] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 524288[+131072] file=0x7f16d4016810 [2009-10-22 12:10:45] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 655360[+131072] file=0x7f16d4016810 [2009-10-22 12:10:45] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 393216[+131072] file=0x7f16dc01c520 [2009-10-22 12:13:07] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 262144[+131072] file=0x7f16dc0235f0 [2009-10-22 12:13:07] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 262144[+131072] file=0x7f16dc0235f0 [2009-10-22 12:13:11] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 393216[+131072] file=0x7f16dc03d750 [2009-10-22 12:13:55] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 262144[+131072] file=0x7f16dc03c110 [2009-10-22 12:13:55] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 262144[+131072] file=0x7f16dc03b750 [2009-10-22 12:14:05] D [client-protocol.c:4913:client_lookup_cbk] remote5: LOOKUP 448071307/navigation_access_2.bin (/store.bin): inode number changed from 44122451 to 44122531 [2009-10-22 12:14:05] D [client-protocol.c:4913:client_lookup_cbk] remote6: LOOKUP 448071307/navigation_access_2.bin (/store.bin): inode number changed from 19931479 to 19931559 [2009-10-22 12:14:05] D [fuse-bridge.c:296:need_fresh_lookup] fuse-bridge: revalidate of /store.bin failed (Stale NFS file handle) [2009-10-22 12:14:05] D [inode.c:572:__inode_replace] fuse/inode: inode(352980250) replaced (352980250 [2009-10-22 12:14:05] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 524288[+131072] file=0x7f16dc03bd30 [2009-10-22 12:14:05] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 655360[+131072] file=0x7f16dc03bd30 [2009-10-22 12:14:05] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 393216[+131072] file=0x7f16dc03c110 [2009-10-22 12:14:05] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 393216[+131072] file=0x7f16dc03c110 [2009-10-22 12:14:05] D [inode.c:572:__inode_replace] fuse/inode: inode(352980250) replaced (352980250 [2009-10-22 12:14:05] D [inode.c:572:__inode_replace] fuse/inode: inode(200674897) replaced (200674897 [2009-10-22 12:14:25] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 393216[+131072] file=0x699580 [2009-10-22 12:14:25] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 393216[+131072] file=0x69b7f0 [2009-10-22 12:14:25] D [inode.c:572:__inode_replace] fuse/inode: inode(352980250) replaced (352980250 [2009-10-22 12:14:38] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 393216[+131072] file=0x7f16dc039120 [2009-10-22 12:14:38] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 524288[+131072] file=0x7f16dc039120 [2009-10-22 12:14:38] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 655360[+131072] file=0x7f16dc039120 [2009-10-22 12:14:38] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 393216[+131072] file=0x69ae20 [2009-10-22 12:14:38] D [inode.c:572:__inode_replace] fuse/inode: inode(352980250) replaced (352980250 [2009-10-22 12:14:39] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 262144[+131072] file=0x7f16dc03e560 [2009-10-22 12:14:39] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 262144[+131072] file=0x7f16dc0398a0 [2009-10-22 12:14:58] D [client-protocol.c:4913:client_lookup_cbk] remote6: LOOKUP 448071307/navigation_access_2.bin (/store.bin): inode number changed from 19931559 to 19931903 [2009-10-22 12:14:58] D [client-protocol.c:4913:client_lookup_cbk] remote5: LOOKUP 448071307/navigation_access_2.bin (/store.bin): inode number changed from 44122531 to 44122875 --- AND --- 2009-10-22 21:27:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 393216[+131072] file=0x7f16dc3285b0 [2009-10-22 21:28:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 524288[+131072] file=0x7f16d43d8f90 [2009-10-22 21:28:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 655360[+131072] file=0x7f16d43d8f90 [2009-10-22 21:28:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 393216[+131072] file=0x7f16d43d8f90 [2009-10-22 21:29:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 524288[+131072] file=0x7f16d43d8f90 [2009-10-22 21:29:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 655360[+131072] file=0x7f16d43d8f90 [2009-10-22 21:29:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 393216[+131072] file=0x7f16dc32c150 [2009-10-22 21:30:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 524288[+131072] file=0x7f16dc32d230 [2009-10-22 21:30:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 655360[+131072] file=0x7f16dc32d230 [2009-10-22 21:30:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 393216[+131072] file=0x7f16dc32d350 [2009-10-22 21:30:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 393216[+131072] file=0x7f16dc32d350 [2009-10-22 21:31:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 524288[+131072] file=0x7f1368178050 [2009-10-22 21:31:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 655360[+131072] file=0x7f1368178050 [2009-10-22 21:31:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 393216[+131072] file=0x7f1368178050 [2009-10-22 21:31:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 393216[+131072] file=0x7f16d43db270 [2009-10-22 21:32:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 524288[+131072] file=0x7f16dc32f2d0 [2009-10-22 21:32:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 655360[+131072] file=0x7f16dc32f2d0 [2009-10-22 21:32:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 393216[+131072] file=0x7f16dc32f2d0 [2009-10-22 21:33:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 655360[+131072] file=0x7f16dc32fbd0 [2009-10-22 21:33:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 524288[+131072] file=0x7f16dc32fbd0 [2009-10-22 21:33:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 393216[+131072] file=0x7f16dc32fbd0 [2009-10-22 21:33:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 393216[+131072] file=0x7f16dc32fbd0 [2009-10-22 21:34:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 524288[+131072] file=0x7f16dc3305f0 [2009-10-22 21:34:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 655360[+131072] file=0x7f16dc3305f0 [2009-10-22 21:34:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 393216[+131072] file=0x7f16dc330950 [2009-10-22 21:34:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 393216[+131072] file=0x7f16dc330950 [2009-10-22 21:35:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 524288[+131072] file=0x77b7e0 [2009-10-22 21:35:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 655360[+131072] file=0x77b7e0 [2009-10-22 21:35:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 393216[+131072] file=0x7f16d43e10f0 [2009-10-22 21:36:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 524288[+131072] file=0x7f136817cf10 [2009-10-22 21:36:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 655360[+131072] file=0x7f136817cf10 [2009-10-22 21:36:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 393216[+131072] file=0x7f16d43e18d0 [2009-10-22 21:37:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 524288[+131072] file=0x7f16d43e3730 [2009-10-22 21:37:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 655360[+131072] file=0x7f16d43e3730 [2009-10-22 21:37:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 393216[+131072] file=0x7f16dc332c70 [2009-10-22 21:37:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 393216[+131072] file=0x7f16dc332c70 [2009-10-22 21:38:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 524288[+131072] file=0x7f16dc332c70 [2009-10-22 21:38:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 655360[+131072] file=0x7f16dc332c70 [2009-10-22 21:38:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 393216[+131072] file=0x7f16dc332c70 [2009-10-22 21:39:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 524288[+131072] file=0x7f136817f5a0 [2009-10-22 21:39:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 655360[+131072] file=0x7f136817f5a0 [2009-10-22 21:39:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 393216[+131072] file=0x7f136817f570 [2009-10-22 21:39:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 393216[+131072] file=0x7f136817f570 [2009-10-22 21:40:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 524288[+131072] file=0x7f16d43e82d0 [2009-10-22 21:40:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 655360[+131072] file=0x7f16d43e82d0 [2009-10-22 21:40:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 393216[+131072] file=0x7f16d43e83f0 [2009-10-22 21:41:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 524288[+131072] file=0x7f16dc336b70 [2009-10-22 21:41:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 655360[+131072] file=0x7f16dc336b70 [2009-10-22 21:41:21] D [page.c:168:ra_fault_cbk] readahead: wasted copy: 393216[+131072] file=0x7f16d43e8ab0 --- We use: ---- Version : glusterfs 2.0.8rc10 built on Oct 22 2009 12:02:20 git: v2.0.7-65-g4c31c11 Starting Time: 2009-10-22 12:02:31 Command line : glusterfs -f /etc/glusterfs/glusterfs-client-fast.vol /mnt/glusterfs/fast/st00008/ -l /var/log/glusterfs-fast.log -L DEBUG PID : 21739 System name : Linux Nodename : pm-web03 Kernel Release : 2.6.24-24-generic Hardware Identifier: x86_64 .... 119: ##### read-ahead - read aggregation 120: volume readahead 121: type performance/read-ahead 122: #option page-size 1048576 # 128kb is the default option 123: option page-count 4 # 2 is default option 124: option force-atime-update off # default is off 125: subvolumes wb 126: end-volume ---- Many thanks in advance and with best regards, Christian Marnitz