* NFS lockups with 2.4.18
@ 2003-09-24 16:51 Stephan Koledin
2003-09-25 19:54 ` Stephan Koledin
0 siblings, 1 reply; 4+ messages in thread
From: Stephan Koledin @ 2003-09-24 16:51 UTC (permalink / raw)
To: nfs
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
--
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 - NFS@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/nfs
^ permalink raw reply [flat|nested] 4+ messages in thread* Re: NFS lockups with 2.4.18
2003-09-24 16:51 NFS lockups with 2.4.18 Stephan Koledin
@ 2003-09-25 19:54 ` Stephan Koledin
2003-09-26 15:47 ` Stephan Koledin
0 siblings, 1 reply; 4+ messages in thread
From: Stephan Koledin @ 2003-09-25 19:54 UTC (permalink / raw)
To: 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%
--
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 - NFS@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/nfs
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: NFS lockups with 2.4.18
2003-09-25 19:54 ` Stephan Koledin
@ 2003-09-26 15:47 ` Stephan Koledin
2003-09-30 23:08 ` Stephan Koledin
0 siblings, 1 reply; 4+ messages in thread
From: Stephan Koledin @ 2003-09-26 15:47 UTC (permalink / raw)
To: 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
--
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 - NFS@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/nfs
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: NFS lockups with 2.4.18
2003-09-26 15:47 ` Stephan Koledin
@ 2003-09-30 23:08 ` Stephan Koledin
0 siblings, 0 replies; 4+ messages in thread
From: Stephan Koledin @ 2003-09-30 23:08 UTC (permalink / raw)
To: nfs
[-- Attachment #1: Type: text/plain, Size: 3001 bytes --]
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
--
Stephan B Koledin
Network Systems Developer
http://neolinear.com/
[-- Attachment #2: setlkw.c --]
[-- Type: text/x-csrc, Size: 2043 bytes --]
/*
* 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);
}
^ permalink raw reply [flat|nested] 4+ messages in thread
end of thread, other threads:[~2003-09-30 23:08 UTC | newest]
Thread overview: 4+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2003-09-24 16:51 NFS lockups with 2.4.18 Stephan Koledin
2003-09-25 19:54 ` Stephan Koledin
2003-09-26 15:47 ` Stephan Koledin
2003-09-30 23:08 ` Stephan Koledin
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.