Hi all,
we are currently in the process of migrating our file server infrastructure to NFS. In our test environments, the following problem has now occurred several times in certain situations:
A previously very fast NFS file operation suddenly takes 5 seconds longer - per file. This leads to applications running very slowly and severely delayed file operations.
Here are the details:
NFS server:
OS: Ubuntu 22.04.1, all patches installed
Kernel: Ubuntu Mainline, Versions
6.1.7-060107-generic_6.1.7-060107.202301181200
6.1.8-060108_6.1.8-060108.202301240742
6.1.9-060109_6.1.9-060109.202302010835
Security options: all Kerberos security options are affected
(The bug does not seem to occur without Kerberos security.)
Output of exportfs -v:
/export gss/krb5p(async,wdelay,hide,crossmnt,no_subtree_check,fsid=0,sec=sys,rw,secure,root_squash,no_all_squash)
/export gss/krb5(async,wdelay,hide,crossmnt,no_subtree_check,fsid=0,sec=sys,rw,secure,root_squash,no_all_squash)
Client 1:
OS: Arch Linux, all patches installed
Kernel: 6.1.9-arch1-2, 6.1.9-arch1-1
Mount-Line: servername:/ on /nfs type nfs4 (rw,relatime,vers=4.2,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=krb5p,clientaddr=XX.XX.XX.XX,local_lock=none,addr=YY.YY.YY.YY,_netdev)
krb5: 1.20.1-1
libevent: 2.1.12-4
nfs-utils: 2.6.2-1
util-linux: 2.38.1-1
Client 2:
OS: openSuSE 15.4, all patches installed
Kernel: 5.14.21-150400.24.41-default
Mount-Line: servername:/ on /nfs type nfs4 (rw,relatime,sync,vers=4.2,rsize=1048576,wsize=1048576,namlen=255,acregmin=0,acregmax=0,acdirmin=0,acdirmax=0,softerr,softreval,noac,noresvport,proto=tcp,timeo=1,retrans=2,sec=krb5,clientaddr=XX.XX.XX.XX,lookupcache=none,local_lock=none,addr=YY.YY.YY.YY)
libgssapi3: 7.8.0-bp154.2.4.1
libevent: 2.1.8-2.23
nfs-client: 2.1.1-150100.10.27.1
util-linux: 2.37.2-140400.8.14.1
The error occurs for example if a file is touched twice:
touch testfile && echo "done" && touch testfile && echo "and again"
However, touching a large number of files (about 10000) with (pairwise) different filenames works fast.
Here is another example that triggers the error:
1st step: create many files (shell code in Z-shell syntax):
for i in {1..10000}; do
echo "test" > $i.txt
done
This is fast.
2nd step:
for i in {1..10000}; do
echo $i
cat $i.txt
done
This takes 5 seconds per cat(1) call.
After unmounting and mounting, the 2nd step also runs quickly at first. But after executing the 2nd step several times in a row, the error occurs again (quite soon, after the 2nd or 3rd execution).
We were not able to reproduce the error without a Kerberos security type set.
Attached are a log from the server and from the client. In both cases
rpcdebug -m nfs -s all
rpcdebug -m nfsd -s all
rpcdebug -m rpc -s all
was set.
Best regards,
Florian Möller
--
Dr. Florian Möller
Universität Würzburg
Institut für Mathematik
Emil-Fischer-Straße 30
97074 Würzburg, Germany
Tel. +49 931 3185596
From: Jeff Layton <jlayton@kernel.org> Date: 2023-02-07 15:22:05
On Tue, 2023-02-07 at 11:58 +0100, Florian Möller wrote:
Hi all,
we are currently in the process of migrating our file server infrastructure to
NFS. In our test environments, the following problem has now occurred several
times in certain situations:
A previously very fast NFS file operation suddenly takes 5 seconds longer - per
file. This leads to applications running very slowly and severely delayed file
operations.
Here are the details:
NFS server:
OS: Ubuntu 22.04.1, all patches installed
Kernel: Ubuntu Mainline, Versions
6.1.7-060107-generic_6.1.7-060107.202301181200
6.1.8-060108_6.1.8-060108.202301240742
6.1.9-060109_6.1.9-060109.202302010835
Security options: all Kerberos security options are affected
(The bug does not seem to occur without Kerberos security.)
Output of exportfs -v:
/export
gss/krb5p(async,wdelay,hide,crossmnt,no_subtree_check,fsid=0,sec=sys,rw,secure,root_squash,no_all_squash)
/export
gss/krb5(async,wdelay,hide,crossmnt,no_subtree_check,fsid=0,sec=sys,rw,secure,root_squash,no_all_squash)
Client 1:
OS: Arch Linux, all patches installed
Kernel: 6.1.9-arch1-2, 6.1.9-arch1-1
Mount-Line: servername:/ on /nfs type nfs4
(rw,relatime,vers=4.2,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=krb5p,clientaddr=XX.XX.XX.XX,local_lock=none,addr=YY.YY.YY.YY,_netdev)
krb5: 1.20.1-1
libevent: 2.1.12-4
nfs-utils: 2.6.2-1
util-linux: 2.38.1-1
Client 2:
OS: openSuSE 15.4, all patches installed
Kernel: 5.14.21-150400.24.41-default
Mount-Line: servername:/ on /nfs type nfs4
(rw,relatime,sync,vers=4.2,rsize=1048576,wsize=1048576,namlen=255,acregmin=0,acregmax=0,acdirmin=0,acdirmax=0,softerr,softreval,noac,noresvport,proto=tcp,timeo=1,retrans=2,sec=krb5,clientaddr=XX.XX.XX.XX,lookupcache=none,local_lock=none,addr=YY.YY.YY.YY)
libgssapi3: 7.8.0-bp154.2.4.1
libevent: 2.1.8-2.23
nfs-client: 2.1.1-150100.10.27.1
util-linux: 2.37.2-140400.8.14.1
The error occurs for example if a file is touched twice:
touch testfile && echo "done" && touch testfile && echo "and again"
However, touching a large number of files (about 10000) with (pairwise)
different filenames works fast.
Here is another example that triggers the error:
1st step: create many files (shell code in Z-shell syntax):
for i in {1..10000}; do
echo "test" > $i.txt
done
This is fast.
2nd step:
for i in {1..10000}; do
echo $i
cat $i.txt
done
This takes 5 seconds per cat(1) call.
After unmounting and mounting, the 2nd step also runs quickly at first. But
after executing the 2nd step several times in a row, the error occurs again
(quite soon, after the 2nd or 3rd execution).
We were not able to reproduce the error without a Kerberos security type set.
Attached are a log from the server and from the client. In both cases
rpcdebug -m nfs -s all
rpcdebug -m nfsd -s all
rpcdebug -m rpc -s all
was set.
Best regards,
Florian Möller
Hi all,
unfortunately the patch did not help, neither using -o async nor using -o sync. We did some more tests (which is the reason for the delay of this reply):
We used a qemu image housing both the NFS server and the client and did some kernel debugging.
OS: Ubuntu 22.04.1
Kernel: 5.15.78
Mount line: rw,relatime,vers=4.2,rsize=1048576,wsize=1048576,
namlen=255,hard,proto=tcp,timeo=600,retrans=2,
sec=krb5p,clientaddr=10.0.0.1,
local_lock=none,addr=10.0.0.1
We touched a file and then touched the file again. This triggers the delay reliably.
We set breakpoints on all functions starting with nfs4 and on "update_open_stateid". The attached file "1sttouch.log" contains a gdb log of the first touch.
"2ndtouch.log" shows the gdb output of the second touch. The delay occurs in line 116 in update_open_stateid.
We then deleted all breakpoints and set a sole breakpoint on update_open_stateid. We touched the file again and used only the "next" command of gdb. The gdb output is in "2ndtouch-next.log", the delay occurs in line 8.
Please let us know if you need more information or if you want us to perform further tests.
Best regards,
Florian Möller
Am 07.02.23 um 16:21 schrieb Jeff Layton:
On Tue, 2023-02-07 at 11:58 +0100, Florian Möller wrote:
quoted
Hi all,
we are currently in the process of migrating our file server infrastructure to
NFS. In our test environments, the following problem has now occurred several
times in certain situations:
A previously very fast NFS file operation suddenly takes 5 seconds longer - per
file. This leads to applications running very slowly and severely delayed file
operations.
Here are the details:
NFS server:
OS: Ubuntu 22.04.1, all patches installed
Kernel: Ubuntu Mainline, Versions
6.1.7-060107-generic_6.1.7-060107.202301181200
6.1.8-060108_6.1.8-060108.202301240742
6.1.9-060109_6.1.9-060109.202302010835
Security options: all Kerberos security options are affected
(The bug does not seem to occur without Kerberos security.)
Output of exportfs -v:
/export
gss/krb5p(async,wdelay,hide,crossmnt,no_subtree_check,fsid=0,sec=sys,rw,secure,root_squash,no_all_squash)
/export
gss/krb5(async,wdelay,hide,crossmnt,no_subtree_check,fsid=0,sec=sys,rw,secure,root_squash,no_all_squash)
Client 1:
OS: Arch Linux, all patches installed
Kernel: 6.1.9-arch1-2, 6.1.9-arch1-1
Mount-Line: servername:/ on /nfs type nfs4
(rw,relatime,vers=4.2,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=krb5p,clientaddr=XX.XX.XX.XX,local_lock=none,addr=YY.YY.YY.YY,_netdev)
krb5: 1.20.1-1
libevent: 2.1.12-4
nfs-utils: 2.6.2-1
util-linux: 2.38.1-1
Client 2:
OS: openSuSE 15.4, all patches installed
Kernel: 5.14.21-150400.24.41-default
Mount-Line: servername:/ on /nfs type nfs4
(rw,relatime,sync,vers=4.2,rsize=1048576,wsize=1048576,namlen=255,acregmin=0,acregmax=0,acdirmin=0,acdirmax=0,softerr,softreval,noac,noresvport,proto=tcp,timeo=1,retrans=2,sec=krb5,clientaddr=XX.XX.XX.XX,lookupcache=none,local_lock=none,addr=YY.YY.YY.YY)
libgssapi3: 7.8.0-bp154.2.4.1
libevent: 2.1.8-2.23
nfs-client: 2.1.1-150100.10.27.1
util-linux: 2.37.2-140400.8.14.1
The error occurs for example if a file is touched twice:
touch testfile && echo "done" && touch testfile && echo "and again"
However, touching a large number of files (about 10000) with (pairwise)
different filenames works fast.
Here is another example that triggers the error:
1st step: create many files (shell code in Z-shell syntax):
for i in {1..10000}; do
echo "test" > $i.txt
done
This is fast.
2nd step:
for i in {1..10000}; do
echo $i
cat $i.txt
done
This takes 5 seconds per cat(1) call.
After unmounting and mounting, the 2nd step also runs quickly at first. But
after executing the 2nd step several times in a row, the error occurs again
(quite soon, after the 2nd or 3rd execution).
We were not able to reproduce the error without a Kerberos security type set.
Attached are a log from the server and from the client. In both cases
rpcdebug -m nfs -s all
rpcdebug -m nfsd -s all
rpcdebug -m rpc -s all
was set.
Best regards,
Florian Möller
--
Dr. Florian Möller
Universität Würzburg
Institut für Mathematik
Emil-Fischer-Straße 30
97074 Würzburg, Germany
Tel. +49 931 3185596
From: Benjamin Coddington <hidden> Date: 2023-02-21 14:14:34
On 21 Feb 2023, at 8:33, Florian Möller wrote:
Hi all,
unfortunately the patch did not help, neither using -o async nor using -o sync. We did some more tests (which is the reason for the delay of this reply):
We used a qemu image housing both the NFS server and the client and did some kernel debugging.
OS: Ubuntu 22.04.1
Kernel: 5.15.78
Mount line: rw,relatime,vers=4.2,rsize=1048576,wsize=1048576,
namlen=255,hard,proto=tcp,timeo=600,retrans=2,
sec=krb5p,clientaddr=10.0.0.1,
local_lock=none,addr=10.0.0.1
We touched a file and then touched the file again. This triggers the delay reliably.
We set breakpoints on all functions starting with nfs4 and on "update_open_stateid". The attached file "1sttouch.log" contains a gdb log of the first touch.
"2ndtouch.log" shows the gdb output of the second touch. The delay occurs in line 116 in update_open_stateid.
We then deleted all breakpoints and set a sole breakpoint on update_open_stateid. We touched the file again and used only the "next" command of gdb. The gdb output is in "2ndtouch-next.log", the delay occurs in line 8.
Please let us know if you need more information or if you want us to perform further tests.
Best regards,
Florian Möller
Hi Florian,
The 5 second value and location of the delay is making me suspect something
is wrong with the open stateid sequence processing.
The client introduces 5-second delays in order to correctly order stateid
updates from the server. Usually this happens because there are multiple
processes sending OPEN/CLOSE calls and the server processess them out of
order, or the client receives the responses out of order.
It would be helpful to have a network capture of the problem, along with the
matching output from these tracepoints on the client:
nfs4:nfs4_open_stateid_update
nfs4:nfs4_open_stateid_update_wait
nfs4:nfs4_close_stateid_update_wait
sunrpc:xs_stream_read_request
sunrpc:rpc_request
sunrpc:rpc_task_end
And these tracepoints on the server:
nfsd:nfsd_preprocess
sunrpc:svc_process
I'm interested in seeing how the client is processing the sequence numbers
of the open stateid, or if perhaps there's a delegation in play.
LMK if you need help with the tracepoints -- you can simply append those
lines into /sys/kernel/debug/tracing/set_event, then reproduce the problem.
The output of those tracepoints will be in /sys/kernel/debug/tracing/trace.
Ben
Hi Benjamin,
here are the trace and a listing of the corresponding network packages. If the listing is not detailed enough, I can send you a full package dump tomorrow.
The command I used was
touch test.txt && sleep 2 && touch test.txt
test.txt did not exist previously. So you have an example of a touch without and with delay.
Best regards,
Florian
Am 21.02.23 um 15:13 schrieb Benjamin Coddington:
On 21 Feb 2023, at 8:33, Florian Möller wrote:
quoted
Hi all,
unfortunately the patch did not help, neither using -o async nor using -o sync. We did some more tests (which is the reason for the delay of this reply):
We used a qemu image housing both the NFS server and the client and did some kernel debugging.
OS: Ubuntu 22.04.1
Kernel: 5.15.78
Mount line: rw,relatime,vers=4.2,rsize=1048576,wsize=1048576,
namlen=255,hard,proto=tcp,timeo=600,retrans=2,
sec=krb5p,clientaddr=10.0.0.1,
local_lock=none,addr=10.0.0.1
We touched a file and then touched the file again. This triggers the delay reliably.
We set breakpoints on all functions starting with nfs4 and on "update_open_stateid". The attached file "1sttouch.log" contains a gdb log of the first touch.
"2ndtouch.log" shows the gdb output of the second touch. The delay occurs in line 116 in update_open_stateid.
We then deleted all breakpoints and set a sole breakpoint on update_open_stateid. We touched the file again and used only the "next" command of gdb. The gdb output is in "2ndtouch-next.log", the delay occurs in line 8.
Please let us know if you need more information or if you want us to perform further tests.
Best regards,
Florian Möller
Hi Florian,
The 5 second value and location of the delay is making me suspect something
is wrong with the open stateid sequence processing.
The client introduces 5-second delays in order to correctly order stateid
updates from the server. Usually this happens because there are multiple
processes sending OPEN/CLOSE calls and the server processess them out of
order, or the client receives the responses out of order.
It would be helpful to have a network capture of the problem, along with the
matching output from these tracepoints on the client:
nfs4:nfs4_open_stateid_update
nfs4:nfs4_open_stateid_update_wait
nfs4:nfs4_close_stateid_update_wait
sunrpc:xs_stream_read_request
sunrpc:rpc_request
sunrpc:rpc_task_end
And these tracepoints on the server:
nfsd:nfsd_preprocess
sunrpc:svc_process
I'm interested in seeing how the client is processing the sequence numbers
of the open stateid, or if perhaps there's a delegation in play.
LMK if you need help with the tracepoints -- you can simply append those
lines into /sys/kernel/debug/tracing/set_event, then reproduce the problem.
The output of those tracepoints will be in /sys/kernel/debug/tracing/trace.
Ben
--
Dr. Florian Möller
Universität Würzburg
Institut für Mathematik
Emil-Fischer-Straße 30
97074 Würzburg, Germany
Tel. +49 931 3185596
From: Benjamin Coddington <hidden> Date: 2023-02-21 18:59:53
On 21 Feb 2023, at 11:52, Florian Möller wrote:
Hi Benjamin,
here are the trace and a listing of the corresponding network packages. If the listing is not detailed enough, I can send you a full package dump tomorrow.
The command I used was
touch test.txt && sleep 2 && touch test.txt
test.txt did not exist previously. So you have an example of a touch without and with delay.
Thanks! These are great - I can see from them that the client is indeed
waiting in the stateid update mechanism because the server has returned
NFS4ERR_STALE to the client's first CLOSE.
That is unusual. The server is signaling that the open file's stateid is old,
so I am interested to see if the first CLOSE is sent with the stateid's
sequence that was returned from the server. I could probably see this if I
had the server-side tracepoint data.
But from what's here I cannot see the details to figure this out because
you've only sent the summary of the packet capture.. can you send along the
raw capture?
I usually use something like:
tshark -w /tmp/pcap -i enps0 -P host server
.. then the file /tmp/pcap has the raw capture. We can use that to look at
the sequence numbers for the stateid as sent from client to server.
However, if you use krb5p, we won't be able to see these details. Only krb5
or krb5i. If the problem only reproduces with krb5p, we have to rely on the
tracepoints output on the client and server.
Ben