NFS lockups with 2.4.18
Subsystems (2)
Hello All-
We're running into some NFS lockups here and having a rough time debugging/solving the issue. I'm hoping that someone on the list may be able to provide some suggestions.
Background:
Unpredictably, but approximately every week or two, we run into a problem where our file server stops responding to NFS requests. The server is Debian 3.0 (woody), running the 2.4.18-1-686 stock debian kernel. Have also seen the same problem with the debian bf2.4 kernel. Server is a single 2.6GHz P4 processor, >1GB RAM, with several large (>500GB) SCSI-160 arrays using ext3 filesystems, quotas enabled.
The problem only seems to be resolvable with a reboot, and even then, the problem will often reoccur within a few minutes, requiring another reboot (1-5 times), before finally settling down and being stable for 1-14+ days.
We have not noticed anything strange/interesting in any of the logs or on the console. All other services/processes on the machine continue to operate perfectly, including disk operations. The machine simply stops serving NFS.
We serve NFS to Linux, Solaris, and HP clients, several versions of each OS.
Some Relevant Data (from when NFS was not working properly):
$ rpcinfo -p
program vers proto port
100000 2 tcp 111 portmapper
100000 2 udp 111 portmapper
100029 1 udp 845 keyserv
100029 2 udp 845 keyserv
100011 1 udp 852 rquotad
100011 2 udp 852 rquotad
100011 1 tcp 855 rquotad
100011 2 tcp 855 rquotad
100024 1 udp 32772 status
100024 1 tcp 32768 status
100001 1 udp 32773 rstatd
100001 2 udp 32773 rstatd
100001 3 udp 32773 rstatd
100001 4 udp 32773 rstatd
100001 5 udp 32773 rstatd
100003 2 udp 2049 nfs
100003 3 udp 2049 nfs
100021 1 udp 32774 nlockmgr
100021 3 udp 32774 nlockmgr
100021 4 udp 32774 nlockmgr
100005 1 udp 32775 mountd
100005 1 tcp 32769 mountd
100005 2 udp 32775 mountd
100005 2 tcp 32769 mountd
100005 3 udp 32775 mountd
100005 3 tcp 32769 mountd$ rpcinfo [-u | -t] <host> <program>
portmapper udp
program 100000 version 2 ready and waiting portmapper tcp
program 100000 version 2 ready and waiting
keyserv
program 100029 version 1 ready and waiting program 100029 version 2 ready and waiting
rquotad udp
program 100011 version 1 ready and waiting program 100011 version 2 ready and waiting rquotad tcp
program 100011 version 1 ready and waiting program 100011 version 2 ready and waiting
status udp
program 100024 version 1 ready and waiting status tcp
program 100024 version 1 ready and waiting
rstatd udp
program 100001 version 1 ready and waiting program 100001 version 2 ready and waiting program 100001 version 3 ready and waiting program 100001 version 4 is not available program 100001 version 5 ready and waiting
nfs udp
program 100003 version 0 is not available
nlockmgr udp
program 100021 version 0 is not available
mountd udp
program 100005 version 0 is not available mountd tcp
program 100005 version 0 is not available
(normal output, as expected, is as follows) nfs udp
program 100003 version 2 ready and waiting program 100003 version 3 ready and waiting
nlockmgr udp
program 100021 version 1 ready and waiting program 100021 version 2 is not available program 100021 version 3 ready and waiting program 100021 version 4 ready and waiting
mountd udp
program 100005 version 1 ready and waiting program 100005 version 2 ready and waiting program 100005 version 3 ready and waiting mountd tcp
program 100005 version 1 ready and waiting program 100005 version 2 ready and waiting program 100005 version 3 ready and waiting
All nfsd processes (32) are still in process list, but the number of swapped processes reported by vmstat jumps from 2 to 33, right around the occurrence of the problem. The rpc.mountd, rpc.rquotad, and rpc.statd processes are also still in the process list along with the 32 nfsd instances. Don't see anything unusual in any of the other system stats - memory, cpu, and disk usage all remain steady. Memory utilization graphs during the problem period appear flatter than is typical, but not much change in values from normal operation.
Does anyone have any ideas about the problem? I'll be sure to grab some nfsstat and better ps output next time this happens, but any other suggestions for better logging or any other relevant data collection? Have there been any fixes since 2.4.18 that address similar or related problems?
Thanks for any help with this elusive problem.
-Stephan
Signature · 13 lines
Stephan B Koledin Network Systems Developer http://neolinear.com/ ------------------------------------------------------- This sf.net email is sponsored by:ThinkGeek Welcome to geek heaven. http://thinkgeek.com/sf _______________________________________________ NFS maillist - [email protected] https://lists.sourceforge.net/lists/listinfo/nfs
We ran into an NFS lockup again this morning. It continued for approximately 1.5 hours, then cleared up (after a number of consecutive reboots) and nfs worked perfectly again.
I managed to collect some more data, in the hopes that someone might have some suggestions.
A process list shows that the lockd and all 32 nfsd processes are in the D state (uninterruptible sleep). lockd is stuck at a WCHAN of 'down'. Also, 31 of the nfsd processes have lost the 'super-user' process flag and are now marked 040 instead of the normal 140. The first nfsd and lockd are still 140.
Interestingly, a process snapshot from a period when nfs was still running, but shortly before it died, shows the nfsd processes in a normal 'S' state, but they have all lost their super-user process flag. The lockd is already in a 'D' state. Not sure if it really means much, but does seem strange.
nfsstat doesn't seem to show anything out of the ordinary, but maybe someone here will see something relevant.
Once again, thanks for any help you can provide.
-Stephan
a relevant excerpt from a ps -elfjHm during the lockup:
F S UID PID PPID WCHAN STIME TIME CMD 140 D root 337 1 ? 07:36 00:00:00 [nfsd] 140 D root 338 1 down 07:36 00:00:00 [lockd] 040 S root 339 338 ? 07:36 00:00:00 [rpciod] 040 D root 340 1 ? 07:36 00:00:00 [nfsd] 040 D root 341 1 ? 07:36 00:00:00 [nfsd] 040 D root 342 1 ? 07:36 00:00:00 [nfsd] 040 D root 343 1 ? 07:36 00:00:00 [nfsd] 040 D root 344 1 ? 07:36 00:00:00 [nfsd] 040 D root 345 1 ? 07:36 00:00:00 [nfsd] 040 D root 346 1 ? 07:36 00:00:00 [nfsd] 040 D root 347 1 ? 07:36 00:00:00 [nfsd] 040 D root 348 1 ? 07:36 00:00:00 [nfsd] 040 D root 349 1 ? 07:36 00:00:00 [nfsd] 040 D root 350 1 ? 07:36 00:00:00 [nfsd] 040 D root 351 1 ? 07:36 00:00:00 [nfsd] 040 D root 352 1 ? 07:36 00:00:00 [nfsd] 040 D root 353 1 ? 07:36 00:00:00 [nfsd] 040 D root 354 1 ? 07:36 00:00:00 [nfsd] 040 D root 355 1 ? 07:36 00:00:00 [nfsd] 040 D root 356 1 ? 07:36 00:00:00 [nfsd] 040 D root 357 1 ? 07:36 00:00:00 [nfsd] 040 D root 358 1 ? 07:36 00:00:00 [nfsd] 040 D root 359 1 ? 07:36 00:00:00 [nfsd] 040 D root 360 1 ? 07:36 00:00:00 [nfsd] 040 D root 361 1 ? 07:36 00:00:00 [nfsd] 040 D root 362 1 ? 07:36 00:00:00 [nfsd] 040 D root 363 1 ? 07:36 00:00:00 [nfsd] 040 D root 364 1 ? 07:36 00:00:00 [nfsd] 040 D root 365 1 ? 07:36 00:00:00 [nfsd] 040 D root 366 1 ? 07:36 00:00:00 [nfsd] 040 D root 367 1 ? 07:36 00:00:00 [nfsd] 040 D root 368 1 ? 07:36 00:00:00 [nfsd] 040 D root 369 1 ? 07:36 00:00:00 [nfsd] 040 D root 370 1 ? 07:36 00:00:00 [nfsd] 140 S root 373 1 ? 07:36 00:00:00 /usr/sbin/rpc.mountd
an excerpt from a ps -elfjHm between lockups:
F S UID PID PPID WCHAN STIME TIME CMD 140 S root 327 1 ? 07:57 00:00:00 [nfsd] 140 D root 328 1 down 07:57 00:00:00 [lockd] 040 S root 329 328 ? 07:57 00:00:00 [rpciod] 040 S root 330 1 ? 07:57 00:00:00 [nfsd] 040 S root 331 1 ? 07:57 00:00:00 [nfsd] 040 S root 332 1 ? 07:57 00:00:00 [nfsd] ... 040 S root 359 1 ? 07:57 00:00:00 [nfsd] 040 S root 360 1 ? 07:57 00:00:00 [nfsd] 140 S root 363 1 poll 07:57 00:00:00 /usr/sbin/rpc.mountd
nfsstat -s during lockup:
Server rpc stats:
calls badcalls badauth badclnt xdrcall 67445 0 0 0 0
Server nfs v2:
null getattr setattr root lookup readlink
8 0% 50557 77% 668 1% 0 0% 9828 15% 4 0%
read wrcache write create remove rename
1762 2% 0 0% 1434 2% 184 0% 6 0% 168 0%
link symlink mkdir rmdir readdir fsstat
0 0% 0 0% 19 0% 0 0% 675 1% 9 0%
Server nfs v3:
null getattr setattr lookup access readlink
69 3% 342 16% 0 0% 108 5% 1601 75% 0 0%
read write create mkdir symlink mknod
0 0% 0 0% 0 0% 0 0% 0 0% 0 0%
remove rmdir rename link readdir readdirplus
0 0% 0 0% 0 0% 0 0% 3 0% 0 0%
fsstat fsinfo pathconf commit
0 0% 0 0% 0 0% 0 0%
nfsstat -s during normal operation:
Server rpc stats:
calls badcalls badauth badclnt xdrcall 8781107 4384 4384 0 0
Server nfs v2:
null getattr setattr root lookup readlink
3845 0% 6360155 82% 30228 0% 0 0% 643234 8% 30581 0%
read wrcache write create remove rename
298134 3% 0 0% 212600 2% 5476 0% 5240 0% 801 0%
link symlink mkdir rmdir readdir fsstat
11 0% 12 0% 336 0% 349 0% 75643 0% 5488 0%
Server nfs v3:
null getattr setattr lookup access readlink
6481 0% 942506 84% 0 0% 81868 7% 64802 5% 1119 0%
read write create mkdir symlink mknod
9091 0% 0 0% 0 0% 0 0% 0 0% 0 0%
remove rmdir rename link readdir readdirplus
0 0% 0 0% 0 0% 0 0% 1673 0% 0 0%
fsstat fsinfo pathconf commit
717 0% 717 0% 0 0% 0 0%
Signature · 13 lines
Stephan B Koledin Network Systems Developer http://neolinear.com/ ------------------------------------------------------- This sf.net email is sponsored by:ThinkGeek Welcome to geek heaven. http://thinkgeek.com/sf _______________________________________________ NFS maillist - [email protected] https://lists.sourceforge.net/lists/listinfo/nfs
Some more observations on this issue...
I've noticed that lockd appears to be the culprit. It is the first process to get stuck in a 'D' state. Eventually, all the nfsd processes follow it, apparently one at a time.
I think I've narrowed the cause down to some questionable SETLK calls from Solaris 8 clients. The suspect 3rd party app is a bit complex, however, so still trying to isolate the exact triggering sequence of events.
In the process of trying to dig up some clues, I ran into a similar problem reported on the lkml (http://lkml.org/lkml/2003/1/29/59). From private correspondence with the submitter, he is still encountering problems, and continues to experiment with the 2.4.2x series and NFS patches in hope of relief. It may not be the exact same problem, but it is very similar.
If anyone has any ideas about this problem, please let me know. I certainly don't mind trying a more recent kernel, but hate to just dive in blindly hoping for a fix that may not be there... Any debugging suggestions?
Thanks.
-Stephan
Signature · 13 lines
Stephan B Koledin Network Systems Developer http://neolinear.com/ ------------------------------------------------------- This sf.net email is sponsored by:ThinkGeek Welcome to geek heaven. http://thinkgeek.com/sf _______________________________________________ NFS maillist - [email protected] https://lists.sourceforge.net/lists/listinfo/nfs
Hello all.
I think we're finally making some progress with our problem. We've isolated the application and the system calls causing the lockups and I performed a bunch of testing today to try and define the causes of the lockups a little better. The recent 2.4.22 kernel from debian testing is affected the same as all other kernels we tried. I suppose I could be missing a more recent patch that fixes things - if so, please let me know.
Here is what we've found out:
- The problem is triggered by a distributed build process running on multiple Solaris 8 machines. The Sun compiler that we're using issues F_SETLKW calls to manage it's lock files during the build process. Since the build is distributed across a number of machines, we are seeing SETLKW attempts on the same file from several machines at the same time.
- We now have some code (attached) and various scripts to reproduce the problem. It requires some coordination of requests from multiple machines, but is easily reproducible, given a proper environment. I can currently trigger the lockup within a couple seconds, even on a machine with a substantial number of nfsd processes running.
- I am unable to reproduce the problem with Linux clients. Only Solaris clients appear able to lock up the NFS server, even using the exact same test code and methodology.
- lockd enters a "D" state, with a WCHAN of "down" when multiple machines try to get a write lock (using F_SETLKW) on the same file(s). There must be at least two machines attempting to lock the same file, and the total number of processes/machines either with locks or waiting for any locks must be approximately 3-5x the number of nfsd processes. It really looks like it's triggered when there are 4x outstanding locks or lock requests, but it's a bit difficult to track given the distributed nature of the problem.
- For example, if I'm running 4 nfsd processes, the problem is triggered with around 16 lock requests from different machines. When running a more typical setup of 32 nfsd, triggering the problem requires a substantial amount of computing resources. We do see the problem with less than 128 machines requesting locks, but we cannot reproduce the problem with only one or two machines.
- Once lockd enters a "D" state, the nfsd processes also begin hitting a "D" state, and no more NFS requests are possible, even ones that do not require locking.
Now that the problem is easily reproducible, I would love to test any suggested solutions/patches. I wish I was more familiar with the lockd/nfs code, but unfortunately I don't have much kernel coding experience. Please let me know if there's anything else I can do (or data I can provide) to help get to the bottom of this issue.
Thanks in advance for any help with this problem, although it does seems like a rare issue, it is causing us a great deal of pain in our environment.
-Stephan
Signature · 3 lines
Stephan B Koledin Network Systems Developer http://neolinear.com/
/*
* To compile run: gcc lock.c
* or: cc lock.c
*
* To lock a file run: a.out <filename>
*
*/
#include <stdio.h>
#include <fcntl.h>
#include <unistd.h>
#include <errno.h>
extern int errno;
extern char *getenv();
static locking_debug_p()
{
return (getenv("LOCKING_DEBUG") != NULL);
}__lock_file(filename)
char *filename;
{
int o_flags;
int fd;
struct flock lockstruct;
o_flags = O_RDWR|O_CREAT|O_TRUNC;
errno = 0;
/* Open the file */
if ((fd = open(filename, o_flags, 0666)) == -1) {
fprintf(stderr, "error opening");
}
lockstruct.l_type = F_WRLCK;
lockstruct.l_whence = SEEK_SET;
lockstruct.l_start = 0L;
lockstruct.l_len = 0L;
/* Try and set the lock */
if (fcntl(fd, F_SETLKW, &lockstruct) == -1) {
fprintf(stderr, "error Locking");
}
return fd;
}__unlock_file(locknum)
int locknum;
{
struct flock lockstruct;
if (locking_debug_p())
fprintf(stderr, "Unlocking fd %d ...\n", locknum);
errno = 0;
lockstruct.l_type = F_UNLCK;
lockstruct.l_whence = SEEK_SET;
lockstruct.l_start = 0L;
lockstruct.l_len = 0L;
if ((fcntl(locknum, F_SETLKW, &lockstruct)) == -1) {
fprintf(stderr, "error unlocking ");
}
if ((close(locknum)) == -1) {
fprintf(stderr, "error closing ");
}
return 0;
}void print_usage(const char* progname)
{
printf("\nUsage:\n %s <file_to_lock> \n", progname);
printf(" where <file_to_lock> is the name of an existing file\n");
}main(argc, argv)
int argc;
char **argv;
{
int result;
/* Did the user specify the correct number of arguments? */
if (argc < 2) {
printf("Error: not enough arguments specified.\n");
print_usage(argv[0]);
exit(1);
}
if (argc > 2) {
printf("Warning: ignoring all arguments other than the first One.\n");
}
result = __lock_file(argv[1]);
printf("#");
fflush(stdout); /* We sleep here just to give enough time to start other competing
* lock attempts on other machines
*/
sleep(60);
result = __unlock_file(result);
printf("!");
exit(0);}