still seeing single client NFS4ERR_DELAY / CB_RECALL

still seeing single client NFS4ERR_DELAY / CB_RECALL

[Chuck Lever]

Hi Bruce-

I noticed that one of my tests takes about 4x longer on NFSv4.0 than it does on NFSv3 or NFSv4.[12]. As an initial stab at the cause, I'm seeing lots of these:

           <...>-283894 [003]  4060.507314: nfs4_xdr_status:      task:51308@5 xid=0x1ec806a9 error=-10008 (DELAY) operation=34
           <...>-283894 [003]  4060.507338: nfs4_setattr:         error=-10008 (DELAY) fileid=00:27:258012 fhandle=0x25ef273d stateid=0:0x7bd5c66f
           <...>-283982 [006]  4060.508134: nfs4_state_mgr:       hostname=klimt.ib clp state=CHECK_LEASE|0x4020
           NFSv4-6239  [007]  4060.508137: nfs4_cb_recall:       error=0 (OK) fileid=00:27:258012 fhandle=0x25ef273d stateid=1:0x910c8d4c dstaddr=klimt.ib

The workload is the git regression suite, which I run like this on a single client:

  --- mount test export ---

 $ cd /mnt; rm -rf git*; tar zvxf ~/Downloads/git-2.23.0.tar.gz

  --- remount test export ---

 $ cd /mnt/git*; make clean; make -j12

  --- remount test export ---

 $ cd /mnt/git*; make -j12 test

--
Chuck Lever

Re: still seeing single client NFS4ERR_DELAY / CB_RECALL

[Bruce Fields]

On Sun, Aug 09, 2020 at 01:11:36PM -0400, Chuck Lever wrote:
> Hi Bruce-
> 
> I noticed that one of my tests takes about 4x longer on NFSv4.0 than
> it does on NFSv3 or NFSv4.[12]. As an initial stab at the cause, I'm
> seeing lots of these:

Oops, looks obvious in retrospect, but I didn't think of it.

In the 4.1+ case, sessions mean that we know which client every
operation comes from.

In the 4.0 case that only works for operations that take a stateid or
something else we can link back to a client.

That means in the 4.0 case delegations are less useful, since they have
to be broken on any (non-truncating) setattr, any link/unlink, etc.,
even if the operation comes from the same client--the server doesn't
have a way to know that.

Maybe the change to give out read delegations even on write opens
probably just isn't worth in the 4.0 case.

--b.


> 
>            <...>-283894 [003]  4060.507314: nfs4_xdr_status:
>            task:51308@5 xid=0x1ec806a9 error=-10008 (DELAY)
>            operation=34 <...>-283894 [003]  4060.507338: nfs4_setattr:
>            error=-10008 (DELAY) fileid=00:27:258012 fhandle=0x25ef273d
>            stateid=0:0x7bd5c66f <...>-283982 [006]  4060.508134:
>            nfs4_state_mgr:       hostname=klimt.ib clp
>            state=CHECK_LEASE|0x4020 NFSv4-6239  [007]  4060.508137:
>            nfs4_cb_recall:       error=0 (OK) fileid=00:27:258012
>            fhandle=0x25ef273d stateid=1:0x910c8d4c dstaddr=klimt.ib
> 
> The workload is the git regression suite, which I run like this on a
> single client:
> 
>   --- mount test export ---
> 
>  $ cd /mnt; rm -rf git*; tar zvxf ~/Downloads/git-2.23.0.tar.gz
> 
>   --- remount test export ---
> 
>  $ cd /mnt/git*; make clean; make -j12
> 
>   --- remount test export ---
> 
>  $ cd /mnt/git*; make -j12 test
> 
> -- Chuck Lever
> 
> 

Re: still seeing single client NFS4ERR_DELAY / CB_RECALL

[Bruce Fields]

On Sun, Aug 09, 2020 at 04:27:39PM -0400, Bruce Fields wrote:
> On Sun, Aug 09, 2020 at 01:11:36PM -0400, Chuck Lever wrote:
> > Hi Bruce-
> > 
> > I noticed that one of my tests takes about 4x longer on NFSv4.0 than
> > it does on NFSv3 or NFSv4.[12]. As an initial stab at the cause, I'm
> > seeing lots of these:
> 
> Oops, looks obvious in retrospect, but I didn't think of it.
> 
> In the 4.1+ case, sessions mean that we know which client every
> operation comes from.
> 
> In the 4.0 case that only works for operations that take a stateid or
> something else we can link back to a client.
> 
> That means in the 4.0 case delegations are less useful, since they have
> to be broken on any (non-truncating) setattr, any link/unlink, etc.,
> even if the operation comes from the same client--the server doesn't
> have a way to know that.
> 
> Maybe the change to give out read delegations even on write opens
> probably just isn't worth in the 4.0 case.

Untested, but maybe this?--b.

commit 2102ac0b68f3
Author: J. Bruce Fields <bfields@redhat.com>
Date:   Sun Aug 9 17:11:59 2020 -0400

    nfsd4: don't grant delegations on 4.0 create opens
    
    Chuck reported a major slowdown running the git regression suite over
    NFSv4.0.
    
    In the 4.0 case, the server has no way to identify which client most
    metadata-modifying operations come from.  So, for example, the common
    pattern of a a setattr is likely to result in an immediate break in the
    4.0 case.
    
    It's probably not worth giving out delegations on 4.0 creates.
    
    Reported-by: Chuck Lever <chuck.lever@oracle.com>
    Signed-off-by: J. Bruce Fields <bfields@redhat.com>

diff --git a/fs/nfsd/nfs4state.c b/fs/nfsd/nfs4state.c
index fdba971d06c3..ce2d052b3f64 100644
--- a/fs/nfsd/nfs4state.c
+++ b/fs/nfsd/nfs4state.c
@@ -5096,6 +5096,16 @@ nfs4_open_delegation(struct svc_fh *fh, struct nfsd4_open *open,
 				goto out_no_deleg;
 			if (!cb_up || !(oo->oo_flags & NFS4_OO_CONFIRMED))
 				goto out_no_deleg;
+			/*
+			 * In the absence of sessions, most operations
+			 * that modify metadata (like setattr) can't
+			 * be linked to the client sending them, so
+			 * will result in a delegation break.  That's
+			 * especially likely for create opens:
+			 */
+			if (clp->cl_minorversion == 0 &&
+					open->op_create == NFS4_OPEN_CREATE)
+				goto out_no_deleg;
 			break;
 		default:
 			goto out_no_deleg;

Re: still seeing single client NFS4ERR_DELAY / CB_RECALL

[Chuck Lever]

> On Aug 9, 2020, at 5:25 PM, Bruce Fields <bfields@fieldses.org> wrote:
> 
> On Sun, Aug 09, 2020 at 04:27:39PM -0400, Bruce Fields wrote:
>> On Sun, Aug 09, 2020 at 01:11:36PM -0400, Chuck Lever wrote:
>>> Hi Bruce-
>>> 
>>> I noticed that one of my tests takes about 4x longer on NFSv4.0 than
>>> it does on NFSv3 or NFSv4.[12]. As an initial stab at the cause, I'm
>>> seeing lots of these:
>> 
>> Oops, looks obvious in retrospect, but I didn't think of it.
>> 
>> In the 4.1+ case, sessions mean that we know which client every
>> operation comes from.
>> 
>> In the 4.0 case that only works for operations that take a stateid or
>> something else we can link back to a client.
>> 
>> That means in the 4.0 case delegations are less useful, since they have
>> to be broken on any (non-truncating) setattr, any link/unlink, etc.,
>> even if the operation comes from the same client--the server doesn't
>> have a way to know that.
>> 
>> Maybe the change to give out read delegations even on write opens
>> probably just isn't worth in the 4.0 case.
> 
> Untested, but maybe this?--b.
> 
> commit 2102ac0b68f3
> Author: J. Bruce Fields <bfields@redhat.com>
> Date:   Sun Aug 9 17:11:59 2020 -0400
> 
>    nfsd4: don't grant delegations on 4.0 create opens
> 
>    Chuck reported a major slowdown running the git regression suite over
>    NFSv4.0.
> 
>    In the 4.0 case, the server has no way to identify which client most
>    metadata-modifying operations come from.  So, for example, the common
>    pattern of a a setattr is likely to result in an immediate break in the
>    4.0 case.
> 
>    It's probably not worth giving out delegations on 4.0 creates.
> 
>    Reported-by: Chuck Lever <chuck.lever@oracle.com>
>    Signed-off-by: J. Bruce Fields <bfields@redhat.com>
> 
> diff --git a/fs/nfsd/nfs4state.c b/fs/nfsd/nfs4state.c
> index fdba971d06c3..ce2d052b3f64 100644
> --- a/fs/nfsd/nfs4state.c
> +++ b/fs/nfsd/nfs4state.c
> @@ -5096,6 +5096,16 @@ nfs4_open_delegation(struct svc_fh *fh, struct nfsd4_open *open,
> 				goto out_no_deleg;
> 			if (!cb_up || !(oo->oo_flags & NFS4_OO_CONFIRMED))
> 				goto out_no_deleg;
> +			/*
> +			 * In the absence of sessions, most operations
> +			 * that modify metadata (like setattr) can't
> +			 * be linked to the client sending them, so
> +			 * will result in a delegation break.  That's
> +			 * especially likely for create opens:
> +			 */
> +			if (clp->cl_minorversion == 0 &&
> +					open->op_create == NFS4_OPEN_CREATE)
> +				goto out_no_deleg;
> 			break;
> 		default:
> 			goto out_no_deleg;


For these results I've switched to sec=sys so the test completes faster.

NFSv3/sys: 953.37user 5101.96system 14:13.78elapsed 709%CPU (0avgtext+0avgdata 107160maxresident)k

NFSv4.1/sys: 953.64user 5202.27system 17:54.51elapsed 572%CPU (0avgtext+0avgdata 107204maxresident)k


NFSv4.0/sys unpatched: 965.44user 5406.75system 36:10.72elapsed 293%CPU (0avgtext+0avgdata 107252maxresident)k

NFSv4.0/sys with fix: 968.38user 5359.18system 30:50.38elapsed 341%CPU (0avgtext+0avgdata 107140maxresident)k


--
Chuck Lever

Re: still seeing single client NFS4ERR_DELAY / CB_RECALL

[Bruce Fields]

Thanks for the test results:

On Mon, Aug 10, 2020 at 02:21:34PM -0400, Chuck Lever wrote:
> For these results I've switched to sec=sys so the test completes faster.
> 
> NFSv3/sys: 953.37user 5101.96system 14:13.78elapsed 709%CPU (0avgtext+0avgdata 107160maxresident)k
> 
> NFSv4.1/sys: 953.64user 5202.27system 17:54.51elapsed 572%CPU (0avgtext+0avgdata 107204maxresident)k
> 
> NFSv4.0/sys unpatched: 965.44user 5406.75system 36:10.72elapsed 293%CPU (0avgtext+0avgdata 107252maxresident)k
> 
> NFSv4.0/sys with fix: 968.38user 5359.18system 30:50.38elapsed 341%CPU (0avgtext+0avgdata 107140maxresident)k

Well, that didn't work!

So maybe it's write opens that are the problem in this case.  The below
should mostly revert to pre-94415b06eb8a behavior in the 4.0 case, so if
this doesn't fix it then I was wrong about the cause....

--b.

commit 0e94ee0b6f11
Author: J. Bruce Fields <bfields@redhat.com>
Date:   Sun Aug 9 17:11:59 2020 -0400

    nfsd4: don't grant delegations on 4.0 create opens
    
    Chuck reported a major slowdown running the git regression suite over
    NFSv4.0.
    
    In the 4.0 case, the server has no way to identify which client most
    metadata-modifying operations come from.  So, for example, the common
    pattern of an create or write open followed by a setattr is likely to
    result in an immediate break in the 4.0 case.
    
    It's probably not worth giving out delegations on 4.0 write or create
    opens.
    
    Reported-by: Chuck Lever <chuck.lever@oracle.com>
    Signed-off-by: J. Bruce Fields <bfields@redhat.com>

diff --git a/fs/nfsd/nfs4state.c b/fs/nfsd/nfs4state.c
index fdba971d06c3..0d51d1751592 100644
--- a/fs/nfsd/nfs4state.c
+++ b/fs/nfsd/nfs4state.c
@@ -5096,6 +5096,19 @@ nfs4_open_delegation(struct svc_fh *fh, struct nfsd4_open *open,
 				goto out_no_deleg;
 			if (!cb_up || !(oo->oo_flags & NFS4_OO_CONFIRMED))
 				goto out_no_deleg;
+			if (clp->cl_minorversion)
+				break;
+			/*
+			 * In the absence of sessions, most operations
+			 * that modify metadata (like setattr) can't
+			 * be linked to the client sending them, so
+			 * will result in a delegation break.  That's
+			 * especially likely for write and create opens:
+			 */
+			if (open->op_share_access & NFS4_SHARE_ACCESS_WRITE)
+				goto out_no_deleg;
+			if (open->op_create == NFS4_OPEN_CREATE)
+				goto out_no_deleg;
 			break;
 		default:
 			goto out_no_deleg;

Re: still seeing single client NFS4ERR_DELAY / CB_RECALL

[Chuck Lever]

> On Aug 10, 2020, at 3:07 PM, Bruce Fields <bfields@fieldses.org> wrote:
> 
> Thanks for the test results:
> 
> On Mon, Aug 10, 2020 at 02:21:34PM -0400, Chuck Lever wrote:
>> For these results I've switched to sec=sys so the test completes faster.
>> 
>> NFSv3/sys: 953.37user 5101.96system 14:13.78elapsed 709%CPU (0avgtext+0avgdata 107160maxresident)k
>> 
>> NFSv4.1/sys: 953.64user 5202.27system 17:54.51elapsed 572%CPU (0avgtext+0avgdata 107204maxresident)k
>> 
>> NFSv4.0/sys unpatched: 965.44user 5406.75system 36:10.72elapsed 293%CPU (0avgtext+0avgdata 107252maxresident)k
>> 
>> NFSv4.0/sys with fix: 968.38user 5359.18system 30:50.38elapsed 341%CPU (0avgtext+0avgdata 107140maxresident)k
> 
> Well, that didn't work!
> 
> So maybe it's write opens that are the problem in this case.  The below
> should mostly revert to pre-94415b06eb8a behavior in the 4.0 case, so if
> this doesn't fix it then I was wrong about the cause....
> 
> --b.
> 
> commit 0e94ee0b6f11
> Author: J. Bruce Fields <bfields@redhat.com>
> Date:   Sun Aug 9 17:11:59 2020 -0400
> 
>    nfsd4: don't grant delegations on 4.0 create opens
> 
>    Chuck reported a major slowdown running the git regression suite over
>    NFSv4.0.
> 
>    In the 4.0 case, the server has no way to identify which client most
>    metadata-modifying operations come from.  So, for example, the common
>    pattern of an create or write open followed by a setattr is likely to
>    result in an immediate break in the 4.0 case.
> 
>    It's probably not worth giving out delegations on 4.0 write or create
>    opens.
> 
>    Reported-by: Chuck Lever <chuck.lever@oracle.com>
>    Signed-off-by: J. Bruce Fields <bfields@redhat.com>
> 
> diff --git a/fs/nfsd/nfs4state.c b/fs/nfsd/nfs4state.c
> index fdba971d06c3..0d51d1751592 100644
> --- a/fs/nfsd/nfs4state.c
> +++ b/fs/nfsd/nfs4state.c
> @@ -5096,6 +5096,19 @@ nfs4_open_delegation(struct svc_fh *fh, struct nfsd4_open *open,
> 				goto out_no_deleg;
> 			if (!cb_up || !(oo->oo_flags & NFS4_OO_CONFIRMED))
> 				goto out_no_deleg;
> +			if (clp->cl_minorversion)
> +				break;
> +			/*
> +			 * In the absence of sessions, most operations
> +			 * that modify metadata (like setattr) can't
> +			 * be linked to the client sending them, so
> +			 * will result in a delegation break.  That's
> +			 * especially likely for write and create opens:
> +			 */
> +			if (open->op_share_access & NFS4_SHARE_ACCESS_WRITE)
> +				goto out_no_deleg;
> +			if (open->op_create == NFS4_OPEN_CREATE)
> +				goto out_no_deleg;
> 			break;
> 		default:
> 			goto out_no_deleg;

Roughly the same result with this patch as with the first one. The
first one is a little better. Plus, I think the Solaris NFS server
hands out write delegations on v4.0, and I haven't heard of a
significant issue there. It's heuristics may be different, though.

So, it might be that NFSv4.0 has always run significantly slower. I
will have to try a v5.4 or older server to see.

Also, instead of timing, I should count forward channel RPCs and
callbacks, or perhaps the number of DELAY responses.

Don't touch that dial!


--
Chuck Lever

Re: still seeing single client NFS4ERR_DELAY / CB_RECALL

[Bruce Fields]

On Mon, Aug 10, 2020 at 04:01:00PM -0400, Chuck Lever wrote:
> Roughly the same result with this patch as with the first one. The
> first one is a little better. Plus, I think the Solaris NFS server
> hands out write delegations on v4.0, and I haven't heard of a
> significant issue there. It's heuristics may be different, though.
> 
> So, it might be that NFSv4.0 has always run significantly slower. I
> will have to try a v5.4 or older server to see.

Oh, OK, I was assuming this was a regression.

> Also, instead of timing, I should count forward channel RPCs and
> callbacks, or perhaps the number of DELAY responses.

Thanks for looking into this!

--b.

Re: still seeing single client NFS4ERR_DELAY / CB_RECALL

[Chuck Lever]

> On Aug 10, 2020, at 4:10 PM, Bruce Fields <bfields@fieldses.org> wrote:
> 
> On Mon, Aug 10, 2020 at 04:01:00PM -0400, Chuck Lever wrote:
>> Roughly the same result with this patch as with the first one. The
>> first one is a little better. Plus, I think the Solaris NFS server
>> hands out write delegations on v4.0, and I haven't heard of a
>> significant issue there. It's heuristics may be different, though.
>> 
>> So, it might be that NFSv4.0 has always run significantly slower. I
>> will have to try a v5.4 or older server to see.
> 
> Oh, OK, I was assuming this was a regression.

Me too. Looks like it is: NFSv4.0 always runs slower, but I see
it get significantly worse between v5.4 and 5.5. I will post more
quantified results soon.


--
Chuck Lever

Re: still seeing single client NFS4ERR_DELAY / CB_RECALL

[Chuck Lever]

Hi Bruce-

> On Aug 11, 2020, at 9:31 AM, Chuck Lever <chuck.lever@oracle.com> wrote:
> 
>> On Aug 10, 2020, at 4:10 PM, Bruce Fields <bfields@fieldses.org> wrote:
>> 
>> On Mon, Aug 10, 2020 at 04:01:00PM -0400, Chuck Lever wrote:
>>> Roughly the same result with this patch as with the first one. The
>>> first one is a little better. Plus, I think the Solaris NFS server
>>> hands out write delegations on v4.0, and I haven't heard of a
>>> significant issue there. It's heuristics may be different, though.
>>> 
>>> So, it might be that NFSv4.0 has always run significantly slower. I
>>> will have to try a v5.4 or older server to see.
>> 
>> Oh, OK, I was assuming this was a regression.
> 
> Me too. Looks like it is: NFSv4.0 always runs slower, but I see
> it get significantly worse between v5.4 and 5.5. I will post more
> quantified results soon.

It took me a while to get plausible bisection results. The problem
appears in the midst of the NFSD filecache patches merged in v5.4.

In order of application:

5920afa3c85f ("nfsd: hook nfsd_commit up to the nfsd_file cache")
961.68user 5252.40system 20:12.30elapsed 512%CPU, 2541 DELAY errors
These results are similar to v5.3.

fd4f83fd7dfb ("nfsd: convert nfs4_file->fi_fds array to use nfsd_files")
Does not build

eb82dd393744 ("nfsd: convert fi_deleg_file and ls_file fields to nfsd_file")
966.92user 5425.47system 33:52.79elapsed 314%CPU, 1330 DELAY errors

Can you take a look and see if there's anything obvious?


--
Chuck Lever

Re: still seeing single client NFS4ERR_DELAY / CB_RECALL

[Bruce Fields]

On Sun, Aug 16, 2020 at 04:46:00PM -0400, Chuck Lever wrote:
> Hi Bruce-
> 
> > On Aug 11, 2020, at 9:31 AM, Chuck Lever <chuck.lever@oracle.com> wrote:
> > 
> >> On Aug 10, 2020, at 4:10 PM, Bruce Fields <bfields@fieldses.org> wrote:
> >> 
> >> On Mon, Aug 10, 2020 at 04:01:00PM -0400, Chuck Lever wrote:
> >>> Roughly the same result with this patch as with the first one. The
> >>> first one is a little better. Plus, I think the Solaris NFS server
> >>> hands out write delegations on v4.0, and I haven't heard of a
> >>> significant issue there. It's heuristics may be different, though.
> >>> 
> >>> So, it might be that NFSv4.0 has always run significantly slower. I
> >>> will have to try a v5.4 or older server to see.
> >> 
> >> Oh, OK, I was assuming this was a regression.
> > 
> > Me too. Looks like it is: NFSv4.0 always runs slower, but I see
> > it get significantly worse between v5.4 and 5.5. I will post more
> > quantified results soon.
> 
> It took me a while to get plausible bisection results. The problem
> appears in the midst of the NFSD filecache patches merged in v5.4.

Well, that's interesting.

> In order of application:
> 
> 5920afa3c85f ("nfsd: hook nfsd_commit up to the nfsd_file cache")
> 961.68user 5252.40system 20:12.30elapsed 512%CPU, 2541 DELAY errors
> These results are similar to v5.3.
> 
> fd4f83fd7dfb ("nfsd: convert nfs4_file->fi_fds array to use nfsd_files")
> Does not build
> 
> eb82dd393744 ("nfsd: convert fi_deleg_file and ls_file fields to nfsd_file")
> 966.92user 5425.47system 33:52.79elapsed 314%CPU, 1330 DELAY errors
> 
> Can you take a look and see if there's anything obvious?

Unfortunately nothing about the file cache code is very obvious to me.
I'm looking at it....

It adds some new nfserr_jukebox returns in nfsd_file_acquire.  Those
mostly look like kmalloc failures, the one I'm not sure about is the
NFSD_FILE_HASHED check.

Or maybe it's the lease break there.

--b.

Re: still seeing single client NFS4ERR_DELAY / CB_RECALL

[Chuck Lever]

> On Aug 17, 2020, at 6:20 PM, Bruce Fields <bfields@fieldses.org> wrote:
> 
> On Sun, Aug 16, 2020 at 04:46:00PM -0400, Chuck Lever wrote:
>> Hi Bruce-
>> 
>>> On Aug 11, 2020, at 9:31 AM, Chuck Lever <chuck.lever@oracle.com> wrote:
>>> 
>>>> On Aug 10, 2020, at 4:10 PM, Bruce Fields <bfields@fieldses.org> wrote:
>>>> 
>>>> On Mon, Aug 10, 2020 at 04:01:00PM -0400, Chuck Lever wrote:
>>>>> Roughly the same result with this patch as with the first one. The
>>>>> first one is a little better. Plus, I think the Solaris NFS server
>>>>> hands out write delegations on v4.0, and I haven't heard of a
>>>>> significant issue there. It's heuristics may be different, though.
>>>>> 
>>>>> So, it might be that NFSv4.0 has always run significantly slower. I
>>>>> will have to try a v5.4 or older server to see.
>>>> 
>>>> Oh, OK, I was assuming this was a regression.
>>> 
>>> Me too. Looks like it is: NFSv4.0 always runs slower, but I see
>>> it get significantly worse between v5.4 and 5.5. I will post more
>>> quantified results soon.
>> 
>> It took me a while to get plausible bisection results. The problem
>> appears in the midst of the NFSD filecache patches merged in v5.4.
> 
> Well, that's interesting.
> 
>> In order of application:
>> 
>> 5920afa3c85f ("nfsd: hook nfsd_commit up to the nfsd_file cache")
>> 961.68user 5252.40system 20:12.30elapsed 512%CPU, 2541 DELAY errors
>> These results are similar to v5.3.
>> 
>> fd4f83fd7dfb ("nfsd: convert nfs4_file->fi_fds array to use nfsd_files")
>> Does not build

Quick follow-up:

I reverted a couple of hunks that appear to be for the next commit,
and fd4f83fd7dfb builds now. Tested, and this is the bad commit (where
the performance regression starts).


>> eb82dd393744 ("nfsd: convert fi_deleg_file and ls_file fields to nfsd_file")
>> 966.92user 5425.47system 33:52.79elapsed 314%CPU, 1330 DELAY errors
>> 
>> Can you take a look and see if there's anything obvious?
> 
> Unfortunately nothing about the file cache code is very obvious to me.
> I'm looking at it....
> 
> It adds some new nfserr_jukebox returns in nfsd_file_acquire.  Those
> mostly look like kmalloc failures, the one I'm not sure about is the
> NFSD_FILE_HASHED check.
> 
> Or maybe it's the lease break there.
> 
> --b.

--
Chuck Lever

Re: still seeing single client NFS4ERR_DELAY / CB_RECALL

[Chuck Lever]

> On Aug 17, 2020, at 6:20 PM, Bruce Fields <bfields@fieldses.org> wrote:
> 
> On Sun, Aug 16, 2020 at 04:46:00PM -0400, Chuck Lever wrote:
> 
>> In order of application:
>> 
>> 5920afa3c85f ("nfsd: hook nfsd_commit up to the nfsd_file cache")
>> 961.68user 5252.40system 20:12.30elapsed 512%CPU, 2541 DELAY errors
>> These results are similar to v5.3.
>> 
>> fd4f83fd7dfb ("nfsd: convert nfs4_file->fi_fds array to use nfsd_files")
>> Does not build
>> 
>> eb82dd393744 ("nfsd: convert fi_deleg_file and ls_file fields to nfsd_file")
>> 966.92user 5425.47system 33:52.79elapsed 314%CPU, 1330 DELAY errors
>> 
>> Can you take a look and see if there's anything obvious?
> 
> Unfortunately nothing about the file cache code is very obvious to me.
> I'm looking at it....
> 
> It adds some new nfserr_jukebox returns in nfsd_file_acquire.  Those
> mostly look like kmalloc failures, the one I'm not sure about is the
> NFSD_FILE_HASHED check.
> 
> Or maybe it's the lease break there.

nfsd_file_acquire() always calls fh_verify() before it invokes nfsd_open().
Replacing nfs4_get_vfs_file's nfsd_open() call with nfsd_file_acquire() adds
almost 10 million fh_verify() calls to my test run.

On my server, fh_verify() is quite expensive. Most of the cost is in the
prepare_creds() call.

--
Chuck Lever

Re: still seeing single client NFS4ERR_DELAY / CB_RECALL

[Bruce Fields]

On Tue, Aug 18, 2020 at 05:26:26PM -0400, Chuck Lever wrote:
> 
> > On Aug 17, 2020, at 6:20 PM, Bruce Fields <bfields@fieldses.org> wrote:
> > 
> > On Sun, Aug 16, 2020 at 04:46:00PM -0400, Chuck Lever wrote:
> > 
> >> In order of application:
> >> 
> >> 5920afa3c85f ("nfsd: hook nfsd_commit up to the nfsd_file cache")
> >> 961.68user 5252.40system 20:12.30elapsed 512%CPU, 2541 DELAY errors
> >> These results are similar to v5.3.
> >> 
> >> fd4f83fd7dfb ("nfsd: convert nfs4_file->fi_fds array to use nfsd_files")
> >> Does not build
> >> 
> >> eb82dd393744 ("nfsd: convert fi_deleg_file and ls_file fields to nfsd_file")
> >> 966.92user 5425.47system 33:52.79elapsed 314%CPU, 1330 DELAY errors
> >> 
> >> Can you take a look and see if there's anything obvious?
> > 
> > Unfortunately nothing about the file cache code is very obvious to me.
> > I'm looking at it....
> > 
> > It adds some new nfserr_jukebox returns in nfsd_file_acquire.  Those
> > mostly look like kmalloc failures, the one I'm not sure about is the
> > NFSD_FILE_HASHED check.
> > 
> > Or maybe it's the lease break there.
> 
> nfsd_file_acquire() always calls fh_verify() before it invokes nfsd_open().
> Replacing nfs4_get_vfs_file's nfsd_open() call with nfsd_file_acquire() adds
> almost 10 million fh_verify() calls to my test run.
> 
> On my server, fh_verify() is quite expensive. Most of the cost is in the
> prepare_creds() call.

Huh, interesting.

So you no longer think there's a difference in NFS4ERR_DELAY returns
before and after?


--b.

Re: still seeing single client NFS4ERR_DELAY / CB_RECALL

[Chuck Lever]

> On Aug 18, 2020, at 5:49 PM, Bruce Fields <bfields@fieldses.org> wrote:
> 
> On Tue, Aug 18, 2020 at 05:26:26PM -0400, Chuck Lever wrote:
>> 
>>> On Aug 17, 2020, at 6:20 PM, Bruce Fields <bfields@fieldses.org> wrote:
>>> 
>>> On Sun, Aug 16, 2020 at 04:46:00PM -0400, Chuck Lever wrote:
>>> 
>>>> In order of application:
>>>> 
>>>> 5920afa3c85f ("nfsd: hook nfsd_commit up to the nfsd_file cache")
>>>> 961.68user 5252.40system 20:12.30elapsed 512%CPU, 2541 DELAY errors
>>>> These results are similar to v5.3.
>>>> 
>>>> fd4f83fd7dfb ("nfsd: convert nfs4_file->fi_fds array to use nfsd_files")
>>>> Does not build
>>>> 
>>>> eb82dd393744 ("nfsd: convert fi_deleg_file and ls_file fields to nfsd_file")
>>>> 966.92user 5425.47system 33:52.79elapsed 314%CPU, 1330 DELAY errors
>>>> 
>>>> Can you take a look and see if there's anything obvious?
>>> 
>>> Unfortunately nothing about the file cache code is very obvious to me.
>>> I'm looking at it....
>>> 
>>> It adds some new nfserr_jukebox returns in nfsd_file_acquire.  Those
>>> mostly look like kmalloc failures, the one I'm not sure about is the
>>> NFSD_FILE_HASHED check.
>>> 
>>> Or maybe it's the lease break there.
>> 
>> nfsd_file_acquire() always calls fh_verify() before it invokes nfsd_open().
>> Replacing nfs4_get_vfs_file's nfsd_open() call with nfsd_file_acquire() adds
>> almost 10 million fh_verify() calls to my test run.

More context for this number is in the raw data:

Before: 15,742,399 calls to fh_verify() on 5,575,986 RPCs or 2.8 per RPC
After: 24,857,521 calls to fh_verify() on 7,684,320 RPCs or 3.2 per PRC

That commit results in more RPCs and more fh_verify calls per RPC. Not
a benign change for NFSv4.0.


>> On my server, fh_verify() is quite expensive. Most of the cost is in the
>> prepare_creds() call.
> 
> Huh, interesting.
> 
> So you no longer think there's a difference in NFS4ERR_DELAY returns
> before and after?

There's a difference. With the bad commit, the number of DELAY errors drops
by half.

Before: 2541 DELAY errors
After: 1330 DELAY errors

However, sometime after the bad commit, the number of DELAY errors during
the test goes back up to about 2700, but the elapsed time doesn't change.
The data suggests that the count of DELAY errors does not impact the
overall throughput of the test.


--
Chuck Lever

Re: still seeing single client NFS4ERR_DELAY / CB_RECALL

[Bruce Fields]

On Tue, Aug 18, 2020 at 05:26:26PM -0400, Chuck Lever wrote:
> 
> > On Aug 17, 2020, at 6:20 PM, Bruce Fields <bfields@fieldses.org> wrote:
> > 
> > On Sun, Aug 16, 2020 at 04:46:00PM -0400, Chuck Lever wrote:
> > 
> >> In order of application:
> >> 
> >> 5920afa3c85f ("nfsd: hook nfsd_commit up to the nfsd_file cache")
> >> 961.68user 5252.40system 20:12.30elapsed 512%CPU, 2541 DELAY errors
> >> These results are similar to v5.3.
> >> 
> >> fd4f83fd7dfb ("nfsd: convert nfs4_file->fi_fds array to use nfsd_files")
> >> Does not build
> >> 
> >> eb82dd393744 ("nfsd: convert fi_deleg_file and ls_file fields to nfsd_file")
> >> 966.92user 5425.47system 33:52.79elapsed 314%CPU, 1330 DELAY errors
> >> 
> >> Can you take a look and see if there's anything obvious?
> > 
> > Unfortunately nothing about the file cache code is very obvious to me.
> > I'm looking at it....
> > 
> > It adds some new nfserr_jukebox returns in nfsd_file_acquire.  Those
> > mostly look like kmalloc failures, the one I'm not sure about is the
> > NFSD_FILE_HASHED check.
> > 
> > Or maybe it's the lease break there.
> 
> nfsd_file_acquire() always calls fh_verify() before it invokes nfsd_open().
> Replacing nfs4_get_vfs_file's nfsd_open() call with nfsd_file_acquire() adds
> almost 10 million fh_verify() calls to my test run.

Checking out the code as of fd4f83fd7dfb....

nfsd_file_acquire() calls nfsd_open_verified().

And nfsd_open() is basically just fh_verify()+nfsd_open_verified().

So it doesn't look like the replacement of nfsd_open() by
nfsd_file_acquire() should have changed the number of fh_verify() calls.

--b.

> 
> On my server, fh_verify() is quite expensive. Most of the cost is in the
> prepare_creds() call.
> 
> --
> Chuck Lever
> 
> 

Re: still seeing single client NFS4ERR_DELAY / CB_RECALL

[Chuck Lever]

> On Aug 19, 2020, at 5:29 PM, Bruce Fields <bfields@fieldses.org> wrote:
> 
> On Tue, Aug 18, 2020 at 05:26:26PM -0400, Chuck Lever wrote:
>> 
>>> On Aug 17, 2020, at 6:20 PM, Bruce Fields <bfields@fieldses.org> wrote:
>>> 
>>> On Sun, Aug 16, 2020 at 04:46:00PM -0400, Chuck Lever wrote:
>>> 
>>>> In order of application:
>>>> 
>>>> 5920afa3c85f ("nfsd: hook nfsd_commit up to the nfsd_file cache")
>>>> 961.68user 5252.40system 20:12.30elapsed 512%CPU, 2541 DELAY errors
>>>> These results are similar to v5.3.
>>>> 
>>>> fd4f83fd7dfb ("nfsd: convert nfs4_file->fi_fds array to use nfsd_files")
>>>> Does not build
>>>> 
>>>> eb82dd393744 ("nfsd: convert fi_deleg_file and ls_file fields to nfsd_file")
>>>> 966.92user 5425.47system 33:52.79elapsed 314%CPU, 1330 DELAY errors
>>>> 
>>>> Can you take a look and see if there's anything obvious?
>>> 
>>> Unfortunately nothing about the file cache code is very obvious to me.
>>> I'm looking at it....
>>> 
>>> It adds some new nfserr_jukebox returns in nfsd_file_acquire.  Those
>>> mostly look like kmalloc failures, the one I'm not sure about is the
>>> NFSD_FILE_HASHED check.
>>> 
>>> Or maybe it's the lease break there.
>> 
>> nfsd_file_acquire() always calls fh_verify() before it invokes nfsd_open().
>> Replacing nfs4_get_vfs_file's nfsd_open() call with nfsd_file_acquire() adds
>> almost 10 million fh_verify() calls to my test run.
> 
> Checking out the code as of fd4f83fd7dfb....
> 
> nfsd_file_acquire() calls nfsd_open_verified().
> 
> And nfsd_open() is basically just fh_verify()+nfsd_open_verified().
> 
> So it doesn't look like the replacement of nfsd_open() by
> nfsd_file_acquire() should have changed the number of fh_verify() calls.

Agreed, the increase is a little mysterious.


> --b.
> 
>> 
>> On my server, fh_verify() is quite expensive. Most of the cost is in the
>> prepare_creds() call.

--
Chuck Lever

Re: still seeing single client NFS4ERR_DELAY / CB_RECALL

[Chuck Lever]

> On Aug 19, 2020, at 5:29 PM, Bruce Fields <bfields@fieldses.org> wrote:
> 
> On Tue, Aug 18, 2020 at 05:26:26PM -0400, Chuck Lever wrote:
>> 
>>> On Aug 17, 2020, at 6:20 PM, Bruce Fields <bfields@fieldses.org> wrote:
>>> 
>>> On Sun, Aug 16, 2020 at 04:46:00PM -0400, Chuck Lever wrote:
>>> 
>>>> In order of application:
>>>> 
>>>> 5920afa3c85f ("nfsd: hook nfsd_commit up to the nfsd_file cache")
>>>> 961.68user 5252.40system 20:12.30elapsed 512%CPU, 2541 DELAY errors
>>>> These results are similar to v5.3.
>>>> 
>>>> fd4f83fd7dfb ("nfsd: convert nfs4_file->fi_fds array to use nfsd_files")
>>>> Does not build
>>>> 
>>>> eb82dd393744 ("nfsd: convert fi_deleg_file and ls_file fields to nfsd_file")
>>>> 966.92user 5425.47system 33:52.79elapsed 314%CPU, 1330 DELAY errors
>>>> 
>>>> Can you take a look and see if there's anything obvious?
>>> 
>>> Unfortunately nothing about the file cache code is very obvious to me.
>>> I'm looking at it....
>>> 
>>> It adds some new nfserr_jukebox returns in nfsd_file_acquire.  Those
>>> mostly look like kmalloc failures, the one I'm not sure about is the
>>> NFSD_FILE_HASHED check.
>>> 
>>> Or maybe it's the lease break there.
>> 
>> nfsd_file_acquire() always calls fh_verify() before it invokes nfsd_open().
>> Replacing nfs4_get_vfs_file's nfsd_open() call with nfsd_file_acquire() adds
>> almost 10 million fh_verify() calls to my test run.
> 
> Checking out the code as of fd4f83fd7dfb....
> 
> nfsd_file_acquire() calls nfsd_open_verified().
> 
> And nfsd_open() is basically just fh_verify()+nfsd_open_verified().
> 
> So it doesn't look like the replacement of nfsd_open() by
> nfsd_file_acquire() should have changed the number of fh_verify() calls.

I see a lot more vfs_setlease() failures after fd4f83fd7dfb.
check_conflicting_open() fails because "inode is open for write":

1780         if (arg == F_RDLCK)
1781                 return inode_is_open_for_write(inode) ? -EAGAIN : 0;

The behavior on the wire is that the server simply doesn't hand out
many delegations.

NFSv4 OPEN uses nfsd_file_acquire() now, but I don't see CLOSE
releasing the cached file descriptor. Wouldn't that cached
descriptor conflict with subsequent OPENs?


--
Chuck Lever

Re: still seeing single client NFS4ERR_DELAY / CB_RECALL

[Bruce Fields]

On Mon, Aug 24, 2020 at 09:39:31AM -0400, Chuck Lever wrote:
> 
> 
> > On Aug 19, 2020, at 5:29 PM, Bruce Fields <bfields@fieldses.org> wrote:
> > 
> > On Tue, Aug 18, 2020 at 05:26:26PM -0400, Chuck Lever wrote:
> >> 
> >>> On Aug 17, 2020, at 6:20 PM, Bruce Fields <bfields@fieldses.org> wrote:
> >>> 
> >>> On Sun, Aug 16, 2020 at 04:46:00PM -0400, Chuck Lever wrote:
> >>> 
> >>>> In order of application:
> >>>> 
> >>>> 5920afa3c85f ("nfsd: hook nfsd_commit up to the nfsd_file cache")
> >>>> 961.68user 5252.40system 20:12.30elapsed 512%CPU, 2541 DELAY errors
> >>>> These results are similar to v5.3.
> >>>> 
> >>>> fd4f83fd7dfb ("nfsd: convert nfs4_file->fi_fds array to use nfsd_files")
> >>>> Does not build
> >>>> 
> >>>> eb82dd393744 ("nfsd: convert fi_deleg_file and ls_file fields to nfsd_file")
> >>>> 966.92user 5425.47system 33:52.79elapsed 314%CPU, 1330 DELAY errors
> >>>> 
> >>>> Can you take a look and see if there's anything obvious?
> >>> 
> >>> Unfortunately nothing about the file cache code is very obvious to me.
> >>> I'm looking at it....
> >>> 
> >>> It adds some new nfserr_jukebox returns in nfsd_file_acquire.  Those
> >>> mostly look like kmalloc failures, the one I'm not sure about is the
> >>> NFSD_FILE_HASHED check.
> >>> 
> >>> Or maybe it's the lease break there.
> >> 
> >> nfsd_file_acquire() always calls fh_verify() before it invokes nfsd_open().
> >> Replacing nfs4_get_vfs_file's nfsd_open() call with nfsd_file_acquire() adds
> >> almost 10 million fh_verify() calls to my test run.
> > 
> > Checking out the code as of fd4f83fd7dfb....
> > 
> > nfsd_file_acquire() calls nfsd_open_verified().
> > 
> > And nfsd_open() is basically just fh_verify()+nfsd_open_verified().
> > 
> > So it doesn't look like the replacement of nfsd_open() by
> > nfsd_file_acquire() should have changed the number of fh_verify() calls.
> 
> I see a lot more vfs_setlease() failures after fd4f83fd7dfb.
> check_conflicting_open() fails because "inode is open for write":
> 
> 1780         if (arg == F_RDLCK)
> 1781                 return inode_is_open_for_write(inode) ? -EAGAIN : 0;
> 
> The behavior on the wire is that the server simply doesn't hand out
> many delegations.
> 
> NFSv4 OPEN uses nfsd_file_acquire() now, but I don't see CLOSE
> releasing the cached file descriptor. Wouldn't that cached
> descriptor conflict with subsequent OPENs?

Could be, yes.

That also reminds me of this patch, did I already send it to you?

--b.

commit 055e7b94ef32
Author: J. Bruce Fields <bfields@redhat.com>
Date:   Fri Jul 17 18:54:54 2020 -0400

    nfsd: Cache R, RW, and W opens separately
    
    The nfsd open code has always kept separate read-only, read-write, and
    write-only opens as necessary to ensure that when a client closes or
    downgrades, we don't retain more access than necessary.
    
    Honestly, I'm not sure if that's completely necessary, but I'd rather
    stick to that behavior.
    
    Signed-off-by: J. Bruce Fields <bfields@redhat.com>

diff --git a/fs/nfsd/filecache.c b/fs/nfsd/filecache.c
index 82198d747c4c..4b6f70e0d987 100644
--- a/fs/nfsd/filecache.c
+++ b/fs/nfsd/filecache.c
@@ -891,7 +891,7 @@ nfsd_file_find_locked(struct inode *inode, unsigned int may_flags,
 
 	hlist_for_each_entry_rcu(nf, &nfsd_file_hashtbl[hashval].nfb_head,
 				 nf_node, lockdep_is_held(&nfsd_file_hashtbl[hashval].nfb_lock)) {
-		if ((need & nf->nf_may) != need)
+		if (nf->nf_may != need)
 			continue;
 		if (nf->nf_inode != inode)
 			continue;

Re: still seeing single client NFS4ERR_DELAY / CB_RECALL

[Chuck Lever]

> On Aug 24, 2020, at 10:22 AM, Bruce Fields <bfields@fieldses.org> wrote:
> 
> On Mon, Aug 24, 2020 at 09:39:31AM -0400, Chuck Lever wrote:
>> 
>> 
>>> On Aug 19, 2020, at 5:29 PM, Bruce Fields <bfields@fieldses.org> wrote:
>>> 
>>> On Tue, Aug 18, 2020 at 05:26:26PM -0400, Chuck Lever wrote:
>>>> 
>>>>> On Aug 17, 2020, at 6:20 PM, Bruce Fields <bfields@fieldses.org> wrote:
>>>>> 
>>>>> On Sun, Aug 16, 2020 at 04:46:00PM -0400, Chuck Lever wrote:
>>>>> 
>>>>>> In order of application:
>>>>>> 
>>>>>> 5920afa3c85f ("nfsd: hook nfsd_commit up to the nfsd_file cache")
>>>>>> 961.68user 5252.40system 20:12.30elapsed 512%CPU, 2541 DELAY errors
>>>>>> These results are similar to v5.3.
>>>>>> 
>>>>>> fd4f83fd7dfb ("nfsd: convert nfs4_file->fi_fds array to use nfsd_files")
>>>>>> Does not build
>>>>>> 
>>>>>> eb82dd393744 ("nfsd: convert fi_deleg_file and ls_file fields to nfsd_file")
>>>>>> 966.92user 5425.47system 33:52.79elapsed 314%CPU, 1330 DELAY errors
>>>>>> 
>>>>>> Can you take a look and see if there's anything obvious?
>>>>> 
>>>>> Unfortunately nothing about the file cache code is very obvious to me.
>>>>> I'm looking at it....
>>>>> 
>>>>> It adds some new nfserr_jukebox returns in nfsd_file_acquire.  Those
>>>>> mostly look like kmalloc failures, the one I'm not sure about is the
>>>>> NFSD_FILE_HASHED check.
>>>>> 
>>>>> Or maybe it's the lease break there.
>>>> 
>>>> nfsd_file_acquire() always calls fh_verify() before it invokes nfsd_open().
>>>> Replacing nfs4_get_vfs_file's nfsd_open() call with nfsd_file_acquire() adds
>>>> almost 10 million fh_verify() calls to my test run.
>>> 
>>> Checking out the code as of fd4f83fd7dfb....
>>> 
>>> nfsd_file_acquire() calls nfsd_open_verified().
>>> 
>>> And nfsd_open() is basically just fh_verify()+nfsd_open_verified().
>>> 
>>> So it doesn't look like the replacement of nfsd_open() by
>>> nfsd_file_acquire() should have changed the number of fh_verify() calls.
>> 
>> I see a lot more vfs_setlease() failures after fd4f83fd7dfb.
>> check_conflicting_open() fails because "inode is open for write":
>> 
>> 1780         if (arg == F_RDLCK)
>> 1781                 return inode_is_open_for_write(inode) ? -EAGAIN : 0;
>> 
>> The behavior on the wire is that the server simply doesn't hand out
>> many delegations.
>> 
>> NFSv4 OPEN uses nfsd_file_acquire() now, but I don't see CLOSE
>> releasing the cached file descriptor. Wouldn't that cached
>> descriptor conflict with subsequent OPENs?
> 
> Could be, yes.
> 
> That also reminds me of this patch, did I already send it to you?

I don't have this one. I can try it.


> --b.
> 
> commit 055e7b94ef32
> Author: J. Bruce Fields <bfields@redhat.com>
> Date:   Fri Jul 17 18:54:54 2020 -0400
> 
>    nfsd: Cache R, RW, and W opens separately
> 
>    The nfsd open code has always kept separate read-only, read-write, and
>    write-only opens as necessary to ensure that when a client closes or
>    downgrades, we don't retain more access than necessary.
> 
>    Honestly, I'm not sure if that's completely necessary, but I'd rather
>    stick to that behavior.
> 
>    Signed-off-by: J. Bruce Fields <bfields@redhat.com>
> 
> diff --git a/fs/nfsd/filecache.c b/fs/nfsd/filecache.c
> index 82198d747c4c..4b6f70e0d987 100644
> --- a/fs/nfsd/filecache.c
> +++ b/fs/nfsd/filecache.c
> @@ -891,7 +891,7 @@ nfsd_file_find_locked(struct inode *inode, unsigned int may_flags,
> 
> 	hlist_for_each_entry_rcu(nf, &nfsd_file_hashtbl[hashval].nfb_head,
> 				 nf_node, lockdep_is_held(&nfsd_file_hashtbl[hashval].nfb_lock)) {
> -		if ((need & nf->nf_may) != need)
> +		if (nf->nf_may != need)
> 			continue;
> 		if (nf->nf_inode != inode)
> 			continue;

--
Chuck Lever

Re: still seeing single client NFS4ERR_DELAY / CB_RECALL

[Bruce Fields]

On Mon, Aug 24, 2020 at 11:42:18AM -0400, Chuck Lever wrote:
> 
> 
> > On Aug 24, 2020, at 10:22 AM, Bruce Fields <bfields@fieldses.org> wrote:
> > 
> > On Mon, Aug 24, 2020 at 09:39:31AM -0400, Chuck Lever wrote:
> >> 
> >> 
> >>> On Aug 19, 2020, at 5:29 PM, Bruce Fields <bfields@fieldses.org> wrote:
> >>> 
> >>> On Tue, Aug 18, 2020 at 05:26:26PM -0400, Chuck Lever wrote:
> >>>> 
> >>>>> On Aug 17, 2020, at 6:20 PM, Bruce Fields <bfields@fieldses.org> wrote:
> >>>>> 
> >>>>> On Sun, Aug 16, 2020 at 04:46:00PM -0400, Chuck Lever wrote:
> >>>>> 
> >>>>>> In order of application:
> >>>>>> 
> >>>>>> 5920afa3c85f ("nfsd: hook nfsd_commit up to the nfsd_file cache")
> >>>>>> 961.68user 5252.40system 20:12.30elapsed 512%CPU, 2541 DELAY errors
> >>>>>> These results are similar to v5.3.
> >>>>>> 
> >>>>>> fd4f83fd7dfb ("nfsd: convert nfs4_file->fi_fds array to use nfsd_files")
> >>>>>> Does not build
> >>>>>> 
> >>>>>> eb82dd393744 ("nfsd: convert fi_deleg_file and ls_file fields to nfsd_file")
> >>>>>> 966.92user 5425.47system 33:52.79elapsed 314%CPU, 1330 DELAY errors
> >>>>>> 
> >>>>>> Can you take a look and see if there's anything obvious?
> >>>>> 
> >>>>> Unfortunately nothing about the file cache code is very obvious to me.
> >>>>> I'm looking at it....
> >>>>> 
> >>>>> It adds some new nfserr_jukebox returns in nfsd_file_acquire.  Those
> >>>>> mostly look like kmalloc failures, the one I'm not sure about is the
> >>>>> NFSD_FILE_HASHED check.
> >>>>> 
> >>>>> Or maybe it's the lease break there.
> >>>> 
> >>>> nfsd_file_acquire() always calls fh_verify() before it invokes nfsd_open().
> >>>> Replacing nfs4_get_vfs_file's nfsd_open() call with nfsd_file_acquire() adds
> >>>> almost 10 million fh_verify() calls to my test run.
> >>> 
> >>> Checking out the code as of fd4f83fd7dfb....
> >>> 
> >>> nfsd_file_acquire() calls nfsd_open_verified().
> >>> 
> >>> And nfsd_open() is basically just fh_verify()+nfsd_open_verified().
> >>> 
> >>> So it doesn't look like the replacement of nfsd_open() by
> >>> nfsd_file_acquire() should have changed the number of fh_verify() calls.
> >> 
> >> I see a lot more vfs_setlease() failures after fd4f83fd7dfb.
> >> check_conflicting_open() fails because "inode is open for write":
> >> 
> >> 1780         if (arg == F_RDLCK)
> >> 1781                 return inode_is_open_for_write(inode) ? -EAGAIN : 0;
> >> 
> >> The behavior on the wire is that the server simply doesn't hand out
> >> many delegations.
> >> 
> >> NFSv4 OPEN uses nfsd_file_acquire() now, but I don't see CLOSE
> >> releasing the cached file descriptor. Wouldn't that cached
> >> descriptor conflict with subsequent OPENs?
> > 
> > Could be, yes.
> > 
> > That also reminds me of this patch, did I already send it to you?
> 
> I don't have this one. I can try it.

No difference, I take it?

There could also be something wrong with nfsd4_check_conflicting_opens()
that's preventing delegations when it shouldn't.

There might also be some way fh_verify() could be smarter.  There's a
big comment there explaining why we repeat the permission checks each
time, but maybe we could keep a flag somewhere that tracks whether we
really need to call nfsd_setuser again.

Based on your and Frank's experiences I'm also sympathetic to the idea
that maybe the filehandle cache just gets in the way in the v4 case.

--b.

> > Author: J. Bruce Fields <bfields@redhat.com>
> > Date:   Fri Jul 17 18:54:54 2020 -0400
> > 
> >    nfsd: Cache R, RW, and W opens separately
> > 
> >    The nfsd open code has always kept separate read-only, read-write, and
> >    write-only opens as necessary to ensure that when a client closes or
> >    downgrades, we don't retain more access than necessary.
> > 
> >    Honestly, I'm not sure if that's completely necessary, but I'd rather
> >    stick to that behavior.
> > 
> >    Signed-off-by: J. Bruce Fields <bfields@redhat.com>
> > 
> > diff --git a/fs/nfsd/filecache.c b/fs/nfsd/filecache.c
> > index 82198d747c4c..4b6f70e0d987 100644
> > --- a/fs/nfsd/filecache.c
> > +++ b/fs/nfsd/filecache.c
> > @@ -891,7 +891,7 @@ nfsd_file_find_locked(struct inode *inode, unsigned int may_flags,
> > 
> > 	hlist_for_each_entry_rcu(nf, &nfsd_file_hashtbl[hashval].nfb_head,
> > 				 nf_node, lockdep_is_held(&nfsd_file_hashtbl[hashval].nfb_lock)) {
> > -		if ((need & nf->nf_may) != need)
> > +		if (nf->nf_may != need)
> > 			continue;
> > 		if (nf->nf_inode != inode)
> > 			continue;
> 
> --
> Chuck Lever
> 
> 

Re: still seeing single client NFS4ERR_DELAY / CB_RECALL

[Chuck Lever]

> On Sep 4, 2020, at 6:01 PM, Bruce Fields <bfields@fieldses.org> wrote:
> 
> On Mon, Aug 24, 2020 at 11:42:18AM -0400, Chuck Lever wrote:
>> 
>> 
>>> On Aug 24, 2020, at 10:22 AM, Bruce Fields <bfields@fieldses.org> wrote:
>>> 
>>> On Mon, Aug 24, 2020 at 09:39:31AM -0400, Chuck Lever wrote:
>>>> 
>>>> 
>>>>> On Aug 19, 2020, at 5:29 PM, Bruce Fields <bfields@fieldses.org> wrote:
>>>>> 
>>>>> On Tue, Aug 18, 2020 at 05:26:26PM -0400, Chuck Lever wrote:
>>>>>> 
>>>>>>> On Aug 17, 2020, at 6:20 PM, Bruce Fields <bfields@fieldses.org> wrote:
>>>>>>> 
>>>>>>> On Sun, Aug 16, 2020 at 04:46:00PM -0400, Chuck Lever wrote:
>>>>>>> 
>>>>>>>> In order of application:
>>>>>>>> 
>>>>>>>> 5920afa3c85f ("nfsd: hook nfsd_commit up to the nfsd_file cache")
>>>>>>>> 961.68user 5252.40system 20:12.30elapsed 512%CPU, 2541 DELAY errors
>>>>>>>> These results are similar to v5.3.
>>>>>>>> 
>>>>>>>> fd4f83fd7dfb ("nfsd: convert nfs4_file->fi_fds array to use nfsd_files")
>>>>>>>> Does not build
>>>>>>>> 
>>>>>>>> eb82dd393744 ("nfsd: convert fi_deleg_file and ls_file fields to nfsd_file")
>>>>>>>> 966.92user 5425.47system 33:52.79elapsed 314%CPU, 1330 DELAY errors
>>>>>>>> 
>>>>>>>> Can you take a look and see if there's anything obvious?
>>>>>>> 
>>>>>>> Unfortunately nothing about the file cache code is very obvious to me.
>>>>>>> I'm looking at it....
>>>>>>> 
>>>>>>> It adds some new nfserr_jukebox returns in nfsd_file_acquire.  Those
>>>>>>> mostly look like kmalloc failures, the one I'm not sure about is the
>>>>>>> NFSD_FILE_HASHED check.
>>>>>>> 
>>>>>>> Or maybe it's the lease break there.
>>>>>> 
>>>>>> nfsd_file_acquire() always calls fh_verify() before it invokes nfsd_open().
>>>>>> Replacing nfs4_get_vfs_file's nfsd_open() call with nfsd_file_acquire() adds
>>>>>> almost 10 million fh_verify() calls to my test run.
>>>>> 
>>>>> Checking out the code as of fd4f83fd7dfb....
>>>>> 
>>>>> nfsd_file_acquire() calls nfsd_open_verified().
>>>>> 
>>>>> And nfsd_open() is basically just fh_verify()+nfsd_open_verified().
>>>>> 
>>>>> So it doesn't look like the replacement of nfsd_open() by
>>>>> nfsd_file_acquire() should have changed the number of fh_verify() calls.
>>>> 
>>>> I see a lot more vfs_setlease() failures after fd4f83fd7dfb.
>>>> check_conflicting_open() fails because "inode is open for write":
>>>> 
>>>> 1780         if (arg == F_RDLCK)
>>>> 1781                 return inode_is_open_for_write(inode) ? -EAGAIN : 0;
>>>> 
>>>> The behavior on the wire is that the server simply doesn't hand out
>>>> many delegations.
>>>> 
>>>> NFSv4 OPEN uses nfsd_file_acquire() now, but I don't see CLOSE
>>>> releasing the cached file descriptor. Wouldn't that cached
>>>> descriptor conflict with subsequent OPENs?
>>> 
>>> Could be, yes.
>>> 
>>> That also reminds me of this patch, did I already send it to you?
>> 
>> I don't have this one. I can try it.
> 
> No difference, I take it?

It helps a little, but it doesn't appear to address the regression.

It does seem like a reasonable change to take anyway. You could
take both of the earlier patches in this thread for v5.10, IMO.


> There could also be something wrong with nfsd4_check_conflicting_opens()
> that's preventing delegations when it shouldn't.

I've added some instrumentation there. It looks like @writes
is still positive because of a previous cached open. The NFS
request stream goes something like this:

OPEN(CREATE) access=WRITE name=yada
WRITE
CLOSE
... here is where the cached WR_ONLY open remains

OPEN(NOCREATE) access=READ name=yada
... conflict detected, no soup for you.

I checked, and before the filecache support was added, the server
does offer a read delegation in this case.


> There might also be some way fh_verify() could be smarter.  There's a
> big comment there explaining why we repeat the permission checks each
> time, but maybe we could keep a flag somewhere that tracks whether we
> really need to call nfsd_setuser again.

I'll have a look at that more closely once we are clear of this
performance regression. The architecture of how fh_verify is
used has been around forever, and it seems like a it's a
separate issue.

I've added some tracepoints that report fh_verify calls and each
change to the current FH. Here's a single OPEN call on the server.
Note the number of fh_verify calls and how long they take
(timestamps are seconds since boot). This is from a single-thread
test on the server, so there's no other activity going on.

6398.079629: nfsd_compound:        xid=0x59f1891e opcnt=5
6398.079632: nfsd_fh_current:      xid=0x59f1891e fh_hash=0x0a393779
6398.079685: nfsd_fh_verify:       xid=0x59f1891e fh_hash=0x0a393779 type=NONE access=BYPASS_GSS status=0
6398.079687: nfsd_compound_status: xid=0x59f1891e op=1/5 OP_PUTFH status=0
6398.079689: nfsd_open_args:       xid=0x59f1891e seqid=12 type=NOCREATE claim=NULL share=READ name=Makefile
6398.079753: nfsd_fh_verify:       xid=0x59f1891e fh_hash=0x0a393779 type=DIR access=EXEC status=0
6398.079789: nfsd_fh_verify:       xid=0x59f1891e fh_hash=0x2c049d00 type=REG access=READ|READ_IF_EXEC status=0
6398.079830: nfsd_fh_verify:       xid=0x59f1891e fh_hash=0x2c049d00 type=REG access=READ|OWNER_OVERRIDE status=0
6398.079833: nfsd_file_acquire:    xid=0x59f1891e hash=0xe28 inode=0xffff88873f4777b0 may_flags=READ ref=2 nf_flags=HASHED|REFERENCED nf_may=READ nf_file=0xffff88872cc53e00 status=0
6398.079868: generic_add_lease:    dev=0x0:0x23 ino=0xe42af wcount=0 rcount=1 icount=2 fl_owner=0xffff88871914cfd8 fl_flags=FL_DELEG fl_type=F_RDLCK
6398.079876: locks_get_lock_context: dev=0x0:0x23 ino=0xe42af type=F_RDLCK ctx=0xffff8886d8a43b58
6398.079881: nfsd_deleg_open:      client 5f529c2f:b9aedadc stateid 002471d9:00000001
6398.079883: nfsd_deleg_none:      client 5f529c2f:b9aedadc stateid 002471d8:00000001
6398.079901: nfsd_fh_current:      xid=0x59f1891e fh_hash=0x2c049d00
6398.079904: nfsd_compound_status: xid=0x59f1891e op=2/5 OP_OPEN status=0
6398.079906: nfsd_compound_status: xid=0x59f1891e op=3/5 OP_GETFH status=0
6398.079941: nfsd_fh_verify:       xid=0x59f1891e fh_hash=0x2c049d00 type=NONE access= status=0
6398.079947: nfsd_compound_status: xid=0x59f1891e op=4/5 OP_ACCESS status=0
6398.079948: nfsd_get_fattr4:      xid=0x59f1891e bm[0]=TYPE|CHANGE|SIZE|FSID|FILEID bm[1]=MODE|NUMLINKS|OWNER|OWNER_GROUP|RAWDEV|SPACE_USED|TIME_ACCESS|TIME_METADATA|TIME_MODIFY|MOUNTED_ON_FILEID bm[2]=
6398.079980: nfsd_fh_verify:       xid=0x59f1891e fh_hash=0x2c049d00 type=NONE access= status=0
6398.079985: nfsd_compound_status: xid=0x59f1891e op=5/5 OP_GETATTR status=0


> Based on your and Frank's experiences I'm also sympathetic to the idea
> that maybe the filehandle cache just gets in the way in the v4 case.

I think it does get in the way for NFSv4. Clearly if there are NFSv3
users, the filecache is a good way to block handing out delegations.

For NFSv4, once there are no clients (or local users) using a file,
the server should be permitted to offer delegations on it. I don't
see any benefit to holding onto file descriptors that clients say
explicitly that they are done using.

My worry is that after the 5 kernel releases since this code went in,
it won't be a simple set of reverts to back out NFSv4 filecache usage.


> --b.
> 
>>> Author: J. Bruce Fields <bfields@redhat.com>
>>> Date:   Fri Jul 17 18:54:54 2020 -0400
>>> 
>>>   nfsd: Cache R, RW, and W opens separately
>>> 
>>>   The nfsd open code has always kept separate read-only, read-write, and
>>>   write-only opens as necessary to ensure that when a client closes or
>>>   downgrades, we don't retain more access than necessary.
>>> 
>>>   Honestly, I'm not sure if that's completely necessary, but I'd rather
>>>   stick to that behavior.
>>> 
>>>   Signed-off-by: J. Bruce Fields <bfields@redhat.com>
>>> 
>>> diff --git a/fs/nfsd/filecache.c b/fs/nfsd/filecache.c
>>> index 82198d747c4c..4b6f70e0d987 100644
>>> --- a/fs/nfsd/filecache.c
>>> +++ b/fs/nfsd/filecache.c
>>> @@ -891,7 +891,7 @@ nfsd_file_find_locked(struct inode *inode, unsigned int may_flags,
>>> 
>>> 	hlist_for_each_entry_rcu(nf, &nfsd_file_hashtbl[hashval].nfb_head,
>>> 				 nf_node, lockdep_is_held(&nfsd_file_hashtbl[hashval].nfb_lock)) {
>>> -		if ((need & nf->nf_may) != need)
>>> +		if (nf->nf_may != need)
>>> 			continue;
>>> 		if (nf->nf_inode != inode)
>>> 			continue;
>> 
>> --
>> Chuck Lever

--
Chuck Lever