"Server not responding" after periods of client inactivity
Subsystems (2)
(Trying to post this for the fourth time -- nothing appeared on the list the first three times.)
I have noticed that after periods of inactivity on the client machine, the first NFS operation will always hang for around 15 seconds. My first guess was that the server had powered down its disk drives, and that it was the spin-up time that caused the delay, but when I had an ssh session open on the server at the same time as the client started complaining about not getting a reply, I saw that this was /not/ the case -- there is nothing on the server that would explain why the client is stalling. No load, and no delay when working directly on the server.
I did tcpdump (on the server side) while the client was hanging, and this is what I found:
Source Time Packets ------ ---- ------- client 0.00 V3 ACCESS Call, FH:0x02120000 client 0.10 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 0.31 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 0.71 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 1.53 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 3.16 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 6.42 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 7.12 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 8.52 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 11.32 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 server 15.30 V3 ACCESS Reply
After this, there are no more delays for this shared file system; any file operation on the same file system will succeed instantly. However, the first operation on any /other/ NFS file system also mounted on the client will still hang just like the above example. I.e., the hang always happens exactly once for each mount point.
I have tried setting rsize=1024,wsize=1024, and I have tried both tcp and udp, but nothing has helped so far. Any ideas? tcpdump clearly shows that all the requests arrive at the server, so why does the server wait 15 seconds before it replies?
NFS server:
Pentium III 650 MHz, 256 MB RAM
Fedora Core 3 (fully updated)
nfs-utils 1.0.6-52
kernel 2.6.11-1.35_FC3
NFS client:
Athlon XP2500+, 1 GB RAM
Slackware 10.1
nfs-utils 1.0.7
kernel 2.6.11.11
Signature · 11 lines
Haakon ------------------------------------------------------- SF.Net email is sponsored by: Discover Easy Linux Migration Strategies from IBM. Find simple to follow Roadmaps, straightforward articles, informative Webcasts and more! Get everything you need to get up to speed, fast. http://ads.osdn.com/?ad_id=7477&alloc_id=16492&op=click _______________________________________________ NFS maillist - [email protected] https://lists.sourceforge.net/lists/listinfo/nfs
(Replying to my own email, since I still haven't seen any comments. The full original email is included below, since it's been a while since I posted it.)
I have now tried this with another NFS client (Fedora Core 4) connected to the NFS server simultaneously with client used in the below problem report. The same problem happens on the new client as well, even when the other client has just experienced the hang.
That is, after the stalled NFS operation completes on client A, it is still possible to observe the same problem on client B. It looks to me like this is caused by the server disconnecting idle clients, and when a new request suddenly occurs, it takes a while before the server manages to resurrect the connection. I tried adding a cron job that does 'ls -l /NFS-MOUNT-POINT >/dev/null' every few minutes, but surprisingly, that didn't keep the the connection alive. Is this because of client side caching? Is there anything I can do? These hangs are getting very annoying; it would be great if I could somehow change the idle timeout.
Quoted 49 lines
I have noticed that after periods of inactivity on the client machine, the first NFS operation will always hang for around 15 seconds. My first guess was that the server had powered down its disk drives, and that it was the spin-up time that caused the delay, but when I had an ssh session open on the server at the same time as the client started complaining about not getting a reply, I saw that this was /not/ the case -- there is nothing on the server that would explain why the client is stalling. No load, and no delay when working directly on the server.
I did tcpdump (on the server side) while the client was hanging, and this is what I found:
Source Time Packets ------ ---- ------- client 0.00 V3 ACCESS Call, FH:0x02120000 client 0.10 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 0.31 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 0.71 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 1.53 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 3.16 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 6.42 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 7.12 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 8.52 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 11.32 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 server 15.30 V3 ACCESS ReplyAfter this, there are no more delays for this shared file system; any file operation on the same file system will succeed instantly. However, the first operation on any /other/ NFS file system also mounted on the client will still hang just like the above example. I.e., the hang always happens exactly once for each mount point.
I have tried setting rsize=1024,wsize=1024, and I have tried both tcp and udp, but nothing has helped so far. Any ideas? tcpdump clearly shows that all the requests arrive at the server, so why does the server wait 15 seconds before it replies?
NFS server:
Pentium III 650 MHz, 256 MB RAM
Fedora Core 3 (fully updated)
nfs-utils 1.0.6-52
kernel 2.6.11-1.35_FC3NFS client:
Athlon XP2500+, 1 GB RAM
Slackware 10.1
nfs-utils 1.0.7
kernel 2.6.11.11
Signature · 11 lines
Haakon ------------------------------------------------------- SF.Net email is sponsored by: Discover Easy Linux Migration Strategies from IBM. Find simple to follow Roadmaps, straightforward articles, informative Webcasts and more! Get everything you need to get up to speed, fast. http://ads.osdn.com/?ad_id=7477&alloc_id=16492&op=click _______________________________________________ NFS maillist - [email protected] https://lists.sourceforge.net/lists/listinfo/nfs
lau den 30.07.2005 Klokka 15:10 (+0200) skreiv Haakon Riiser:
Quoted 6 lines
I have now tried this with another NFS client (Fedora Core 4) connected to the NFS server simultaneously with client used in the below problem report. The same problem happens on the new client as well, even when the other client has just experienced the hang.
Quoted 10 lines
That is, after the stalled NFS operation completes on client A, it is still possible to observe the same problem on client B. It looks to me like this is caused by the server disconnecting idle clients, and when a new request suddenly occurs, it takes a while before the server manages to resurrect the connection. I tried adding a cron job that does 'ls -l /NFS-MOUNT-POINT >/dev/null' every few minutes, but surprisingly, that didn't keep the the connection alive. Is this because of client side caching? Is there anything I can do? These hangs are getting very annoying; it would be great if I could somehow change the idle timeout.
If the server drops the connection, then the client will wait 15 seconds before retrying. The reason for this is that client has to assume that the server is disconnecting due to congestion issues.
Note that if congestion really is an issue, your Linux server should normally send an error message to the effect of "too many open TCP sockets, consider increasing the number of nfsd threads" to your syslog. You can fiddle with RPC_REESTABLISH_TIMEOUT if you want to change the 15 second delay, but I wouldn't recommend this unless you are sure you know what you are doing. (FYI, the fixed timeout is, BTW, soon due to be replaced with an exponential backoff-based timeout.)
Otherwise, you should note that the client too will attempt to drop the connection after 5 minutes of idle activity on the socket. That should normally not lead to a 15 second wait, though.
If the client fails to disconnect the idle connection, then the server will do so after 6 minutes (i.e. ~ 1 minute after the client timeout should have occurred).
Cheers,
Trond
-------------------------------------------------------
SF.Net email is sponsored by: Discover Easy Linux Migration Strategies from IBM. Find simple to follow Roadmaps, straightforward articles, informative Webcasts and more! Get everything you need to get up to speed, fast. http://ads.osdn.com/?ad_id=7477&alloc_id=16492&op=click
_______________________________________________
NFS maillist - [email protected]
https://lists.sourceforge.net/lists/listinfo/nfs
Trond,
Quoted 6 lines
If the server drops the connection, then the client will wait 15 seconds before retrying. The reason for this is that client has to assume that the server is disconnecting due to congestion issues.
Note that if congestion really is an issue, your Linux server should normally send an error message to the effect of "too many open TCP sockets, consider increasing the number of nfsd threads" to your syslog.
Congestion is almost definitely not the case here, since the NFS server is located in my own home, and is typically only used by one client at a time. During these timeouts, it isn't doing anything. This is why I first thought that the problem was that the server disks had spun down to save power.
Btw, one thing I haven't tried yet is upgrading to NFSv4. Do you think that could help?
Quoted 11 lines
You can fiddle with
RPC_REESTABLISH_TIMEOUTif you want to change the 15 second delay, but I wouldn't recommend this unless you are sure you know what you are doing. (FYI, the fixed timeout is, BTW, soon due to be replaced with an exponential backoff-based timeout.)Otherwise, you should note that the client too will attempt to drop the connection after 5 minutes of idle activity on the socket. That should normally not lead to a 15 second wait, though.
If the client fails to disconnect the idle connection, then the server will do so after 6 minutes (i.e. ~ 1 minute after the client timeout should have occurred).
Hmm, what did you make of the result I got with tcpdump/Ethereal? (Reposted below for convenience.) It looks like the problem is on the server side.
Source Time Packets ------ ---- ------- client 0.00 V3 ACCESS Call, FH:0x02120000 client 0.10 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 0.31 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 0.71 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 1.53 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 3.16 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 6.42 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 7.12 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 8.52 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 11.32 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 server 15.30 V3 ACCESS Reply
Signature · 11 lines
Haakon ------------------------------------------------------- SF.Net email is sponsored by: Discover Easy Linux Migration Strategies from IBM. Find simple to follow Roadmaps, straightforward articles, informative Webcasts and more! Get everything you need to get up to speed, fast. http://ads.osdn.com/?ad_id=7477&alloc_id=16492&op=click _______________________________________________ NFS maillist - [email protected] https://lists.sourceforge.net/lists/listinfo/nfs
lau den 30.07.2005 Klokka 16:32 (+0200) skreiv Haakon Riiser:
Quoted 2 lines
Btw, one thing I haven't tried yet is upgrading to NFSv4. Do you think that could help?
Normally it shouldn't. Sockets are managed by the RPC code, not the NFS code. The only difference there is that the NFSv4 client has a "heartbeat" that pings the server every 30 seconds or so in order to tell the server it is still alive.
Quoted 16 lines
Quoted 11 lines
You can fiddle with
RPC_REESTABLISH_TIMEOUTif you want to change the 15 second delay, but I wouldn't recommend this unless you are sure you know what you are doing. (FYI, the fixed timeout is, BTW, soon due to be replaced with an exponential backoff-based timeout.)Otherwise, you should note that the client too will attempt to drop the connection after 5 minutes of idle activity on the socket. That should normally not lead to a 15 second wait, though.
If the client fails to disconnect the idle connection, then the server will do so after 6 minutes (i.e. ~ 1 minute after the client timeout should have occurred).Hmm, what did you make of the result I got with tcpdump/Ethereal? (Reposted below for convenience.) It looks like the problem is on the server side.
Quoted 13 lines
Source Time Packets ------ ---- ------- client 0.00 V3 ACCESS Call, FH:0x02120000 client 0.10 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 0.31 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 0.71 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 1.53 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 3.16 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 6.42 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 7.12 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 8.52 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 11.32 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 server 15.30 V3 ACCESS Reply
This is a different problem that has nothing to do with connecting. If the client can send RPC requests, then the connection has clearly been set up.
If I were you, I'd look into what "mountd" is up to on the server when this happens. The server will just silently drop packets if mountd is slow to authorise the client.
Cheers,
Trond
-------------------------------------------------------
SF.Net email is sponsored by: Discover Easy Linux Migration Strategies from IBM. Find simple to follow Roadmaps, straightforward articles, informative Webcasts and more! Get everything you need to get up to speed, fast. http://ads.osdn.com/?ad_id=7477&alloc_id=16492&op=click
_______________________________________________
NFS maillist - [email protected]
https://lists.sourceforge.net/lists/listinfo/nfs
Trond,
Quoted 14 lines
Quoted 5 lines
Source Time Packets ------ ---- ------- client 0.00 V3 ACCESS Call, FH:0x02120000 client 0.10 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 0.31 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000Quoted 8 lines
client 0.71 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 1.53 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 3.16 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 6.42 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 7.12 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 8.52 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 client 11.32 [Retransmission of #1] V3 ACCESS Call, FH:0x02120000 server 15.30 V3 ACCESS Reply
Quoted 7 lines
This is a different problem that has nothing to do with connecting. If the client can send RPC requests, then the connection has clearly been set up.
If I were you, I'd look into what "mountd" is up to on the server when this happens. The server will just silently drop packets if mountd is slow to authorise the client.
OK, I've been trying for some time to reproduce the bug while stracing mountd on the server, but it seems impossible to do it. If I do
strace -p $(pidof rpc.mountd)
the bug never occurs. If I try to start strace immediately after the hang begins, strace doesn't attach until the hang is over. That is, it takes approximately 15 seconds (the entire duration of the hang) before the
Process <PID> attached - interrupt to quit
message is displayed and anything else is printed by strace. Does this tell you anything?
Signature · 11 lines
Haakon ------------------------------------------------------- SF.Net email is Sponsored by the Better Software Conference & EXPO September 19-22, 2005 * San Francisco, CA * Development Lifecycle Practices Agile & Plan-Driven Development * Managing Projects & Teams * Testing & QA Security * Process Improvement & Measurement * http://www.sqe.com/bsce5sf _______________________________________________ NFS maillist - [email protected] https://lists.sourceforge.net/lists/listinfo/nfs
ty den 09.08.2005 Klokka 21:06 (+0200) skreiv Haakon Riiser:
Quoted 11 lines
OK, I've been trying for some time to reproduce the bug while stracing mountd on the server, but it seems impossible to do it. If I do
strace -p $(pidof rpc.mountd)the bug never occurs. If I try to start strace immediately after the hang begins, strace doesn't attach until the hang is over. That is, it takes approximately 15 seconds (the entire duration of the hang) before the
Quoted 4 lines
Process <PID> attached - interrupt to quit
message is displayed and anything else is printed by strace. Does this tell you anything?
Just means that the mountd process is stuck in a syscall. Have you tried getting a thread dump when it happens?
echo "t" > /proc/sysrq-trigger
on the server then scour through the 'dmesg' output until you find out where mountd is hiding.
Cheers,
Trond
-------------------------------------------------------
SF.Net email is Sponsored by the Better Software Conference & EXPO September 19-22, 2005 * San Francisco, CA * Development Lifecycle Practices Agile & Plan-Driven Development * Managing Projects & Teams * Testing & QA Security * Process Improvement & Measurement * http://www.sqe.com/bsce5sf
_______________________________________________
NFS maillist - [email protected]
https://lists.sourceforge.net/lists/listinfo/nfs
Trond,
Quoted 4 lines
Have you tried getting a thread dump when it happens?
echo "t" >/proc/sysrq-trigger
on the server then scour through the 'dmesg' output until you find out where mountd is hiding.
Haven't tried that yet, but I'll get right on it. (That is, in an hour or two, since that's about how long I have to wait before the bug occurs. :-)
Signature · 11 lines
Haakon ------------------------------------------------------- SF.Net email is Sponsored by the Better Software Conference & EXPO September 19-22, 2005 * San Francisco, CA * Development Lifecycle Practices Agile & Plan-Driven Development * Managing Projects & Teams * Testing & QA Security * Process Improvement & Measurement * http://www.sqe.com/bsce5sf _______________________________________________ NFS maillist - [email protected] https://lists.sourceforge.net/lists/listinfo/nfs
Trond,
Quoted 5 lines
Just means that the mountd process is stuck in a syscall. Have you tried getting a thread dump when it happens?
echo "t" >/proc/sysrq-trigger
on the server then scour through the 'dmesg' output until you find out where mountd is hiding.
Done. Unfortunately, I couldn't find a call trace for mountd, I only got this:
rpc.mountd R running 1880 2814 1 18906 (NOTLB)
When mountd isn't hanging, I do get a call trace. Also, I noticed that echo "t" > /proc/sysrq-trigger didn't return immediately while mountd was hanging. Normally, it returns almost instantaneously, but during the hang, it took a second or two. (Returned long before the hang was over, though.)
Btw, I saved the entire dmesg output, just in case. Let me know if you're interested, OK?
Signature · 11 lines
Haakon ------------------------------------------------------- SF.Net email is Sponsored by the Better Software Conference & EXPO September 19-22, 2005 * San Francisco, CA * Development Lifecycle Practices Agile & Plan-Driven Development * Managing Projects & Teams * Testing & QA Security * Process Improvement & Measurement * http://www.sqe.com/bsce5sf _______________________________________________ NFS maillist - [email protected] https://lists.sourceforge.net/lists/listinfo/nfs
ty den 09.08.2005 Klokka 22:32 (+0200) skreiv Haakon Riiser:
Quoted 4 lines
Done. Unfortunately, I couldn't find a call trace for mountd, I only got this:
rpc.mountd R running 1880 2814 1 18906 (NOTLB)
Makes sense. That means that rpc.mountd is hanging in userland. That would also explain why you can't immediately ptrace it.
It is worrying, though. rpc.mountd should almost always be in the kernel, waiting in select().
Did you compile this version of rpc.mountd yourself? If not, is there anything special/weird in your /etc/exports file that might cause the rpc.mountd parser to be screwing up?
Cheers,
Trond
-------------------------------------------------------
SF.Net email is Sponsored by the Better Software Conference & EXPO September 19-22, 2005 * San Francisco, CA * Development Lifecycle Practices Agile & Plan-Driven Development * Managing Projects & Teams * Testing & QA Security * Process Improvement & Measurement * http://www.sqe.com/bsce5sf
_______________________________________________
NFS maillist - [email protected]
https://lists.sourceforge.net/lists/listinfo/nfs
Trond,
Quoted 4 lines
Quoted 1 line
rpc.mountd R running 1880 2814 1 18906 (NOTLB)
Makes sense. That means that rpc.mountd is hanging in userland. That would also explain why you can't immediately ptrace it.
But shouldn't strace immediately attach, even if mountd is busy-waiting in userspace? E.g., if I create a program that loops forever, such as
for (;;) { }
I can still attach immediately, although nothing is printed since there are no system calls (I've verified this). How can a program running in userspace delay strace's initial attachment?
Quoted 6 lines
It is worrying, though. rpc.mountd should almost always be in the kernel, waiting in
select().Did you compile this version of rpc.mountd yourself? If not, is there anything special/weird in your
/etc/exportsfile that might cause the rpc.mountd parser to be screwing up?
No and no. I'm using Fedora Core 3's rpc.mountd (nfs-utils-1.0.6-52), and this is my /etc/exports:
/pub 10.0.0.4(rw,async,no_root_squash,no_subtree_check) /raid 10.0.0.4(rw,async,no_subtree_check) /pub 10.0.0.21(rw,async,no_root_squash,no_subtree_check) /raid 10.0.0.21(rw,async,no_subtree_check)
Shouldn't have any problems with this, right?
Signature · 11 lines
Haakon ------------------------------------------------------- SF.Net email is Sponsored by the Better Software Conference & EXPO September 19-22, 2005 * San Francisco, CA * Development Lifecycle Practices Agile & Plan-Driven Development * Managing Projects & Teams * Testing & QA Security * Process Improvement & Measurement * http://www.sqe.com/bsce5sf _______________________________________________ NFS maillist - [email protected] https://lists.sourceforge.net/lists/listinfo/nfs