Linux client cache corruption, system call returning incorrectly

DISCUSSION Eli Stair 2 participants 6 messages Mar 2, 2007 – Mar 27, 2007

Subsystems (2)

NFS client NFS server

lore

Share & tools

lore

Eli Stair

author

2007-03-02 03:15 UTC #0 lore raw

I'm having a serious client cache issue on recent kernels. On 2.6.18 and 2.6.20 (but /not/ 2.6.15.4) clients I'm seeing periodic file GETATTR or ACCESS calls that return fine from the server pass an ENOFILE up to the application. It occurs against all NFS servers I've tested (2.6.18 knfsd, OnTap 10.0.1, SpinOS 2.5.5p8).

The triggering usage stage is repeated stat'ing of a several hundred files that are opened read-only (but not close() or open()'ing it again) during runtime. I have been unable to duplicate the usage into a bug-triggering testcase yet, but it is very easily triggered by an internal app. Mounting the NFS filesystems with 'nocto' appears to mitigate the issue by about 50%, but does not completely get rid of it.
Also, using 2.6.20+ Trond's NFS_ALL patches and this one you supplied
also slow the rate of errors, but not completely.

I'm rigging the application with an strace harness so I can track down specifically what ops are failing in production. I can confirm that those errors I have witnessed under debug are NOT failing due to an NFS call returning where access is denied, or on an open(), it appears to be stat() of the file (usually several dozen or hundreds in sequence) that return ENOFILE, though the call should return sucess.

Any tips on using rpcdebug effectively? I'm getting tremendous levels of info output with '-m nfs -s all', too much to parse well.

I'll update with some more hard data as I get further along, but want to see if a) anyone else has noticed this and working on a fix, and b) if there are any suggestions on getting more useful data than what I'm working towards.

Reverting to 2.6.15.4 (which doesn't exhibit this particular bug) isn't a direct solution even temporarily, as that has a nasty NFS fseek bug (seek to EOF goes to wrong offset).

Cheers,

/eli

-------------------------------------------------------------------------
Take Surveys. Earn Cash. Influence the Future of IT
Join SourceForge.net's Techsay panel and you'll get the chance to share your opinions on IT & business topics through brief surveys-and earn cash
http://www.techsay.com/default.php?page=join.php&p=sourceforge&CID=DEVDEV
_______________________________________________
NFS maillist - [email protected]
https://lists.sourceforge.net/lists/listinfo/nfs

Talpey, Thomas

2007-03-02 13:46 UTC #1 lore raw

Do you mean ENFILE? If so, what's your process's file descriptor limit (ulimit -n)? Since stat(2) doesn't open anything, in theory it shouldn't return this. fstat(2) takes a file descriptor but again, doesn't open anything.

I wouldn't recommend using rpcdebug, since this is probably a local issue. Rpcdebug will show over-the-wire stuff, mostly. Strace will probably be the best tool.

Tom.

Quoted 31 lines · Eli Stair

I'm having a serious client cache issue on recent kernels. On 2.6.18 and 2.6.20 (but /not/ 2.6.15.4) clients I'm seeing periodic file GETATTR or ACCESS calls that return fine from the server pass an ENOFILE up to the application. It occurs against all NFS servers I've tested (2.6.18 knfsd, OnTap 10.0.1, SpinOS 2.5.5p8).
The triggering usage stage is repeated stat'ing of a several hundred files that are opened read-only (but not close() or open()'ing it again) during runtime. I have been unable to duplicate the usage into a bug-triggering testcase yet, but it is very easily triggered by an internal app. Mounting the NFS filesystems with 'nocto' appears to mitigate the issue by about 50%, but does not completely get rid of it.
Also, using 2.6.20+ Trond's NFS_ALL patches and this one you supplied
also slow the rate of errors, but not completely.
I'm rigging the application with an strace harness so I can track down specifically what ops are failing in production. I can confirm that those errors I have witnessed under debug are NOT failing due to an NFS call returning where access is denied, or on an open(), it appears to be stat() of the file (usually several dozen or hundreds in sequence) that return ENOFILE, though the call should return sucess.
Any tips on using rpcdebug effectively? I'm getting tremendous levels of info output with '-m nfs -s all', too much to parse well.
I'll update with some more hard data as I get further along, but want to see if a) anyone else has noticed this and working on a fix, and b) if there are any suggestions on getting more useful data than what I'm working towards.

Quoted 8 lines

Reverting to 2.6.15.4 (which doesn't exhibit this particular bug) isn't a direct solution even temporarily, as that has a nasty NFS fseek bug (seek to EOF goes to wrong offset).
Cheers,
/eli

Eli Stair

author

2007-03-02 21:58 UTC #2 lore raw

Still working on getting more useful debug output (MANY-layered application run through a batch scheduler) from the system calls themselves. It doesn't look like the errors occur on stat() after all, but open().

The problem being an ENOENT that should NOT be occuring, as the file exists and is perfectly readable by other clients at the time of the open, as confirmed by the pcaps and other sequential successes. This is what I am considering real breakage of the client. Note that I've confirmed that this does not occur when accessing the same files over a local block device, only NFS. No locks are occuring, and the file is opened read-only, so there should be no contention or reason that I can see.

Here's an strace of operations across several clients opening the file at the same time, showing one succeed and one fail.

Quoted 7 lines

deathstar1071:/strace # cat RIB_OPENS.txt | grep "geom.55.rib" | grep -v stat shot1.estair.test3strace.pid.11296:open("/path/file/geom.55.rib", O_RDONLY) = -1 ENOENT (No such file or directory) shot1.estair.test3strace.pid.12115:open("/path/file/geom.55.rib", O_RDONLY) = 4
deathstar1071:/strace # ls -la path/file/geom.55.rib -rw-rw---- 1 uid gid 406206 Feb 22 11:58 /path/file/geom.55.rib

If this were a ulimit issue for the process, it would receive an ENFILE not the ENOENT right? It's looking like there's a disconnect in-kernel when system calls are occuring over NFS. Strangely, I left a test prog running over night just doing an open(), stat(), readc(), then close() of these same files for 5000+ iterations without reproducing the issue.
So it doesn't appear to be a library issue since the call itself is
returning improperly, but some usage/access pattern (above simple ops) is triggering it.

I never found what update/patch fixed the issue, but the 2.6.15 fseek() bug I tracked down similarly occured over NFS only. When performing a write into a file, then a seek and write at the head, 10%+ of the time a seek to EOF would return to the wrong byte offset. This is seeming as fatal but more obscure.

/eli

Quoted 5 lines · Thomas

Do you mean ENFILE? If so, what's your process's file descriptor limit (ulimit -n)? Since stat(2) doesn't open anything, in theory it shouldn't return this. fstat(2) takes a file descriptor but again, doesn't open anything.

Quoted 48 lines

I wouldn't recommend using rpcdebug, since this is probably a local issue. Rpcdebug will show over-the-wire stuff, mostly. Strace will probably be the best tool.
Tom.
Quoted 39 lines · Eli Stair
I'm having a serious client cache issue on recent kernels. On 2.6.18 and 2.6.20 (but /not/ 2.6.15.4) clients I'm seeing periodic file GETATTR or ACCESS calls that return fine from the server pass an ENOFILE up to the application. It occurs against all NFS servers I've tested (2.6.18 knfsd, OnTap 10.0.1, SpinOS 2.5.5p8).
The triggering usage stage is repeated stat'ing of a several hundred files that are opened read-only (but not close() or open()'ing it again) during runtime. I have been unable to duplicate the usage into a bug-triggering testcase yet, but it is very easily triggered by an internal app. Mounting the NFS filesystems with 'nocto' appears to mitigate the issue by about 50%, but does not completely get rid of it.
Also, using 2.6.20+ Trond's NFS_ALL patches and this one you supplied
also slow the rate of errors, but not completely.
I'm rigging the application with an strace harness so I can track down specifically what ops are failing in production. I can confirm that those errors I have witnessed under debug are NOT failing due to an NFS call returning where access is denied, or on an open(), it appears to be stat() of the file (usually several dozen or hundreds in sequence) that return ENOFILE, though the call should return sucess.
Any tips on using rpcdebug effectively? I'm getting tremendous levels of info output with '-m nfs -s all', too much to parse well.
I'll update with some more hard data as I get further along, but want to see if a) anyone else has noticed this and working on a fix, and b) if there are any suggestions on getting more useful data than what I'm working towards.
Reverting to 2.6.15.4 (which doesn't exhibit this particular bug) isn't a direct solution even temporarily, as that has a nasty NFS fseek bug (seek to EOF goes to wrong offset).
Cheers,
/eli

Talpey, Thomas

2007-03-02 23:19 UTC #3 lore raw

:-) your first message said ENOFILE, not ENOENT! So nevermind the ENFILE diagnostics.

What mount options are you using (cat /proc/mounts)? Also, are you building custom kernels? If they're from a distro, what is the uname -a output? Is there anything interesting in dmesg?

This does sound like a dnlc issue (directory name cache). But there are other possibilities. A soft mount with network errors, or a server/client time skew for example can affect caching.

Tom.

Quoted 106 lines · Eli Stair

Still working on getting more useful debug output (MANY-layered application run through a batch scheduler) from the system calls themselves. It doesn't look like the errors occur on stat() after all, but open().
The problem being an ENOENT that should NOT be occuring, as the file exists and is perfectly readable by other clients at the time of the open, as confirmed by the pcaps and other sequential successes. This is what I am considering real breakage of the client. Note that I've confirmed that this does not occur when accessing the same files over a local block device, only NFS. No locks are occuring, and the file is opened read-only, so there should be no contention or reason that I can see.
Here's an strace of operations across several clients opening the file at the same time, showing one succeed and one fail.
Quoted 1 line
deathstar1071:/strace # cat RIB_OPENS.txt | grep "geom.55.rib" |
grep -v stat
Quoted 1 line
shot1.estair.test3strace.pid.11296:open("/path/file/geom.55.rib",
O_RDONLY) = -1 ENOENT (No such file or directory)
Quoted 1 line
shot1.estair.test3strace.pid.12115:open("/path/file/geom.55.rib",
O_RDONLY) = 4
Quoted 3 lines
deathstar1071:/strace # ls -la path/file/geom.55.rib -rw-rw---- 1 uid gid 406206 Feb 22 11:58 /path/file/geom.55.rib
If this were a ulimit issue for the process, it would receive an ENFILE not the ENOENT right? It's looking like there's a disconnect in-kernel when system calls are occuring over NFS. Strangely, I left a test prog running over night just doing an open(), stat(), readc(), then close() of these same files for 5000+ iterations without reproducing the issue.
So it doesn't appear to be a library issue since the call itself is
returning improperly, but some usage/access pattern (above simple ops) is triggering it.
I never found what update/patch fixed the issue, but the 2.6.15 fseek() bug I tracked down similarly occured over NFS only. When performing a write into a file, then a seek and write at the head, 10%+ of the time a seek to EOF would return to the wrong byte offset. This is seeming as fatal but more obscure.
/eli
Quoted 5 lines · Thomas
Do you mean ENFILE? If so, what's your process's file descriptor limit (ulimit -n)? Since stat(2) doesn't open anything, in theory it shouldn't return this. fstat(2) takes a file descriptor but again, doesn't open anything.
Quoted 48 lines
I wouldn't recommend using rpcdebug, since this is probably a local issue. Rpcdebug will show over-the-wire stuff, mostly. Strace will probably be the best tool.
Tom.
Quoted 39 lines · Eli Stair
I'm having a serious client cache issue on recent kernels. On 2.6.18 and 2.6.20 (but /not/ 2.6.15.4) clients I'm seeing periodic file GETATTR or ACCESS calls that return fine from the server pass an ENOFILE up to the application. It occurs against all NFS servers I've tested (2.6.18 knfsd, OnTap 10.0.1, SpinOS 2.5.5p8).
The triggering usage stage is repeated stat'ing of a several hundred files that are opened read-only (but not close() or open()'ing it again) during runtime. I have been unable to duplicate the usage into a bug-triggering testcase yet, but it is very easily triggered by an internal app. Mounting the NFS filesystems with 'nocto' appears to mitigate the issue by about 50%, but does not completely get rid of it.
Also, using 2.6.20+ Trond's NFS_ALL patches and this one you supplied
also slow the rate of errors, but not completely.
I'm rigging the application with an strace harness so I can track down specifically what ops are failing in production. I can confirm that those errors I have witnessed under debug are NOT failing due to an NFS call returning where access is denied, or on an open(), it appears to be stat() of the file (usually several dozen or hundreds in sequence) that return ENOFILE, though the call should return sucess.
Any tips on using rpcdebug effectively? I'm getting tremendous levels of info output with '-m nfs -s all', too much to parse well.
I'll update with some more hard data as I get further along, but want to see if a) anyone else has noticed this and working on a fix, and b) if there are any suggestions on getting more useful data than what I'm working towards.
Reverting to 2.6.15.4 (which doesn't exhibit this particular bug) isn't a direct solution even temporarily, as that has a nasty NFS fseek bug (seek to EOF goes to wrong offset).
Cheers,
/eli

Quoted 8 lines

-------------------------------------------------------------------------
Take Surveys. Earn Cash. Influence the Future of IT
Join SourceForge.net's Techsay panel and you'll get the chance to share your opinions on IT & business topics through brief surveys-and earn cash
http://www.techsay.com/default.php?page=join.php&p=sourceforge&CID=DEVDEV
_______________________________________________
NFS maillist - [email protected]
https://lists.sourceforge.net/lists/listinfo/nfs

Talpey, Thomas

2007-03-03 15:53 UTC #4 lore raw

Say Eli, I have another question. Does this error occur mostly within specific directories, and if so are they really large? Perhaps you could do "ls -ld <dirname>" and "ls <dirname> | wc -l" if so? If possible, doing these from a shell on the server itself would be best (I know this won't work for Ontap of course).

I'm jumping ahead, but if my suspicion is correct then the problem would be coming from NFSv3 readdirplus on a huge number of files, evicting other active entries in the client's cache. It's not easy to turn this behavior off, but a quick test would be to use an NFSv2 mount, which would have other ramifications (e.g. lots more rpc's on the wire due to 8KB size) but would help narrow things down.

All this assumes there isn't something obvious in the mount options, etc. Thanks for any info.

Tom.

Quoted 130 lines · Thomas

:-) your first message said ENOFILE, not ENOENT! So nevermind the ENFILE diagnostics.
What mount options are you using (cat /proc/mounts)? Also, are you building custom kernels? If they're from a distro, what is the uname -a output? Is there anything interesting in dmesg?
This does sound like a dnlc issue (directory name cache). But there are other possibilities. A soft mount with network errors, or a server/client time skew for example can affect caching.
Tom.
Quoted 106 lines · Eli Stair
Still working on getting more useful debug output (MANY-layered application run through a batch scheduler) from the system calls themselves. It doesn't look like the errors occur on stat() after all, but open().
The problem being an ENOENT that should NOT be occuring, as the file exists and is perfectly readable by other clients at the time of the open, as confirmed by the pcaps and other sequential successes. This is what I am considering real breakage of the client. Note that I've confirmed that this does not occur when accessing the same files over a local block device, only NFS. No locks are occuring, and the file is opened read-only, so there should be no contention or reason that I can see.
Here's an strace of operations across several clients opening the file at the same time, showing one succeed and one fail.
Quoted 1 line
deathstar1071:/strace # cat RIB_OPENS.txt | grep "geom.55.rib" |
grep -v stat
Quoted 1 line
shot1.estair.test3strace.pid.11296:open("/path/file/geom.55.rib",
O_RDONLY) = -1 ENOENT (No such file or directory)
Quoted 1 line
shot1.estair.test3strace.pid.12115:open("/path/file/geom.55.rib",
O_RDONLY) = 4
Quoted 3 lines
deathstar1071:/strace # ls -la path/file/geom.55.rib -rw-rw---- 1 uid gid 406206 Feb 22 11:58 /path/file/geom.55.rib
If this were a ulimit issue for the process, it would receive an ENFILE not the ENOENT right? It's looking like there's a disconnect in-kernel when system calls are occuring over NFS. Strangely, I left a test prog running over night just doing an open(), stat(), readc(), then close() of these same files for 5000+ iterations without reproducing the issue.
So it doesn't appear to be a library issue since the call itself is
returning improperly, but some usage/access pattern (above simple ops) is triggering it.
I never found what update/patch fixed the issue, but the 2.6.15 fseek() bug I tracked down similarly occured over NFS only. When performing a write into a file, then a seek and write at the head, 10%+ of the time a seek to EOF would return to the wrong byte offset. This is seeming as fatal but more obscure.
/eli
Quoted 5 lines · Thomas
Do you mean ENFILE? If so, what's your process's file descriptor limit (ulimit -n)? Since stat(2) doesn't open anything, in theory it shouldn't return this. fstat(2) takes a file descriptor but again, doesn't open anything.
Quoted 48 lines
I wouldn't recommend using rpcdebug, since this is probably a local issue. Rpcdebug will show over-the-wire stuff, mostly. Strace will probably be the best tool.
Tom.
Quoted 39 lines · Eli Stair
I'm having a serious client cache issue on recent kernels. On 2.6.18 and 2.6.20 (but /not/ 2.6.15.4) clients I'm seeing periodic file GETATTR or ACCESS calls that return fine from the server pass an ENOFILE up to the application. It occurs against all NFS servers I've tested (2.6.18 knfsd, OnTap 10.0.1, SpinOS 2.5.5p8).
The triggering usage stage is repeated stat'ing of a several hundred files that are opened read-only (but not close() or open()'ing it again) during runtime. I have been unable to duplicate the usage into a bug-triggering testcase yet, but it is very easily triggered by an internal app. Mounting the NFS filesystems with 'nocto' appears to mitigate the issue by about 50%, but does not completely get rid of it.
Also, using 2.6.20+ Trond's NFS_ALL patches and this one you supplied
also slow the rate of errors, but not completely.
I'm rigging the application with an strace harness so I can track down specifically what ops are failing in production. I can confirm that those errors I have witnessed under debug are NOT failing due to an NFS call returning where access is denied, or on an open(), it appears to be stat() of the file (usually several dozen or hundreds in sequence) that return ENOFILE, though the call should return sucess.
Any tips on using rpcdebug effectively? I'm getting tremendous levels of info output with '-m nfs -s all', too much to parse well.
I'll update with some more hard data as I get further along, but want to see if a) anyone else has noticed this and working on a fix, and b) if there are any suggestions on getting more useful data than what I'm working towards.
Reverting to 2.6.15.4 (which doesn't exhibit this particular bug) isn't a direct solution even temporarily, as that has a nasty NFS fseek bug (seek to EOF goes to wrong offset).
Cheers,
/eli
Quoted 8 lines
-------------------------------------------------------------------------
Take Surveys. Earn Cash. Influence the Future of IT
Join SourceForge.net's Techsay panel and you'll get the chance to share your opinions on IT & business topics through brief surveys-and earn cash
http://www.techsay.com/default.php?page=join.php&p=sourceforge&CID=DEVDEV
_______________________________________________
NFS maillist - [email protected]
https://lists.sourceforge.net/lists/listinfo/nfs

Quoted 8 lines

-------------------------------------------------------------------------
Take Surveys. Earn Cash. Influence the Future of IT
Join SourceForge.net's Techsay panel and you'll get the chance to share your opinions on IT & business topics through brief surveys-and earn cash
http://www.techsay.com/default.php?page=join.php&p=sourceforge&CID=DEVDEV
_______________________________________________
NFS maillist - [email protected]
https://lists.sourceforge.net/lists/listinfo/nfs

Eli Stair

author

2007-03-27 19:21 UTC #5 lore raw

I'm reporting back on this issue, and have found that this behaviour (bug) was introduced in kernel 2.6.17. All prior versions tested, 2.6.15 through 2.6.16.44, work fine. Starting in 2.6.17 this ENOENT (sorry for the type-o stating ENOFILE) error starts occuring, and is present then up to and including 2.6.21-rc4.

To follow up on some previous questions:

1) Kernels in use.
I'm using kernel.org sources. The patch from Neil Brown I mentioned I applied to 2.6.20 only, and it did not impact the bug we're discussing here. Trond's NFS_ALL, and CITI's current patchset for 2.6.20 don't rectify this either.

2) Client & Server details.
Mounts are set up as follows (endor is SpinFS 2.5.5.p9, hoth is GX OnTap 10.0.1p2). This same bug is occuring when accessing over either of these platforms, and additionally linux kernel 2.6.18.2.. It seems the syntax was altered beetween these two versions for version and protocol, and 'lock' was removed by default from 2.6.17 (these mounts occur using the same autofs), as specified below however, these options have been tried on several testcases and they still occur. Not sure yet why locking ceases to apply to the mounts starting at 2.6.17, or if this is an issue.

#2.6.17 (default):

Quoted 2 lines

endor:/san /net/san nfs rw,vers=3,rsize=8192,wsize=8192,hard,proto=udp,timeo=11,retrans=2,addr=endor hothshow:/san/show /san/show nfs rw,vers=3,rsize=32768,wsize=32768,hard,proto=tcp,timeo=600,retrans=2,addr=hothshow

#2.6.17 (specifying 'lock'):

Quoted 2 lines

endor:/san /net/san nfs rw,vers=3,rsize=8192,wsize=8192,hard,proto=udp,timeo=11,retrans=2,addr=endor hothshow:/san/show /san/show nfs rw,vers=3,rsize=32768,wsize=32768,hard,proto=tcp,timeo=600,retrans=2,addr=hothshow

#2.6.16.44:

Quoted 2 lines

endor:/san /net/san nfs rw,v3,rsize=8192,wsize=8192,hard,lock,proto=udp,addr=endor hothshow:/san/show /san/show nfs rw,v3,rsize=32768,wsize=32768,hard,lock,proto=tcp,addr=hothshow

Further, I've tried mounting with combinations of mount options which seem likely candidates for affecting this bug, but have had no statistically significant effect:

Quoted 1 line

noac sync sync,noac,nocto nolock nocto noac,nolock,nocto

I've also compiled and added mount.nfs from nfs-utils 1.0.11 into /sbin/mount.nfs, enabling automount to use the most recent userland tool in case there is something "known" that was patched at that level recently. No change from that in client behaviour.

3) Client usage pattern, file/dir structure.
In regards to the directory-contents/size question, they are not large. Directly within the directory being accessed are 300 regular files ~400K in size, and three directories each with the same number/size of files. Files are accessed primarily out of one of the subdirs from this point.

The most compelling piece of evidence I've tracked down so far (aside from the point where it was introduced) is that this bug appears to _only_ be triggered if there are two+ instances of the application running in memory acting on this directory. I've only run a few hundred more test cases, but forcing only one job per host has not triggered it even on the "bad" kernels. It appears (anecdotally) that jobs started a wildly different times (> 15 mins apart) don't seem to trigger it either. That would make sense if there's some client-side timeout on kernel-cached entries and the TTL is expiring by the time the second job gets to the same phase of operation on said directory/file entries.

---
I'll be moving forward with debugging this, but considering the major jump in code between 2.6.16.44 and 2.6.17, I will be "inefficient at best" in determining which patch/major restructuring in the kernel instigated this and fixing it. With most of the client nfs updates in 2.6.17 being in the rpc_iostats and O_DIRECT write areas, those seem unlikely to be the cause.

Unfortunately I have yet to trigger this artificially. Now that I know the trigger is a usage pattern of concurrent process accesses to a directory, I'll see if I can recreate the usage pattern more correctly after tracking the application/dir accesses with inotify/pcaps again.
If it's useful, I have correlated packet captures, strace logs, and
inotify output from the data operations. Unfortunately, all they do is confirm things are working properly on the wire and break at the system call level when the app opens files.

Let me know if after this feedback there's anything more I can provide directly. I know the most useful thing I can do is provide a synthetic unit test for this, which I'm working on.

I greatly appreciate the questions & help.

Thanks,

/eli

Quoted 191 lines · Thomas

Say Eli, I have another question. Does this error occur mostly within
specific directories, and if so are they really large? Perhaps you
could do "ls -ld <dirname>" and "ls <dirname> | wc -l" if so? If possible, doing these from a shell on the server itself would be best (I know this won't work for Ontap of course).
I'm jumping ahead, but if my suspicion is correct then the problem would be coming from NFSv3 readdirplus on a huge number of files, evicting other active entries in the client's cache. It's not easy to
turn this behavior off, but a quick test would be to use an NFSv2
mount, which would have other ramifications (e.g. lots more rpc's on the wire due to 8KB size) but would help narrow things down.
All this assumes there isn't something obvious in the mount options, etc. Thanks for any info.
Tom.
Quoted 7 lines · Thomas
:-) your first message said ENOFILE, not ENOENT! So nevermind the ENFILE diagnostics.
What mount options are you using (cat /proc/mounts)? Also, are you building custom kernels? If they're from a distro, what is the uname -a output? Is there anything interesting in dmesg?
Quoted 21 lines
This does sound like a dnlc issue (directory name cache). But there
are other possibilities. A soft mount with network errors, or a
server/client time skew for example can affect caching.
Tom.
Quoted 14 lines · Eli Stair
Still working on getting more useful debug output (MANY-layered application run through a batch scheduler) from the system calls themselves. It doesn't look like the errors occur on stat() after all, but open().
The problem being an ENOENT that should NOT be occuring, as the file exists and is perfectly readable by other clients at the time of the open, as confirmed by the pcaps and other sequential successes. This is what I am considering real breakage of the client. Note that I've confirmed that this does not occur when accessing the same files over a local block device, only NFS. No locks are occuring, and the file is opened read-only, so there should be no contention or reason that I
can see.
Quoted 41 lines
Quoted 41 lines
Here's an strace of operations across several clients opening the file at the same time, showing one succeed and one fail.
Quoted 2 lines
deathstar1071:/strace # cat RIB_OPENS.txt | grep
"geom.55.rib" |
grep -v stat
Quoted 2 lines
shot1.estair.test3strace.pid.11296:open("/path/file/geom.55.rib",
O_RDONLY) = -1 ENOENT (No such file or directory)
Quoted 2 lines
shot1.estair.test3strace.pid.12115:open("/path/file/geom.55.rib",
O_RDONLY) = 4
Quoted 3 lines
deathstar1071:/strace # ls -la path/file/geom.55.rib -rw-rw---- 1 uid gid 406206 Feb 22 11:58 /path/file/geom.55.rib
If this were a ulimit issue for the process, it would receive an ENFILE not the ENOENT right? It's looking like there's a disconnect in-kernel when system calls are occuring over NFS. Strangely, I left a test prog running over night just doing an open(), stat(), readc(), then close() of these same files for 5000+ iterations without reproducing the issue. So it doesn't appear to be a library issue since the call itself is returning improperly, but some usage/access pattern (above simple ops) is triggering it.
I never found what update/patch fixed the issue, but the 2.6.15 fseek() bug I tracked down similarly occured over NFS only. When performing a write into a file, then a seek and write at the head, 10%+ of the time a seek to EOF would return to the wrong byte offset. This is seeming as fatal but more obscure.
/eli
Quoted 4 lines
Quoted 4 lines
Quoted 3 lines · Thomas
Do you mean ENFILE? If so, what's your process's file descriptor limit (ulimit -n)? Since stat(2) doesn't open anything, in theory it
shouldn't
Quoted 7 lines
Quoted 7 lines
Quoted 7 lines
return this. fstat(2) takes a file descriptor but again, doesn't open anything.
I wouldn't recommend using rpcdebug, since this is probably a local issue. Rpcdebug will show over-the-wire stuff, mostly. Strace will probably be the best tool.
Quoted 7 lines
Quoted 7 lines
Quoted 7 lines
Tom.
Quoted 4 lines · Eli Stair
I'm having a serious client cache issue on recent kernels. On 2.6.18 and 2.6.20 (but /not/ 2.6.15.4) clients I'm seeing periodic file
GETATTR
Quoted 2 lines
Quoted 2 lines
Quoted 2 lines
Quoted 2 lines
or ACCESS calls that return fine from the server pass an ENOFILE
up to
Quoted 2 lines
Quoted 2 lines
Quoted 2 lines
Quoted 2 lines
the application. It occurs against all NFS servers I've tested
(2.6.18
Quoted 5 lines
Quoted 5 lines
Quoted 5 lines
Quoted 5 lines
knfsd, OnTap 10.0.1, SpinOS 2.5.5p8).
The triggering usage stage is repeated stat'ing of a several hundred files that are opened read-only (but not close() or open()'ing it
again)
Quoted 5 lines
Quoted 5 lines
Quoted 5 lines
Quoted 5 lines
during runtime. I have been unable to duplicate the usage into a bug-triggering testcase yet, but it is very easily triggered by an internal app. Mounting the NFS filesystems with 'nocto' appears to mitigate the issue by about 50%, but does not completely get rid
of it.
Quoted 2 lines
Quoted 2 lines
Quoted 2 lines
Quoted 2 lines
Also, using 2.6.20+ Trond's NFS_ALL patches and this one you
supplied
Quoted 4 lines
Quoted 4 lines
Quoted 4 lines
Quoted 4 lines
also slow the rate of errors, but not completely.
I'm rigging the application with an strace harness so I can track
down
Quoted 3 lines
Quoted 3 lines
Quoted 3 lines
Quoted 3 lines
specifically what ops are failing in production. I can confirm that those errors I have witnessed under debug are NOT failing due to
an NFS
Quoted 1 line
Quoted 1 line
Quoted 1 line
Quoted 1 line
call returning where access is denied, or on an open(), it
appears to be
Quoted 1 line
Quoted 1 line
Quoted 1 line
Quoted 1 line
stat() of the file (usually several dozen or hundreds in
sequence) that
Quoted 4 lines
Quoted 4 lines
Quoted 4 lines
Quoted 4 lines
return ENOFILE, though the call should return sucess.
Any tips on using rpcdebug effectively? I'm getting tremendous
levels
Quoted 4 lines
Quoted 4 lines
Quoted 4 lines
Quoted 4 lines
of info output with '-m nfs -s all', too much to parse well.
I'll update with some more hard data as I get further along, but
want to
Quoted 2 lines
Quoted 2 lines
Quoted 2 lines
Quoted 2 lines
see if a) anyone else has noticed this and working on a fix, and
b) if
Quoted 5 lines
Quoted 5 lines
Quoted 5 lines
Quoted 5 lines
there are any suggestions on getting more useful data than what I'm working towards.
Reverting to 2.6.15.4 (which doesn't exhibit this particular bug)
isn't
Quoted 6 lines
Quoted 6 lines
Quoted 6 lines
Quoted 6 lines
a direct solution even temporarily, as that has a nasty NFS fseek bug (seek to EOF goes to wrong offset).
Cheers,
Quoted 8 lines
Quoted 8 lines
Quoted 3 lines
Quoted 1 line
/eli
-------------------------------------------------------------------------
Take Surveys. Earn Cash. Influence the Future of IT Join
SourceForge.net's Techsay panel and you'll get the chance to
share your
Quoted 4 lines
Quoted 4 lines
opinions on IT & business topics through brief surveys-and earn cash
http://www.techsay.com/default.php?page=join.php&p=sourceforge&CID=DEVDEV
<http://www.techsay.com/default.php?page=join.php&p=sourceforge&CID=DEVDEV>
Quoted 8 lines
Quoted 3 lines
_______________________________________________ NFS maillist - [email protected]
https://lists.sourceforge.net/lists/listinfo/nfs
-------------------------------------------------------------------------
Take Surveys. Earn Cash. Influence the Future of IT Join
SourceForge.net's Techsay panel and you'll get the chance to

Quoted 12 lines

share your
Quoted 4 lines
opinions on IT & business topics through brief surveys-and earn cash
http://www.techsay.com/default.php?page=join.php&p=sourceforge&CID=DEVDEV
<http://www.techsay.com/default.php?page=join.php&p=sourceforge&CID=DEVDEV>
Quoted 3 lines
_______________________________________________ NFS maillist - [email protected]
https://lists.sourceforge.net/lists/listinfo/nfs