* Linux client cache corruption, system call returning incorrectly @ 2007-03-02 3:15 Eli Stair 2007-03-02 13:45 ` Talpey, Thomas 0 siblings, 1 reply; 6+ messages in thread From: Eli Stair @ 2007-03-02 3:15 UTC (permalink / raw) To: nfs 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 - NFS@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/nfs ^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Linux client cache corruption, system call returning incorrectly 2007-03-02 3:15 Linux client cache corruption, system call returning incorrectly Eli Stair @ 2007-03-02 13:45 ` Talpey, Thomas 2007-03-02 21:58 ` Eli Stair 0 siblings, 1 reply; 6+ messages in thread From: Talpey, Thomas @ 2007-03-02 13:45 UTC (permalink / raw) To: Eli Stair; +Cc: nfs 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. At 10:15 PM 3/1/2007, Eli Stair wrote: > >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 - NFS@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/nfs ^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Linux client cache corruption, system call returning incorrectly 2007-03-02 13:45 ` Talpey, Thomas @ 2007-03-02 21:58 ` Eli Stair 2007-03-02 23:19 ` Talpey, Thomas 0 siblings, 1 reply; 6+ messages in thread From: Eli Stair @ 2007-03-02 21:58 UTC (permalink / raw) To: Talpey, Thomas; +Cc: nfs 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. > 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 Talpey, Thomas wrote: > 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. > > At 10:15 PM 3/1/2007, Eli Stair wrote: > > > >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 - NFS@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/nfs ^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Linux client cache corruption, system call returning incorrectly 2007-03-02 21:58 ` Eli Stair @ 2007-03-02 23:19 ` Talpey, Thomas 2007-03-03 15:52 ` Talpey, Thomas 0 siblings, 1 reply; 6+ messages in thread From: Talpey, Thomas @ 2007-03-02 23:19 UTC (permalink / raw) To: Eli Stair; +Cc: nfs :-) 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. At 04:58 PM 3/2/2007, Eli Stair wrote: > >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. > >> 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 > > > > > >Talpey, Thomas wrote: >> 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. >> >> At 10:15 PM 3/1/2007, Eli Stair wrote: >> > >> >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 - NFS@lists.sourceforge.net >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 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 - NFS@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/nfs ^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Linux client cache corruption, system call returning incorrectly 2007-03-02 23:19 ` Talpey, Thomas @ 2007-03-03 15:52 ` Talpey, Thomas 2007-03-27 19:21 ` Eli Stair 0 siblings, 1 reply; 6+ messages in thread From: Talpey, Thomas @ 2007-03-03 15:52 UTC (permalink / raw) To: Eli Stair; +Cc: nfs 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. At 06:19 PM 3/2/2007, Talpey, Thomas wrote: >:-) 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. > >At 04:58 PM 3/2/2007, Eli Stair wrote: >> >>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. >> >>> 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 >> >> >> >> >> >>Talpey, Thomas wrote: >>> 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. >>> >>> At 10:15 PM 3/1/2007, Eli Stair wrote: >>> > >>> >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 - NFS@lists.sourceforge.net >>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 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 - NFS@lists.sourceforge.net >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 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 - NFS@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/nfs ^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Linux client cache corruption, system call returning incorrectly 2007-03-03 15:52 ` Talpey, Thomas @ 2007-03-27 19:21 ` Eli Stair 0 siblings, 0 replies; 6+ messages in thread From: Eli Stair @ 2007-03-27 19:21 UTC (permalink / raw) To: nfs; +Cc: Talpey, Thomas 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): > 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'): > 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: > 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: > 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 Talpey, Thomas wrote: > 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. > > At 06:19 PM 3/2/2007, Talpey, Thomas wrote: >> :-) 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. >> >> At 04:58 PM 3/2/2007, Eli Stair wrote: >>> >>> 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. >>> >>>> 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 >>> >>> >>> >>> >>> >>> Talpey, Thomas wrote: >>>> 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. >>>> >>>> At 10:15 PM 3/1/2007, Eli Stair wrote: >>>>> >>>>> 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 >>> > <http://www.techsay.com/default.php?page=join.php&p=sourceforge&CID=DEVDEV> > >>> _______________________________________________ NFS maillist - >>> NFS@lists.sourceforge.net >>> 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 > 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 >> > <http://www.techsay.com/default.php?page=join.php&p=sourceforge&CID=DEVDEV> > >> _______________________________________________ NFS maillist - >> NFS@lists.sourceforge.net >> 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 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 - NFS@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/nfs ^ permalink raw reply [flat|nested] 6+ messages in thread
end of thread, other threads:[~2007-03-27 19:21 UTC | newest] Thread overview: 6+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 2007-03-02 3:15 Linux client cache corruption, system call returning incorrectly Eli Stair 2007-03-02 13:45 ` Talpey, Thomas 2007-03-02 21:58 ` Eli Stair 2007-03-02 23:19 ` Talpey, Thomas 2007-03-03 15:52 ` Talpey, Thomas 2007-03-27 19:21 ` Eli Stair
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.