stale nfs file handle with exported loopback mounts

DISCUSSION [email protected] 2 participants 3 messages Nov 2, 2007

Subsystems (2)

NFS client NFS server

lore

Share & tools

lore

[email protected]

author

2007-11-02 19:06 UTC #0 lore raw

hi!

it seems i was having weird mail problems with sending mails trough my webm= ailer - at least two followups with attachments seem to be lost on sending = and are not in my sent folder anymore....

anyway - here is a second try, but probably worse than what i have written = before :)

first off, thanks for the patch Neil, things look _much_ better now and exp= orting loopback mounts now basiscally works again.
nice to see that my posting helped finding bugs.

maybe i have two more bugs for you :)

i have loopback mounts on the server and exported the parent dir with cross= mnt option.

after mounting for the first time on the client, i`m getting "Invalid argum= ent" for each loopback-mounted dir, if i do an ls -la on /mnt. this only happens _once_ and seems to be a server problem, because i can re= boot the client and remount , i never see that errors again.

besides that, all seems to work fine.

as neil suggested, i have made a tcpdump of this available at:
http://82.141.46.148/bugs/nfs/tcpdump.out.bz2

furthermore, there is a very strange performance issue i was able to track = down to uuid/blkid support.

i recognized this issue when i exported a directory containing a very large=
number of loopback mounts via crossmnt export option.
ls -la on the clients mountpoint seemed to hung and i could see mountd bein= g busy, eating 100% cpu for quite a while.

the time needed for ls to finish seems to grow exponentially with the numbe= r of loopback-mounts inside the exported directory - i also tried with 1000=
loopback mounts and mountd being busy for several minutes with this.

i have made a strace of mountd available at:
http://82.141.46.148/bugs/nfs/mountd.strace.txt.bz2

you can see that mountd seems to be busy doing the same things over and ove= r again, looks that it does stat64() for all devices in /etc/blkid.tab for = each loopback mount, weird.

here is some "strace -c -p $PID_OF_MOUNTD" for comparison - without uuid/b= lkid support compiled in it looks like this:

% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------

 73.23    0.147722           2     66313           stat64
 10.37    0.020923          20      1031           write
  5.54    0.011179          23       494           select
  3.82    0.007699           5      1546           read
  3.04    0.006137           8       773           time
  2.18    0.004393           6       769           lstat64
  1.08    0.002182           4       519           munmap
  0.40    0.000797           1      1035           close
  0.29    0.000594           1      1034           open
  0.04    0.000089           0      1036           fstat64
  0.00    0.000000           0         2           alarm
  0.00    0.000000           0         3           _llseek
  0.00    0.000000           0         1           fdatasync
  0.00    0.000000           0         2           poll
  0.00    0.000000           0         2           rt_sigaction
  0.00    0.000000           0       521           mmap2
  0.00    0.000000           0         2           fcntl64
  0.00    0.000000           0         1           socket
  0.00    0.000000           0         1           connect
  0.00    0.000000           0         1           accept
  0.00    0.000000           0         2           send

------ ----------- ----------- --------- --------- ----------------
100.00 0.201715 75088 total

this is an strace -c when uuid/blkid support is being compiled in:

% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------

 61.64    1.008158           2    550916           stat64
 21.67    0.354441           9     37662           read
  5.65    0.092476          15      6377           getdents64
  4.06    0.066381           3     21395      8232 open
  1.62    0.026485           2     13169           fstat64
  1.36    0.022237           2     13164           close
  1.22    0.020025           2      8414           lstat64
  1.15    0.018805           4      4415           munmap
  0.27    0.004382          17       258           rename
  0.26    0.004329          17       258           unlink
  0.26    0.004305           2      2101           write
  0.23    0.003786           1      4380           fcntl64
  0.18    0.002899          11       262           select
  0.18    0.002883          11       258           access
  0.11    0.001857           0      4417           mmap2
  0.11    0.001765           0      4652           time
  0.01    0.000237           1       258           link
  0.00    0.000041           0       258           lseek
  0.00    0.000000           0         2           alarm
  0.00    0.000000           0         2           brk
  0.00    0.000000           0         1           gettimeofday
  0.00    0.000000           0       258           fchmod
  0.00    0.000000           0       265           _llseek
  0.00    0.000000           0         1           fdatasync
  0.00    0.000000           0         2           poll
  0.00    0.000000           0         1           prctl
  0.00    0.000000           0         2           rt_sigaction
  0.00    0.000000           0         1           getuid32
  0.00    0.000000           0         1           getgid32
  0.00    0.000000           0         1           geteuid32
  0.00    0.000000           0         1           getegid32
  0.00    0.000000           0         1           futex
  0.00    0.000000           0         1           socket
  0.00    0.000000           0         1           connect
  0.00    0.000000           0         1           accept
  0.00    0.000000           0         2           send

------ ----------- ----------- --------- --------- ----------------
100.00 1.635492 673158 8232 total

as you can see there is an unusual high number of stat64() calls

server is opensuse 10.3 , client is suse 9.3 professional

if i can help resolving this issue, tell me what to do :)

regards
roland

Quoted 64 lines

-----Urspr=FCngliche Nachricht-----
Von: Neil Brown <[email protected]>
Gesendet: 01.11.07 05:26:50
An: [email protected]
CC: "J. Bruce Fields" <[email protected]>, [email protected]
Betreff: Re: [NFS] stale nfs file handle with exported loopback mounts
=
Quoted 7 lines · On Wednesday October 31, [email protected] wrote:
ok, i just wanted to tell that this isn`t the right way to go imho. =
some time ago i have tested exporting a parent dir containing several loopback mounted iso images with some pre-1.1.0 nfs-utils version and it worked - so =EC wonder why it now seems to have issues as things should have gone stable..... =
=
We have a way of breaking things sometimes.... It's called "progress". :-)
=
The short answer is that there is a bug in mountd which is fixed by this patch:
=
utils/mountd/cache.c +1 -1
index ce1a5a9..fd317cd 100644
@@ -508,7 +508,7 @@ void nfsd_fh(FILE *f)
 	 */
 	qword_printint(f, 0x7fffffff);
 	if (found)
-		qword_print(f, found->e_path);
+		qword_print(f, found_path);
 	qword_eol(f);
  out:
 	free(found_path);
=
=
The longer answer is that there is also a bug in "mount.nfs" which is unrelated but was slowing me down in chasing this bug, and there is also a bug in the NFS client which was causing my client oops and need a reboot every time I triggered this bug in mountd, which further slowed me down.
=
The effect of this bug in mountd is that when the NFS client calls GETATTR on the root of the subordinate filesystem (e.g. your loop-mounted isos), it got attr information about the parent. ie. the top-level exported filesystem (/export in your case I think). This has a different 'fsid' than the nfs client was expecting and the NFS client got confused in various ways.
=
Thanks for your problem report - it helped find 3 bugs! =

Quoted 6 lines

I'll get proper patches or bug report off to the relevant maintainers shortly.
=
NeilBrown
=

_____________________________________________________________________
Der WEB.DE SmartSurfer hilft bis zu 70% Ihrer Onlinekosten zu sparen!
http://smartsurfer.web.de/?mc=3D100071&distributionid=3D000000000066

-------------------------------------------------------------------------
This SF.net email is sponsored by: Splunk Inc.
Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
_______________________________________________
NFS maillist - [email protected]
https://lists.sourceforge.net/lists/listinfo/nfs

J. Bruce Fields

2007-11-02 19:23 UTC #1 lore raw

Quoted 10 lines · On Fri, Nov 02, 2007 at 08:06:58PM +0100, [email protected] wrote:

hi!
it seems i was having weird mail problems with sending mails trough my webmailer - at least two followups with attachments seem to be lost on sending and are not in my sent folder anymore....
anyway - here is a second try, but probably worse than what i have written before :)
first off, thanks for the patch Neil, things look _much_ better now and exporting loopback mounts now basiscally works again. nice to see that my posting helped finding bugs.

Quoted 8 lines

maybe i have two more bugs for you :)
i have loopback mounts on the server and exported the parent dir with crossmnt option.
after mounting for the first time on the client, i`m getting "Invalid argument" for each loopback-mounted dir, if i do an ls -la on /mnt. this only happens _once_ and seems to be a server problem, because i can reboot the client and remount , i never see that errors again.
From a quick look at the trace (thanks)--there's some getacl calls that

return EINVAL, then a few milliseconds later a second reply returns with the original data. That looks suspiciously like a reply being sent when the request was also deferred pending the upcall to deal with the newly encountered filesystem. Sure enough, in fs/nfs/nfs3acl.c:nfsd3_proc_getacl(), there's

	 if ((nfserr = fh_verify(rqstp, &resp->fh, 0, MAY_NOP)))
		RETURN_STATUS(nfserr_inval);

Change that nfserr_inval to an nfserr (here and in fs/nfs/nfs2acl.c:nfsd_proc_getacl()), and maybe the problem will go away.

--b.

J. Bruce Fields

2007-11-02 19:24 UTC #2 lore raw

Quoted 25 lines · J. Bruce Fields

Quoted 10 lines · On Fri, Nov 02, 2007 at 08:06:58PM +0100, [email protected] wrote:
hi!
it seems i was having weird mail problems with sending mails trough my webmailer - at least two followups with attachments seem to be lost on sending and are not in my sent folder anymore....
anyway - here is a second try, but probably worse than what i have written before :)
first off, thanks for the patch Neil, things look _much_ better now and exporting loopback mounts now basiscally works again. nice to see that my posting helped finding bugs.
Quoted 8 lines
maybe i have two more bugs for you :)
i have loopback mounts on the server and exported the parent dir with crossmnt option.
after mounting for the first time on the client, i`m getting "Invalid argument" for each loopback-mounted dir, if i do an ls -la on /mnt. this only happens _once_ and seems to be a server problem, because i can reboot the client and remount , i never see that errors again.
From a quick look at the trace (thanks)--there's some getacl calls that
return EINVAL, then a few milliseconds later a second reply returns with the original data. That looks suspiciously like a reply being sent when the request was also deferred pending the upcall to deal with the newly encountered filesystem. Sure enough, in fs/nfs/nfs3acl.c:nfsd3_proc_getacl(), there's

Quoted 6 lines

	 if ((nfserr = fh_verify(rqstp, &resp->fh, 0, MAY_NOP)))
		RETURN_STATUS(nfserr_inval);
Change that nfserr_inval to an nfserr (here and in fs/nfs/nfs2acl.c:nfsd_proc_getacl()), and maybe the problem will go away.

(I've been seeing some odd spurious replayed replies in the nfsv4 case as well, by the way--I suspect it's a similar problem, but haven't had the chance to track it down yet....)

--b.