2
2
I have a Linux-based fileserver (ark) which exports a raid volume over nfs4.
Sometimes when doing large copy operations, it will time out.
[nathan@ebisu /mnt/extra/disk] rsync -a --progress . /mnt/raid/backup/backup.extra/disk
sending incremental file list
BSD.0/
BSD.0/BSD.0.vdi
411336704 12% 48.60MB/s 0:00:56
rsync: writefd_unbuffered failed to write 4 bytes to socket [sender]: Broken pipe (32)
rsync: write failed on "/mnt/raid/backup/backup.extra/disk/BSD.0/BSD.0.vdi": Input/output error (5)
rsync error: error in file IO (code 11) at receiver.c(322) [receiver=3.0.9]
rsync: connection unexpectedly closed (32 bytes received so far) [sender]
rsync error: error in rsync protocol data stream (code 12) at io.c(605) [sender=3.0.9]
I know that this is a timeout because dmesg tells me so:
[nathan@ebisu ~] dmesg | tail
[52722.138132] nfs: server ark not responding, timed out
[52722.138137] nfs: server ark not responding, timed out
[52722.138145] nfs: server ark not responding, timed out
[52722.138150] nfs: server ark not responding, timed out
[52722.138154] nfs: server ark not responding, timed out
In case you think this may be a bug just related to rsync, I tried doing a regular copy too:
[nathan@ebisu /mnt/extra/disk] cp BSD.0/BSD.0.vdi /mnt/raid/backup/backup.extra/disk
cp: error writing ‘/mnt/raid/backup/backup.extra/disk/BSD.0.vdi’: Input/output error
cp: failed to extend ‘/mnt/raid/backup/backup.extra/disk/BSD.0.vdi’: Input/output error
I don't even know where to begin to look to fix this problem. They are both connected via gigabit ethernet through a gigabit switch. I have used ethtool to validate that both are actually running at gigabit speeds. Most operations between the host and the server work fine; it's only in the middle of big transfers that it dies.
Nothing in the fileserver's dmesg stands out as being awkward.
[root@ark ~]# dmesg | tail
[ 7.088959] NFSD: Using /var/lib/nfs/v4recovery as the NFSv4 state recovery directory
[ 7.266363] NFSD: starting 90-second grace period (net ffffffff81880e80)
[ 8492.222871] type=1326 audit(1365926452.334:2): auid=4294967295 uid=99 gid=99 ses=4294967295 pid=336 comm="sshd" sig=31 syscall=48 compat=0 ip=0x7fe1be17edc7 code=0x0
[ 8492.314714] type=1326 audit(1365926452.424:3): auid=4294967295 uid=99 gid=99 ses=4294967295 pid=338 comm="sshd" sig=31 syscall=48 compat=0 ip=0x7fe30fd9ddc7 code=0x0
[ 8492.405336] type=1326 audit(1365926452.514:4): auid=4294967295 uid=99 gid=99 ses=4294967295 pid=340 comm="sshd" sig=31 syscall=48 compat=0 ip=0x7f6bb032ddc7 code=0x0
[ 8492.501048] type=1326 audit(1365926452.611:5): auid=4294967295 uid=99 gid=99 ses=4294967295 pid=342 comm="sshd" sig=31 syscall=48 compat=0 ip=0x7f81d7c2fdc7 code=0x0
[ 8492.603056] type=1326 audit(1365926452.714:6): auid=4294967295 uid=99 gid=99 ses=4294967295 pid=344 comm="sshd" sig=31 syscall=48 compat=0 ip=0x7f97c8bc9dc7 code=0x0
[ 8492.703732] type=1326 audit(1365926452.814:7): auid=4294967295 uid=99 gid=99 ses=4294967295 pid=346 comm="sshd" sig=31 syscall=48 compat=0 ip=0x7f0661b2fdc7 code=0x0
[ 8492.837977] type=1326 audit(1365926452.947:8): auid=4294967295 uid=99 gid=99 ses=4294967295 pid=348 comm="sshd" sig=31 syscall=48 compat=0 ip=0x7fd024f8cdc7 code=0x0
[54125.173195] type=1326 audit(1365972085.286:9): auid=4294967295 uid=99 gid=99 ses=4294967295 pid=353 comm="sshd" sig=31 syscall=48 compat=0 ip=0x7f390a6b9dc7 code=0x0
The syslog is similarly devoid of any issues.
Some more random diagnostic information I gathered:
[root@ebisu etc]# nfsstat -rc
Client rpc stats:
calls retrans authrefrsh
1057273 34163 1050608
That's a whole lot of retrans.
I checked to see if I was saturating my nfsd threads, but no, they were mostly idle.
Just for fun, I did a similar transfer completely locally, to see if I was hitting disk errors or slowness:
[root@ark ~]# rsync --progress test.img /mnt/bigraid/backup/backup.ark/
test.img
8589934592 100% 48.38MB/s 0:02:49 (xfer#1, to-check=0/1)
sent 8590983238 bytes received 31 bytes 50386998.65 bytes/sec
total size is 8589934592 speedup is 1.00
Looks like it hit a bit under 50MB/s, which is roughly the speed I was getting on the remote rsync.
I tried doing the transfer while running htop on the server, and I did notice that after a while it seems like nfsd may have requested more memory buffers. It may be memory related, as by modern standards the server is not a high-memory system. But it seems to me that this should just cause the transfer to go slower, not to time out entirely.
Anything in Ark's log file? Maybe it's a disk timeout. – Johnny – 2013-04-11T19:34:09.767
I am assuming these two are not connected using a cross-over cable but through some network switches and routers. I'd ask the network admins to put a sniffer to both sides of this connection and determine when and where this time out problem starts and what leads to that. Sounds too much like a networking gear not liking the the large amounts of data passing thru and dropping the connection to me. – MelBurslan – 2013-04-11T19:51:27.017
@Johnny Added to question as edit – Nathan – 2013-04-11T19:56:02.730
@Mel_Burslan I briefly described the network topology in the question. There is no "network admin" (or, more precisely, that would be me. This is my home network). I could do a tcpdump and grunge through it, though I doubt that would be helpful. I'll try to scrounge another gigabit switch from somewhere in case it's the switch that's flaking out. – Nathan – 2013-04-11T19:58:41.183
It seems to me like the problem may be actually with the network. When the logs are clean, just about a timeout error, it may be network robustness. Can you ping the nfs server from another terminal while copying and see if at any time the network seems to drop? – Bichoy – 2013-04-18T01:18:10.370
@Bichoy Good suggestion. I tried that and had 0% packet loss with an average time of .42 ms. I also tried Mel_Burslan's suggestion of replacing the switch, which didn't help. I don't think it's a network timeout. – Nathan – 2013-04-18T13:12:06.153
Can you try checking/adjusting the various limits listed in this article? http://nfs.sourceforge.net/nfs-howto/ar01s05.html
– Bichoy – 2013-04-18T17:44:58.400@Bichoy Block size: 16k. MTU: 1500. Exportfs uses the 'sync' option. Backing store is a raid5. I think that's all the tunables that article mentions. – Nathan – 2013-04-18T18:41:05.910