[Gluster-users] [page.c:168:ra_fault_cbk] readahead: wasted copy:

Thu Oct 22 21:29:39 UTC 2009

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