Re: Reoccurring 5 second delays during NFS calls

Florian Möller <fmoeller@xxxxxxxxxxxxxxxxxxxxxxxxxxx> · Tue, 21 Feb 2023 14:33:32 +0100

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:
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)

I see you're using the -o async export option. Note that you may end up
with corrupt data on a server reboot (see exports(5) manpage).

Assuming you're aware of this and want to keep that anyway, then the
patch I just posted to the mailing list may help you, if the stalls are
coming during CLOSE operations:

https://lore.kernel.org/linux-nfs/9137413986ba9c2e83c030513fa9ae3358f30a85.camel@xxxxxxxxxx/T/#mcb88f091263d07d8b9c13e6cc5ce0a0413d3f761

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
Breakpoint 181, 0xffffffffc0979970 in nfs4_atomic_open ()
Continuing.

Breakpoint 180, 0xffffffffc0978c80 in nfs4_do_open ()
Continuing.

Breakpoint 371, 0xffffffffc098c990 in nfs4_get_state_owner ()
Continuing.

Breakpoint 396, 0xffffffffc098f560 in nfs4_client_recover_expired_lease ()
Continuing.

Breakpoint 395, 0xffffffffc098f4b0 in nfs4_wait_clnt_recover ()
Continuing.

Breakpoint 62, 0xffffffffc096d300 in nfs4_opendata_alloc ()
Continuing.

Breakpoint 675, 0xffffffffc09130f0 in nfs4_label_alloc ()
Continuing.

Breakpoint 68, 0xffffffffc096e2f0 in nfs4_run_open_task ()
Continuing.

Breakpoint 120, 0xffffffffc0972a40 in nfs4_open_prepare ()
Continuing.

Breakpoint 104, 0xffffffffc09724a0 in nfs4_setup_sequence ()
Continuing.

Breakpoint 480, 0xffffffffc099a430 in nfs4_alloc_slot ()
Continuing.

Breakpoint 471, 0xffffffffc0999e60 in nfs4_find_or_create_slot ()
Continuing.

Breakpoint 325, 0xffffffffc0988e90 in nfs4_xdr_enc_open ()
Continuing.

Breakpoint 678, 0xffffffffc0580ed0 in nfs4svc_decode_compoundargs ()
Continuing.

Breakpoint 694, 0xffffffffc0585770 in nfs4_alloc_stid ()
Continuing.

Breakpoint 692, 0xffffffffc0584ad0 in nfs4_get_vfs_file ()
Continuing.

Breakpoint 699, 0xffffffffc0586370 in nfs4_inc_and_copy_stateid ()
Continuing.

Breakpoint 698, 0xffffffffc05859c0 in nfs4_put_stid ()
Continuing.

Breakpoint 688, 0xffffffffc05835a0 in nfs4_put_stateowner ()
Continuing.

Breakpoint 679, 0xffffffffc0581310 in nfs4svc_encode_compoundres ()
Continuing.

Breakpoint 338, 0xffffffffc098ae50 in nfs4_xdr_dec_open ()
Continuing.

Breakpoint 100, 0xffffffffc09712f0 in nfs4_open_done ()
Continuing.

Breakpoint 76, 0xffffffffc096f340 in nfs41_sequence_process ()
Continuing.

Breakpoint 400, 0xffffffffc098faf0 in nfs41_handle_sequence_flag_errors ()
Continuing.

Breakpoint 486, 0xffffffffc099a740 in nfs41_update_target_slotid ()
Continuing.

Breakpoint 480, 0xffffffffc099a430 in nfs4_alloc_slot ()
Continuing.

Breakpoint 471, 0xffffffffc0999e60 in nfs4_find_or_create_slot ()
Continuing.

Breakpoint 476, 0xffffffffc099a200 in nfs4_free_slot ()
Continuing.

Breakpoint 178, 0xffffffffc0978b20 in nfs4_open_release ()
Continuing.

Breakpoint 24, 0xffffffffc09691c0 in nfs4_update_changeattr_locked ()
Continuing.

Breakpoint 376, 0xffffffffc098d0b0 in nfs4_get_open_state ()
Continuing.

Breakpoint 737, 0xffffffffc0977280 in update_open_stateid ()
Continuing.

Breakpoint 418, 0xffffffffc0991d20 in nfs4_get_valid_delegation ()
Continuing.

Breakpoint 375, 0xffffffffc098d040 in nfs4_state_set_mode_locked ()
Continuing.

Breakpoint 87, 0xffffffffc0970230 in nfs4_sequence_free_slot ()
Continuing.

Breakpoint 73, 0xffffffffc096efe0 in nfs41_release_slot ()
Continuing.

Breakpoint 483, 0xffffffffc099a5e0 in nfs41_wake_and_assign_slot ()
Continuing.

Breakpoint 476, 0xffffffffc099a200 in nfs4_free_slot ()
Continuing.

Breakpoint 93, 0xffffffffc09706d0 in nfs4_opendata_free ()
Continuing.

Breakpoint 493, 0xffffffffc09a9800 in nfs4_lgopen_release ()
Continuing.

Breakpoint 372, 0xffffffffc098ce50 in nfs4_put_state_owner ()
Continuing.

Breakpoint 412, 0xffffffffc0990840 in nfs4_file_flush ()
Continuing.

Breakpoint 426, 0xffffffffc0992fc0 in nfs4_delegation_flush_on_close ()
Continuing.

Breakpoint 140, 0xffffffffc0974b90 in nfs4_proc_setattr ()
Continuing.

Breakpoint 675, 0xffffffffc09130f0 in nfs4_label_alloc ()
Continuing.

Breakpoint 139, 0xffffffffc09746c0 in nfs4_do_setattr ()
Continuing.

Breakpoint 27, 0xffffffffc0969520 in nfs4_bitmap_copy_adjust ()
Continuing.

Breakpoint 423, 0xffffffffc0992610 in nfs4_inode_make_writeable ()
Continuing.

Breakpoint 53, 0xffffffffc096b060 in nfs4_call_sync_sequence ()
Continuing.

Breakpoint 111, 0xffffffffc09727c0 in nfs41_call_sync_prepare ()
Continuing.

Breakpoint 104, 0xffffffffc09724a0 in nfs4_setup_sequence ()
Continuing.

Breakpoint 480, 0xffffffffc099a430 in nfs4_alloc_slot ()
Continuing.

Breakpoint 471, 0xffffffffc0999e60 in nfs4_find_or_create_slot ()
Continuing.

Breakpoint 296, 0xffffffffc0984b50 in nfs4_xdr_enc_setattr ()
Continuing.

Breakpoint 678, 0xffffffffc0580ed0 in nfs4svc_decode_compoundargs ()
Continuing.

Breakpoint 679, 0xffffffffc0581310 in nfs4svc_encode_compoundres ()
Continuing.

Breakpoint 330, 0xffffffffc098a740 in nfs4_xdr_dec_setattr ()
Continuing.

Breakpoint 79, 0xffffffffc096f700 in nfs41_call_sync_done ()
Continuing.