From:   Benjamin Coddington <bcodding@redhat.com>
To:     Jeff Layton <jlayton@kernel.org>
Cc:     =?utf-8?q?Florian_M=C3=B6ller?= 
        <fmoeller@mathematik.uni-wuerzburg.de>, linux-nfs@vger.kernel.org,
        Andreas Seeg <andreas.seeg@mathematik.uni-wuerzburg.de>
Subject: Re: Reoccurring 5 second delays during NFS calls
Date:   Wed, 22 Feb 2023 07:45:59 -0500
Message-ID: <44FB0164-D389-44ED-A784-8B0ABA32EF4C@redhat.com>
In-Reply-To: <90861fe9716ab35f52b136f533ac693eb3d86279.camel@kernel.org>
References: <59682160-a246-395a-9486-9bbf11686740@mathematik.uni-wuerzburg.de>
 <8a02c86882bc47c1c1387dba8c7d756237cb3f3f.camel@kernel.org>
 <3b6c9b8e-2795-74e8-aefa-d4f1ac007c3c@mathematik.uni-wuerzburg.de>
 <785052D6-E39F-40D3-8BA3-72D3940EDD84@redhat.com>
 <7c7de5f1-fb6a-e970-99a2-4880583d8f6d@mathematik.uni-wuerzburg.de>
 <1B586C15-908C-4B00-9739-9AD118F88BD4@redhat.com>
 <4f70c2f5-dfdb-c37c-8663-5f2a108e229e@mathematik.uni-wuerzburg.de>
 <5AB8B0FE-5D7E-4ED4-9537-979341C6371A@redhat.com>
 <90861fe9716ab35f52b136f533ac693eb3d86279.camel@kernel.org>
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: quoted-printable
Precedence: bulk

On 22 Feb 2023, at 7:22, Jeff Layton wrote:

> On Wed, 2023-02-22 at 06:54 -0500, Benjamin Coddington wrote:
>> On 22 Feb 2023, at 3:19, Florian M=C3=B6ller wrote:
>>
>>> Am 21.02.23 um 19:58 schrieb Benjamin Coddington:
>>>> On 21 Feb 2023, at 11:52, Florian M=C3=B6ller wrote:
>>>>
>>>>> Hi Benjamin,
>>>>>
>>>>> here are the trace and a listing of the corresponding network packa=
ges. 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 touc=
h without and with delay.
>>>>
>>>> Thanks!  These are great - I can see from them that the client is in=
deed
>>>> waiting in the stateid update mechanism because the server has retur=
ned
>>>> NFS4ERR_STALE to the client's first CLOSE.
>>>>
>>>> That is unusual.  The server is signaling that the open file's state=
id is old,
>>>> so I am interested to see if the first CLOSE is sent with the statei=
d's
>>>> sequence that was returned from the server.  I could probably see th=
is if I
>>>> had the server-side tracepoint data.
>>>
>>> Hi Benjamin,
>>>
>>> the server-side tracepoints
>>>
>>> nfsd:nfsd_preprocess
>>> sunrpc:svc_process
>>>
>>> were enabled. It seems they did not produce any output.
>>>
>>> What I did now was:
>>> - enable all nfsd tracepoints,
>>> - enable all nfs4 tracepoints,
>>> - enable all sunrpc tracepoints.
>>>
>>> The command I used was
>>>
>>> touch somefile && sleep 2 && touch somefile.
>>>
>>> Then I unmounted the NFS share - this also causes a delay.
>>>
>>> I changed the security type to krb5 and captured trace and network ou=
tput for a version 4.0 and a version 4.2 mount. The delay does not occur =
when using version 4.0.
>>
>>
>> In frame 9 of nfs-v4.2-krb5.pcap, the server responds to PUTFH with
>> NFS4ERR_STALE, so nothing to do with the open stateid sequencing.  I a=
lso
>> see:
>>
>> nfsd-1693    [000] .....  1951.353889: nfsd_exp_find_key: fsid=3D1::{0=
x0,0xe5fcf0,0xffffc900,0x811e87a3,0xffffffff,0xe5fd00} domain=3Dgss/krb5i=
 status=3D-2
>> nfsd-1693    [000] .....  1951.353889: nfsd_set_fh_dentry_badexport: x=
id=3D0xe1511810 fh_hash=3D0x3f9e713a status=3D-2
>> nfsd-1693    [000] .....  1951.353890: nfsd_compound_status: op=3D2/4 =
OP_PUTFH status=3D70
>>
>
> This just means that the kernel called into the "cache" infrastructure
> to find an export entry, and there wasn't one.
>
>
> Looking back at the original email here, I'd say this is expected since=

> the export wasn't set up for krb5i.
>
> Output of exportfs -v:
> /export
> gss/krb5p(async,wdelay,hide,crossmnt,no_subtree_check,fsid=3D0,sec=3Dsy=
s,rw,secure,root_squash,no_all_squash)
> /export
> gss/krb5(async,wdelay,hide,crossmnt,no_subtree_check,fsid=3D0,sec=3Dsys=
,rw,secure,root_squash,no_all_squash)

Jeff and I were chatting on #linux-nfs, and its back to looking like a
client issue.. as he's pointed out that the client starts out with krb5,
then in Frame 8 (the CLOSE that receives STALE) switches to krb5i, then b=
ack
to krb5 in Frame 10..

=2E. this should be reproduceable.  Let me dust off my old kdc.

Ben