Received-SPF: pass (google.com: best guess record for domain of linux-nfs-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) client-ip=209.132.180.67;
Content-Type: text/plain;
        charset=us-ascii
Mime-Version: 1.0 (Mac OS X Mail 12.4 \(3445.104.11\))
Subject: Re: [PATCH RFC] sunrpc: Ensure signalled RPC tasks exit
From:   Chuck Lever <chuck.lever@oracle.com>
In-Reply-To: <6d1e88145119587069a0077df8b31c9b80656d68.camel@hammerspace.com>
Date:   Thu, 2 Apr 2020 11:05:10 -0400
Cc:     Linux NFS Mailing List <linux-nfs@vger.kernel.org>
Content-Transfer-Encoding: quoted-printable
Message-Id: <B6F2FDD0-FFC3-4874-9F5E-B232F36F3373@oracle.com>
References: <20200401193559.6487.55107.stgit@manet.1015granger.net>
 <6d1e88145119587069a0077df8b31c9b80656d68.camel@hammerspace.com>
To:     Trond Myklebust <trondmy@hammerspace.com>
Sender: linux-nfs-owner@vger.kernel.org
Precedence: bulk


> On Apr 1, 2020, at 5:55 PM, Trond Myklebust <trondmy@hammerspace.com> =
wrote:
>=20
> On Wed, 2020-04-01 at 15:37 -0400, Chuck Lever wrote:
>> If an RPC task is signaled while it is running and the transport is
>> not connected, it will never sleep and never be terminated. This can
>> happen when a RPC transport is shut down: the remaining tasks are
>> signalled, but the transport is disconnected.
>>=20
>> Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
>> ---
>> net/sunrpc/sched.c |   14 ++++++--------
>> 1 file changed, 6 insertions(+), 8 deletions(-)
>>=20
>> Interested in comments and suggestions.
>>=20
>> Nearly every time my NFS/RDMA client unmounts when using krb5, the
>> umount hangs (killably). I tracked it down to an NFSv3 NULL request
>> that is signalled but loops and does not exit.
>>=20
>>=20
>> diff --git a/net/sunrpc/sched.c b/net/sunrpc/sched.c
>> index 55e900255b0c..905c31f75593 100644
>> --- a/net/sunrpc/sched.c
>> +++ b/net/sunrpc/sched.c
>> @@ -905,6 +905,12 @@ static void __rpc_execute(struct rpc_task *task)
>> 		trace_rpc_task_run_action(task, do_action);
>> 		do_action(task);
>>=20
>> +		if (RPC_SIGNALLED(task)) {
>> +			task->tk_rpc_status =3D -ERESTARTSYS;
>> +			rpc_exit(task, -ERESTARTSYS);
>> +			break;
>> +		}
>> +
>=20
> Hmm... I'd really prefer to avoid this kind of check in the tight =
loop.

Certainly performance is a concern, but compared to the indirect
function call directly preceding this check, it is small potatoes.
Adding an "unlikely()" to the RPC_SIGNALLED() macro might help
mitigate the execution pipeline bubble it would cause.


> Why is this NULL request looping?

Here's an ftrace log I captured a couple of days ago.

      umount.nfs-7540  [004]   938.823064: rpc_task_begin:       =
task:18647@1 flags=3DASYNC|DYNAMIC|SOFT runstate=3DACTIVE status=3D0 =
action=3D(nil)s
   kworker/u25:0-6092  [000]   938.823073: rpc_task_run_action:  =
task:18647@1 flags=3DASYNC|DYNAMIC|SOFT runstate=3DRUNNING|ACTIVE =
status=3D0 action=3Dcall_start
   kworker/u25:0-6092  [000]   938.823075: rpc_request:          =
task:18647@1 nfsv3 NULL (async)
   kworker/u25:0-6092  [000]   938.823076: rpc_task_run_action:  =
task:18647@1 flags=3DASYNC|DYNAMIC|SOFT runstate=3DRUNNING|ACTIVE =
status=3D0 action=3Dcall_reserve
   kworker/u25:0-6092  [000]   938.823078: rpc_task_run_action:  =
task:18647@1 flags=3DASYNC|DYNAMIC|SOFT runstate=3DRUNNING|ACTIVE =
status=3D0 action=3Dcall_reserveresult
   kworker/u25:0-6092  [000]   938.823079: rpc_task_run_action:  =
task:18647@1 flags=3DASYNC|DYNAMIC|SOFT runstate=3DRUNNING|ACTIVE =
status=3D0 action=3Dcall_refresh
   kworker/u25:0-6092  [000]   938.823080: rpc_task_run_action:  =
task:18647@1 flags=3DASYNC|DYNAMIC|SOFT runstate=3DRUNNING|ACTIVE =
status=3D0 action=3Dcall_refreshresult
   kworker/u25:0-6092  [000]   938.823081: rpc_task_run_action:  =
task:18647@1 flags=3DASYNC|DYNAMIC|SOFT runstate=3DRUNNING|ACTIVE =
status=3D0 action=3Dcall_allocate
   kworker/u25:0-6092  [000]   938.823084: xprtrdma_op_allocate: =
task:18647@1 req=3D0xffff8884691ca000 (1624, 60)
   kworker/u25:0-6092  [000]   938.823085: rpc_task_run_action:  =
task:18647@1 flags=3DASYNC|DYNAMIC|SOFT runstate=3DRUNNING|ACTIVE =
status=3D0 action=3Dcall_encode
   kworker/u25:0-6092  [000]   938.823088: rpcgss_seqno:         =
task:18647@1 xid=3D0xfd7e5fb8 seqno=3D21981
   kworker/u25:0-6092  [000]   938.823117: xprt_enq_xmit:        =
task:18647@1 xid=3D0xfd7e5fb8 seqno=3D21981 stage=3D4
   kworker/u25:0-6092  [000]   938.823118: rpc_task_run_action:  =
task:18647@1 flags=3DASYNC|DYNAMIC|SOFT =
runstate=3DRUNNING|ACTIVE|NEED_XMIT|NEED_RECV status=3D0 =
action=3Dcall_transmit
      umount.nfs-7540  [004]   938.823119: rpc_task_signalled:   =
task:18647@1 flags=3DASYNC|DYNAMIC|SOFT =
runstate=3DRUNNING|ACTIVE|NEED_XMIT|NEED_RECV status=3D0 =
action=3Dcall_transmit_status
   kworker/u25:0-6092  [000]   938.823119: xprt_reserve_cong:    =
task:18647@1 snd_task:18647 cong=3D0 cwnd=3D16384
   kworker/u25:0-6092  [000]   938.823121: xprt_transmit:        =
task:18647@1 xid=3D0xfd7e5fb8 seqno=3D21981 status=3D-512
   kworker/u25:0-6092  [000]   938.823127: xprt_release_cong:    =
task:18647@1 snd_task:4294967295 cong=3D0 cwnd=3D16384
   kworker/u25:0-6092  [000]   938.823127: rpc_task_run_action:  =
task:18647@1 flags=3DASYNC|DYNAMIC|SOFT =
runstate=3DRUNNING|ACTIVE|NEED_RECV|SIGNALLED status=3D0 =
action=3Dcall_transmit_status
   kworker/u25:0-6092  [000]   938.823129: rpc_task_sleep:       =
task:18647@1 flags=3DASYNC|DYNAMIC|SOFT =
runstate=3DRUNNING|ACTIVE|NEED_RECV|SIGNALLED status=3D0 timeout=3D0 =
queue=3Dxprt_pending
   kworker/u25:0-6092  [000]   938.823132: rpc_task_wakeup:      =
task:18647@1 flags=3DASYNC|DYNAMIC|SOFT =
runstate=3DRUNNING|QUEUED|ACTIVE|NEED_RECV|SIGNALLED status=3D-107 =
timeout=3D60000 queue=3Dxprt_pending
   kworker/u25:0-6092  [000]   938.823133: rpc_task_run_action:  =
task:18647@1 flags=3DASYNC|DYNAMIC|SOFT =
runstate=3DRUNNING|ACTIVE|NEED_RECV|SIGNALLED status=3D-107 =
action=3Dxprt_timer
   kworker/u25:0-6092  [000]   938.823133: rpc_task_run_action:  =
task:18647@1 flags=3DASYNC|DYNAMIC|SOFT =
runstate=3DRUNNING|ACTIVE|NEED_RECV|SIGNALLED status=3D-107 =
action=3Dcall_status
   kworker/u25:0-6092  [000]   938.823136: rpc_call_status:      =
task:18647@1 status=3D-107
   kworker/u25:0-6092  [000]   938.823137: rpc_task_run_action:  =
task:18647@1 flags=3DASYNC|DYNAMIC|SOFT =
runstate=3DRUNNING|ACTIVE|NEED_RECV|SIGNALLED status=3D0 =
action=3Dcall_encode
   kworker/u25:0-6092  [000]   938.823138: rpcgss_seqno:         =
task:18647@1 xid=3D0xfd7e5fb8 seqno=3D21982
   kworker/u25:0-6092  [000]   938.823146: xprt_enq_xmit:        =
task:18647@1 xid=3D0xfd7e5fb8 seqno=3D21982 stage=3D4
   kworker/u25:0-6092  [000]   938.823147: rpc_task_run_action:  =
task:18647@1 flags=3DASYNC|DYNAMIC|SOFT =
runstate=3DRUNNING|ACTIVE|NEED_XMIT|NEED_RECV|SIGNALLED status=3D0 =
action=3Dcall_transmit
   kworker/u25:0-6092  [000]   938.823147: xprt_reserve_cong:    =
task:18647@1 snd_task:18647 cong=3D0 cwnd=3D16384
   kworker/u25:0-6092  [000]   938.823148: xprt_transmit:        =
task:18647@1 xid=3D0xfd7e5fb8 seqno=3D21982 status=3D-512
   kworker/u25:0-6092  [000]   938.823149: xprt_release_cong:    =
task:18647@1 snd_task:4294967295 cong=3D0 cwnd=3D16384
   kworker/u25:0-6092  [000]   938.823149: rpc_task_run_action:  =
task:18647@1 flags=3DASYNC|DYNAMIC|SOFT =
runstate=3DRUNNING|ACTIVE|NEED_RECV|SIGNALLED status=3D0 =
action=3Dcall_transmit_status
   kworker/u25:0-6092  [000]   938.823150: rpc_task_sleep:       =
task:18647@1 flags=3DASYNC|DYNAMIC|SOFT =
runstate=3DRUNNING|ACTIVE|NEED_RECV|SIGNALLED status=3D0 timeout=3D0 =
queue=3Dxprt_pending
   kworker/u25:0-6092  [000]   938.823151: rpc_task_wakeup:      =
task:18647@1 flags=3DASYNC|DYNAMIC|SOFT =
runstate=3DRUNNING|QUEUED|ACTIVE|NEED_RECV|SIGNALLED status=3D-107 =
timeout=3D120000 queue=3Dxprt_pending
   kworker/u25:0-6092  [000]   938.823152: rpc_task_run_action:  =
task:18647@1 flags=3DASYNC|DYNAMIC|SOFT =
runstate=3DRUNNING|ACTIVE|NEED_RECV|SIGNALLED status=3D-107 =
action=3Dxprt_timer
   kworker/u25:0-6092  [000]   938.823152: rpc_task_run_action:  =
task:18647@1 flags=3DASYNC|DYNAMIC|SOFT =
runstate=3DRUNNING|ACTIVE|NEED_RECV|SIGNALLED status=3D-107 =
action=3Dcall_status
   kworker/u25:0-6092  [000]   938.823153: rpc_call_status:      =
task:18647@1 status=3D-107

And here, the looping continues.

My analysis is that the signal occurs while the task is running/active
in a section of code that continues to iterate on reconnecting without
checking for a signal. Note that the tail of xprt_transmit will not set
tk_status in this case, so it remains set to zero upon entry to
call_transmit_status.

I like the scheduler fix because I don't believe we can easily tell if
there might be other such critical sections in the client's state
machine where a loop might occur with no exit condition based on a
signal.

This fix closes the door on all such bugs.


--
Chuck Lever