On 07/14/2017 01:51 AM, NeilBrown wrote:
Please try this (against a clean nfs-utils. i.e. remove the previous
patch).
It is a hack and would need to be totally re-written, but hopely the
measurements you make and strace that you report could be useful.
Also, for the strace, please use "-ttt" rather than "-tt" like I asked
before. It is easier to find the difference between two times with
-ttt. And add -T as well.
Sorry this took so long but I had to be sure of my results.
With your latest patch applied I am unable to mount my NFS shares and
thus continue with the tests from before.
Since the patch you provided cannot be applied cleanly to the source
used to build '1:1.2.8-9ubuntu12.1' for Ubuntu Xenial I chose to build a
couple of VMs to continue this testing. They should be identical to the
machines I was using before except they are under powered and not using
nfs-common, nfs-kernel-server package version 1:1.2.8-9ubuntu12.1. Most
importantly the zfs datasets and the files in /etc/exports.d are the same.
I found that utils/mountd/cache.c was last modified in 1.3.4, so I
tested both 1.3.4 and 2.1.1 without your patch as a baseline. I was able
to mount my shares in both versions.
I then reverted my VMs to a state before the baseline install and
installed again with your patch applied.
I get the following with your patch applied on 1.3.4 and 2.1.1:
root@nfsclient:~# mount -avv
/ : ignored
/boot : already mounted
none : ignored
mount.nfs4: timeout set for Tue Jul 25 15:43:13 2017
mount.nfs4: trying text-based options
'ac,hard,rsize=16384,wsize=16384,vers=4.2,addr=10.135.24.23,clientaddr=10.135.24.22'
mount.nfs4: mount(2): No such file or directory
mount.nfs4: trying text-based options
'ac,hard,rsize=16384,wsize=16384,addr=10.135.24.23'
mount.nfs4: prog 100003, trying vers=3, prot=6
mount.nfs4: trying 10.135.24.23 prog 100003 vers 3 prot TCP port 2049
mount.nfs4: prog 100005, trying vers=3, prot=17
mount.nfs4: trying 10.135.24.23 prog 100005 vers 3 prot UDP port 41598
mount.nfs4: mount(2): Permission denied
mount.nfs4: access denied by server while mounting
nfsserver.cs.uchicago.edu:/homes
mount.nfs4: timeout set for Tue Jul 25 15:43:14 2017
mount.nfs4: trying text-based options
'ac,hard,rsize=16384,wsize=16384,vers=4.2,addr=10.135.24.23,clientaddr=10.135.24.22'
mount.nfs4: mount(2): No such file or directory
mount.nfs4: trying text-based options
'ac,hard,rsize=16384,wsize=16384,addr=10.135.24.23'
mount.nfs4: prog 100003, trying vers=3, prot=6
mount.nfs4: trying 10.135.24.23 prog 100003 vers 3 prot TCP port 2049
mount.nfs4: prog 100005, trying vers=3, prot=17
mount.nfs4: trying 10.135.24.23 prog 100005 vers 3 prot UDP port 41598
mount.nfs4: mount(2): Permission denied
mount.nfs4: access denied by server while mounting
nfsserver.cs.uchicago.edu:/stage
Attached are my install notes and the strace during the failed mount above.
--
Phil Kauffman
Systems Admin
Dept. of Computer Science
University of Chicago
kauffman@xxxxxxxxxxxxxxx
# all
umask 022
apt-get build-dep nfs-kernel-server
apt-get install rpcbind strace
systemctl enable rpcbind
git clone git://git.linux-nfs.org/projects/steved/nfs-utils.git
cd nfs-utils
# choose the version to test
#git checkout tags/nfs-utils-1-3-4 -b 1.3.4
#git checkout tags/nfs-utils-2-1-1 -b 2.1.1
# if patching
wget http://people.cs.uchicago.edu/~kauffman/nfs-kernel-server/take3/nb2.patch
patch -p1 utils/mountd/cache.c < nb2.patch
rm nb2.patch
# Server
./autogen.sh && ./configure --with-systemd --disable-gss && make && make install
touch /etc/default/nfs-kernel-server /etc/default/nfs-common
mkdir -p /usr/libexec/nfs-utils
cp ../nfs-utils/debian/nfs-utils_env.sh /usr/libexec/nfs-utils/
touch /etc/exports && mkdir -p /etc/exports.d
systemctl enable nfs-server.service
systemctl enable nfs-utils.service
reboot
# client
./autogen.sh && ./configure --with-systemd --disable-gss && make && make install
touch /etc/default/nfs-common
chmod 644 /usr/lib/systemd/system/*
systemctl enable nfs-client.target
systemctl enable rpc-statd.service
reboot
root@nfsserver:~/nfs-utils# cat /etc/default/nfs-common
NEED_STATD=yes
STATDOPTS="--port 44634"
NEED_GSSD=
root@nfsserver:~/nfs-utils# cat /etc/default/nfs-kernel-server
RPCNFSDCOUNT=
RPCNFSDPRIORITY=0
RPCMOUNTDOPTS=
NEED_SVCGSSD=
RPCSVCGSSDOPTS=
RPCNFSDOPTS='--syslog'
strace: Process 32552 attached
1501016020.534715 select(1024, [3 4 5 7 8 9 10 11 12 13 14 15 16 17 18], NULL, NULL, NULL) = 1 (in [3]) <2.334481>
1501016022.869338 read(3, "nfsd 10.135.24.22\n", 32768) = 18 <0.000029>
1501016022.869443 open("/var/lib/nfs/etab", O_RDONLY) = 20 <0.000058>
1501016022.869566 fstat(20, {st_mode=S_IFREG|0644, st_size=234990, ...}) = 0 <0.000036>
1501016022.869673 close(20) = 0 <0.000045>
1501016022.870015 write(3, "nfsd 10.135.24.22 1501017822 nfs"..., 56) = 56 <0.000042>
1501016022.870094 select(1024, [3 4 5 7 8 9 10 11 12 13 14 15 16 17 18], NULL, NULL, NULL) = 1 (in [5]) <0.189956>
1501016023.060124 read(5, "nfsclient.cs.uchicago.edu 1 \\x00"..., 32768) = 39 <0.000046>
1501016023.060220 open("/var/lib/nfs/etab", O_RDONLY) = 20 <0.000028>
1501016023.060292 fstat(20, {st_mode=S_IFREG|0644, st_size=234990, ...}) = 0 <0.000021>
1501016023.060350 close(20) = 0 <0.000022>
1501016023.060423 write(5, "nfsclient.cs.uchicago.edu 1 \\x00"..., 51) = 51 <0.000032>
1501016023.060488 select(1024, [3 4 5 7 8 9 10 11 12 13 14 15 16 17 18], NULL, NULL, NULL) = 1 (in [15]) <0.050699>
1501016023.111265 recvmsg(15, {msg_name(16)={sa_family=AF_INET, sin_port=htons(51141), sin_addr=inet_addr("10.135.24.22")}, msg_iov(1)=[{"Yv\31\354\0\0\0\0\0\0\0\2\0\1\206\245\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0"..., 8800}], msg_controllen=32, [{cmsg_len=28, cmsg_level=SOL_IP, cmsg_type=IP_PKTINFO, {ipi_ifindex=if_nametoindex("ens18"), ipi_spec_dst=inet_addr("10.135.24.23"), ipi_addr=inet_addr("10.135.24.23")}}], msg_flags=0}, 0) = 40 <0.000029>
1501016023.111435 stat("/etc/hosts.allow", {st_mode=S_IFREG|0644, st_size=411, ...}) = 0 <0.000030>
1501016023.111522 stat("/etc/hosts.deny", {st_mode=S_IFREG|0644, st_size=711, ...}) = 0 <0.000028>
1501016023.111610 sendmsg(15, {msg_name(16)={sa_family=AF_INET, sin_port=htons(51141), sin_addr=inet_addr("10.135.24.22")}, msg_iov(1)=[{"Yv\31\354\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 24}], msg_controllen=32, [{cmsg_len=28, cmsg_level=SOL_IP, cmsg_type=IP_PKTINFO, {ipi_ifindex=0, ipi_spec_dst=inet_addr("10.135.24.23"), ipi_addr=inet_addr("10.135.24.23")}}], msg_flags=0}, 0) = 24 <0.000051>
1501016023.111727 select(1024, [3 4 5 7 8 9 10 11 12 13 14 15 16 17 18], NULL, NULL, NULL) = 1 (in [15]) <0.000232>
1501016023.112015 recvmsg(15, {msg_name(16)={sa_family=AF_INET, sin_port=htons(989), sin_addr=inet_addr("10.135.24.22")}, msg_iov(1)=[{".\314P$\0\0\0\0\0\0\0\2\0\1\206\245\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0"..., 8800}], msg_controllen=32, [{cmsg_len=28, cmsg_level=SOL_IP, cmsg_type=IP_PKTINFO, {ipi_ifindex=if_nametoindex("ens18"), ipi_spec_dst=inet_addr("10.135.24.23"), ipi_addr=inet_addr("10.135.24.23")}}], msg_flags=0}, 0) = 40 <0.000023>
1501016023.112093 stat("/etc/hosts.allow", {st_mode=S_IFREG|0644, st_size=411, ...}) = 0 <0.000054>
1501016023.112188 stat("/etc/hosts.deny", {st_mode=S_IFREG|0644, st_size=711, ...}) = 0 <0.000021>
1501016023.112254 sendmsg(15, {msg_name(16)={sa_family=AF_INET, sin_port=htons(989), sin_addr=inet_addr("10.135.24.22")}, msg_iov(1)=[{".\314P$\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 24}], msg_controllen=32, [{cmsg_len=28, cmsg_level=SOL_IP, cmsg_type=IP_PKTINFO, {ipi_ifindex=0, ipi_spec_dst=inet_addr("10.135.24.23"), ipi_addr=inet_addr("10.135.24.23")}}], msg_flags=0}, 0) = 24 <0.000039>
1501016023.112340 select(1024, [3 4 5 7 8 9 10 11 12 13 14 15 16 17 18], NULL, NULL, NULL) = 1 (in [15]) <0.000083>
1501016023.112466 recvmsg(15, {msg_name(16)={sa_family=AF_INET, sin_port=htons(989), sin_addr=inet_addr("10.135.24.22")}, msg_iov(1)=[{"/\314P$\0\0\0\0\0\0\0\2\0\1\206\245\0\0\0\3\0\0\0\1\0\0\0\1\0\0\0$"..., 8800}], msg_controllen=32, [{cmsg_len=28, cmsg_level=SOL_IP, cmsg_type=IP_PKTINFO, {ipi_ifindex=if_nametoindex("ens18"), ipi_spec_dst=inet_addr("10.135.24.23"), ipi_addr=inet_addr("10.135.24.23")}}], msg_flags=0}, 0) = 88 <0.000023>
1501016023.112537 stat("/etc/hosts.allow", {st_mode=S_IFREG|0644, st_size=411, ...}) = 0 <0.000022>
1501016023.112597 stat("/etc/hosts.deny", {st_mode=S_IFREG|0644, st_size=711, ...}) = 0 <0.000022>
1501016023.112669 open("/var/lib/nfs/etab", O_RDONLY) = 20 <0.000027>
1501016023.112734 fstat(20, {st_mode=S_IFREG|0644, st_size=234990, ...}) = 0 <0.000030>
1501016023.112856 close(20) = 0 <0.000057>
1501016023.112977 lstat("/homes", 0x7ffc0917b900) = -1 ENOENT (No such file or directory) <0.000059>
1501016023.113593 sendto(6, "<28>Jul 25 15:53:43 rpc.mountd[3"..., 107, MSG_NOSIGNAL, NULL, 0) = 107 <0.000054>
1501016023.114333 sendmsg(15, {msg_name(16)={sa_family=AF_INET, sin_port=htons(989), sin_addr=inet_addr("10.135.24.22")}, msg_iov(1)=[{"/\314P$\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\r", 28}], msg_controllen=32, [{cmsg_len=28, cmsg_level=SOL_IP, cmsg_type=IP_PKTINFO, {ipi_ifindex=0, ipi_spec_dst=inet_addr("10.135.24.23"), ipi_addr=inet_addr("10.135.24.23")}}], msg_flags=0}, 0) = 28 <0.000065>
1501016023.114480 select(1024, [3 4 5 7 8 9 10 11 12 13 14 15 16 17 18], NULL, NULL, NULL) = 1 (in [15]) <0.196515>
1501016023.311130 recvmsg(15, {msg_name(16)={sa_family=AF_INET, sin_port=htons(49539), sin_addr=inet_addr("10.135.24.22")}, msg_iov(1)=[{"YsnP\0\0\0\0\0\0\0\2\0\1\206\245\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0"..., 8800}], msg_controllen=32, [{cmsg_len=28, cmsg_level=SOL_IP, cmsg_type=IP_PKTINFO, {ipi_ifindex=if_nametoindex("ens18"), ipi_spec_dst=inet_addr("10.135.24.23"), ipi_addr=inet_addr("10.135.24.23")}}], msg_flags=0}, 0) = 40 <0.000051>
1501016023.311292 stat("/etc/hosts.allow", {st_mode=S_IFREG|0644, st_size=411, ...}) = 0 <0.000042>
1501016023.311406 stat("/etc/hosts.deny", {st_mode=S_IFREG|0644, st_size=711, ...}) = 0 <0.000038>
1501016023.311504 sendmsg(15, {msg_name(16)={sa_family=AF_INET, sin_port=htons(49539), sin_addr=inet_addr("10.135.24.22")}, msg_iov(1)=[{"YsnP\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 24}], msg_controllen=32, [{cmsg_len=28, cmsg_level=SOL_IP, cmsg_type=IP_PKTINFO, {ipi_ifindex=0, ipi_spec_dst=inet_addr("10.135.24.23"), ipi_addr=inet_addr("10.135.24.23")}}], msg_flags=0}, 0) = 24 <0.000064>
1501016023.311653 select(1024, [3 4 5 7 8 9 10 11 12 13 14 15 16 17 18], NULL, NULL, NULL) = 1 (in [15]) <0.000175>
1501016023.311907 recvmsg(15, {msg_name(16)={sa_family=AF_INET, sin_port=htons(971), sin_addr=inet_addr("10.135.24.22")}, msg_iov(1)=[{"\f[kA\0\0\0\0\0\0\0\2\0\1\206\245\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0"..., 8800}], msg_controllen=32, [{cmsg_len=28, cmsg_level=SOL_IP, cmsg_type=IP_PKTINFO, {ipi_ifindex=if_nametoindex("ens18"), ipi_spec_dst=inet_addr("10.135.24.23"), ipi_addr=inet_addr("10.135.24.23")}}], msg_flags=0}, 0) = 40 <0.000047>
1501016023.312044 stat("/etc/hosts.allow", {st_mode=S_IFREG|0644, st_size=411, ...}) = 0 <0.000050>
1501016023.312136 stat("/etc/hosts.deny", {st_mode=S_IFREG|0644, st_size=711, ...}) = 0 <0.000023>
1501016023.312224 sendmsg(15, {msg_name(16)={sa_family=AF_INET, sin_port=htons(971), sin_addr=inet_addr("10.135.24.22")}, msg_iov(1)=[{"\f[kA\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 24}], msg_controllen=32, [{cmsg_len=28, cmsg_level=SOL_IP, cmsg_type=IP_PKTINFO, {ipi_ifindex=0, ipi_spec_dst=inet_addr("10.135.24.23"), ipi_addr=inet_addr("10.135.24.23")}}], msg_flags=0}, 0) = 24 <0.000041>
1501016023.312317 select(1024, [3 4 5 7 8 9 10 11 12 13 14 15 16 17 18], NULL, NULL, NULL) = 1 (in [15]) <0.000083>
1501016023.312440 recvmsg(15, {msg_name(16)={sa_family=AF_INET, sin_port=htons(971), sin_addr=inet_addr("10.135.24.22")}, msg_iov(1)=[{"\r[kA\0\0\0\0\0\0\0\2\0\1\206\245\0\0\0\3\0\0\0\1\0\0\0\1\0\0\0$"..., 8800}], msg_controllen=32, [{cmsg_len=28, cmsg_level=SOL_IP, cmsg_type=IP_PKTINFO, {ipi_ifindex=if_nametoindex("ens18"), ipi_spec_dst=inet_addr("10.135.24.23"), ipi_addr=inet_addr("10.135.24.23")}}], msg_flags=0}, 0) = 88 <0.000021>
1501016023.312513 stat("/etc/hosts.allow", {st_mode=S_IFREG|0644, st_size=411, ...}) = 0 <0.000026>
1501016023.312576 stat("/etc/hosts.deny", {st_mode=S_IFREG|0644, st_size=711, ...}) = 0 <0.000019>
1501016023.312635 open("/var/lib/nfs/etab", O_RDONLY) = 20 <0.000023>
1501016023.312691 fstat(20, {st_mode=S_IFREG|0644, st_size=234990, ...}) = 0 <0.000019>
1501016023.312741 close(20) = 0 <0.000019>
1501016023.312790 lstat("/stage", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 <0.000045>
1501016023.313043 sendto(6, "<28>Jul 25 15:53:43 rpc.mountd[3"..., 107, MSG_NOSIGNAL, NULL, 0) = 107 <0.000027>
1501016023.313400 sendmsg(15, {msg_name(16)={sa_family=AF_INET, sin_port=htons(971), sin_addr=inet_addr("10.135.24.22")}, msg_iov(1)=[{"\r[kA\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\r", 28}], msg_controllen=32, [{cmsg_len=28, cmsg_level=SOL_IP, cmsg_type=IP_PKTINFO, {ipi_ifindex=0, ipi_spec_dst=inet_addr("10.135.24.23"), ipi_addr=inet_addr("10.135.24.23")}}], msg_flags=0}, 0) = 28 <0.000036>
1501016023.313485 select(1024, [3 4 5 7 8 9 10 11 12 13 14 15 16 17 18], NULL, NULL, NULL
