Re: CPU stall, eventual host hang with BTRFS + NFS under heavy load

[Trond Myklebust <trondmy@hammerspace.com>]

On Wed, 2021-12-01 at 13:36 -0500, Scott Mayhew wrote:
> On Fri, 15 Oct 2021, Trond Myklebust wrote:
> 
> > On Fri, 2021-10-15 at 08:03 +0000, Trond Myklebust wrote:
> > > On Fri, 2021-10-15 at 09:51 +1100, NeilBrown wrote:
> > > > On Fri, 15 Oct 2021, Trond Myklebust wrote:
> > > > > On Tue, 2021-10-12 at 08:57 +1100, NeilBrown wrote:
> > > > > > On Tue, 12 Oct 2021, Chuck Lever III wrote:
> > > > > > > 
> > > > > > > Scott seems well positioned to identify a reproducer.
> > > > > > > Maybe
> > > > > > > we
> > > > > > > can give him some likely candidates for possible bugs to
> > > > > > > explore
> > > > > > > first.
> > > > > > 
> > > > > > Has this patch been tried?
> > > > > > 
> > > > > > NeilBrown
> > > > > > 
> > > > > > 
> > > > > > diff --git a/net/sunrpc/sched.c b/net/sunrpc/sched.c
> > > > > > index c045f63d11fa..308f5961cb78 100644
> > > > > > --- a/net/sunrpc/sched.c
> > > > > > +++ b/net/sunrpc/sched.c
> > > > > > @@ -814,6 +814,7 @@ rpc_reset_task_statistics(struct
> > > > > > rpc_task
> > > > > > *task)
> > > > > >  {
> > > > > >         task->tk_timeouts = 0;
> > > > > >         task->tk_flags &=
> > > > > > ~(RPC_CALL_MAJORSEEN|RPC_TASK_SENT);
> > > > > > +       clear_bit(RPC_TASK_SIGNALLED, &task->tk_runstate);
> > > > > >         rpc_init_task_st
> > > > > 
> > > > > We shouldn't automatically "unsignal" a task once it has been
> > > > > told
> > > > > to
> > > > > die. The correct thing to do here should rather be to change
> > > > > rpc_restart_call() to exit early if the task was signalled.
> > > > > 
> > > > 
> > > > Maybe.  It depends on exactly what the signal meant
> > > > (rpc_killall_tasks()
> > > > is a bit different from getting a SIGKILL), and exactly what
> > > > the
> > > > task
> > > > is
> > > > trying to achieve.
> > > > 
> > > > Before Commit ae67bd3821bb ("SUNRPC: Fix up task signalling")
> > > > that is exactly what we did.
> > > > If we want to change the behaviour of a task responding to
> > > > rpc_killall_tasks(), we should clearly justify it in a patch
> > > > doing
> > > > exactly that.
> > > > 
> > > 
> > > The intention behind rpc_killall_tasks() never changed, which is
> > > why
> > > it
> > 
> > ("it" being the error ERESTARTSYS)
> > 
> > > is listed in nfs_error_is_fatal(). I'm not aware of any case
> > > where we
> > > deliberately override in order to restart the RPC call on an
> > > ERESTARTSYS error.
> > > 
> Update: I'm not able to reproduce this with an upstream kernel.  I
> bisected it down to commit 2ba5acfb3495 "SUNRPC: fix sign error
> causing
> rpcsec_gss drops" as the commit that "fixed" the issue (but really
> just
> makes the issue less likely to occur, I think).
> 
> I also tested commit 10b9d99a3dbb "SUNRPC: Augment server-side rpcgss
> tracepoints" (the commit in the Fixes: tag of 2ba5acfb3495) as well
> as
> commit 0e885e846d96 "nfsd: add fattr support for user extended
> attributes"
> (the parent of commit 10b9d99a3dbb) and verified that commit
> 10b9d99a3dbb is where the issue started occurring.
> 
> I think what is happening is that the NFS server gets a request that
> it
> thinks is outside of the GSS sequence window and drops the request,
> closes the connection and calls nfsd4_conn_lost(), which calls
> nfsd4_probe_callback() which sets NFSD4_CLIENT_CB_UPDATE in
> clp->cl_flags.  Then the client reestablishes the connection on that
> port, sends another request which receives
> NFS4ERR_CONN_NOT_BOUND_TO_SESSION.  The client runs the state manager
> which calls nfs4_bind_conn_to_session(), which calls
> nfs4_begin_drain_session(), which sets NFS4_SLOT_TBL_DRAINING in
> tbl->slot_tbl_state.  Meanwhile a conflicting request comes in that
> causes the server to recall the delegation.  Since
> NFS4_SLOT_TBL_DRAINING is set, the client responds to the CB_SEQUENCE
> with NFS4ERR_DELAY.  At the same time, the BIND_CONN_TO_SESSION
> requests
> from the client are causing the server to call
> nfsd4_process_cb_update(), since NFSD4_CLIENT_CB_UPDATE flag is set.
> nfsd4_process_cb_update() calls rpc_shutdown_client() which signals
> the
> CB_RECALL task, which the server is trying re-send due to the
> NFS4ERR_DELAY, and we get into the soft-lockup.
> 

I'm a little lost with the above explantion. How can the server send a
callback on a connection that isn't bound? If it isn't bound, then it
can't be used as a back channel.


-- 
Trond Myklebust
Linux NFS client maintainer, Hammerspace
trond.myklebust@hammerspace.com