Content-Type: text/plain;
        charset=us-ascii
Mime-Version: 1.0 (Mac OS X Mail 11.5 \(3445.9.1\))
Subject: Re: [PATCH v3 26/44] SUNRPC: Improve latency for interactive tasks
From:   Chuck Lever <chuck.lever@oracle.com>
In-Reply-To: <3e3c803dd0d007e4692ae2142b73bc1294d2b62a.camel@hammerspace.com>
Date:   Wed, 2 Jan 2019 14:08:01 -0500
Cc:     Linux NFS Mailing List <linux-nfs@vger.kernel.org>
Content-Transfer-Encoding: quoted-printable
Message-Id: <BDD7E434-DE5C-441C-8ED3-4A3CA28B7A36@oracle.com>
References: <c4bd04d525a1355e3dfff054985d697f0f391816.camel@hammerspace.com>
 <07dcc1731996d6e59d882c5e4e7e7765d013c337.camel@hammerspace.com>
 <E9A190A9-4A55-4D02-9259-2F26BC41F16C@oracle.com>
 <1fa9f43b6cc2ba5d4ebd24955bf76454bfab0c18.camel@hammerspace.com>
 <5160E7EB-556C-4099-B564-8EFF7D7D9113@oracle.com>
 <3e3c803dd0d007e4692ae2142b73bc1294d2b62a.camel@hammerspace.com>
To:     Trond Myklebust <trondmy@hammerspace.com>
Sender: linux-nfs-owner@vger.kernel.org
Precedence: bulk


> On Jan 2, 2019, at 1:57 PM, Trond Myklebust <trondmy@hammerspace.com> =
wrote:
>=20
> On Wed, 2019-01-02 at 13:51 -0500, Chuck Lever wrote:
>>> On Jan 2, 2019, at 1:45 PM, Trond Myklebust <
>>> trondmy@hammerspace.com> wrote:
>>>=20
>>> On Wed, 2019-01-02 at 13:17 -0500, Chuck Lever wrote:
>>>>> On Dec 31, 2018, at 2:21 PM, Trond Myklebust <
>>>>> trondmy@hammerspace.com> wrote:
>>>>>=20
>>>>> On Mon, 2018-12-31 at 19:18 +0000, Trond Myklebust wrote:
>>>>>> On Mon, 2018-12-31 at 14:09 -0500, Chuck Lever wrote:
>>>>>>>> On Dec 31, 2018, at 1:59 PM, Trond Myklebust <
>>>>>>>> trondmy@hammerspace.com> wrote:
>>>>>>>>=20
>>>>>>>>=20
>>>>>> The test for rpcauth_xmit_need_reencode() happens when we
>>>>>> call
>>>>>> xprt_request_transmit() to actually put the RPC call on the
>>>>>> wire.
>>>>>> The
>>>>>> enqueue order should not be able to defeat that test.
>>>>>>=20
>>>>>> Hmm... Is it perhaps the test for req->rq_bytes_sent that is
>>>>>> failing
>>>>>> because this is a retransmission after a disconnect/reconnect
>>>>>> that
>>>>>> didn't trigger a re-encode?
>>>>>=20
>>>>> Actually, it might be worth a try to move the test for
>>>>> rpcauth_xmit_need_reencode() outside the enclosing test for
>>>>> req-
>>>>>> rq_bytes_sent as that is just a minor optimisation.
>>>>=20
>>>> Perhaps that's the case for TCP, but RPCs sent via xprtrdma never
>>>> set
>>>> req->rq_bytes_sent to a non-zero value. The body of the "if"
>>>> statement
>>>> is always executed for those RPCs.
>>>>=20
>>>=20
>>> Then the question is what is defeating the call to
>>> rpcauth_xmit_need_reencode() in xprt_request_transmit() and causing
>>> it
>>> not to trigger in the misordered cases?
>>=20
>> Here's a sample RPC/RDMA case.
>>=20
>> My instrumented server reports this:
>>=20
>> Jan  2 13:29:00 klimt kernel: gss_check_seq_num: dropped:
>> seq_num=3D141220 sd->sd_max=3D141360
>>=20
>>=20
>> ftrace log on the client shows this:
>>=20
>>  kworker/u28:12-2191  [004]   194.048534: rpcgss_need_reencode:
>> task:1761@5 xid=3D0x88f4f47c rq_seqno=3D141220 seq_xmit=3D141336 =
reencode
>> unneeded
>>  kworker/u28:12-2191  [004]   194.048534:
>> xprt_transmit:        task:1761@5 xid=3D0x88f4f47c seqno=3D141220
>> status=3D-57
>>  kworker/u28:12-2191  [004]   194.048534:
>> rpc_task_run_action:  task:1779@5 flags=3DASYNC
>> runstate=3DRUNNING|ACTIVE|NEED_XMIT|NEED_RECV status=3D-57
>> action=3Dcall_transmit_status
>>  kworker/u28:12-2191  [004]   194.048535:
>> rpc_task_run_action:  task:1779@5 flags=3DASYNC
>> runstate=3DRUNNING|ACTIVE|NEED_XMIT|NEED_RECV status=3D0
>> action=3Dcall_transmit
>>  kworker/u28:12-2191  [004]   194.048535:
>> rpc_task_sleep:       task:1779@5 flags=3DASYNC
>> runstate=3DRUNNING|ACTIVE|NEED_XMIT|NEED_RECV status=3D-11 timeout=3D0
>> queue=3Dxprt_sending
>>=20
>>=20
>>  kworker/u28:12-2191  [004]   194.048552: rpcgss_need_reencode:
>> task:1761@5 xid=3D0x88f4f47c rq_seqno=3D141220 seq_xmit=3D141336 =
reencode
>> unneeded
>>  kworker/u28:12-2191  [004]   194.048557:
>> xprt_transmit:        task:1761@5 xid=3D0x88f4f47c seqno=3D141220
>> status=3D0
>>=20
>>=20
>>  kworker/u28:12-2191  [004]   194.048559: rpcgss_need_reencode:
>> task:1902@5 xid=3D0x14f5f47c rq_seqno=3D141360 seq_xmit=3D141336 =
reencode
>> unneeded
>>  kworker/u28:12-2191  [004]   194.048563:
>> xprt_transmit:        task:1902@5 xid=3D0x14f5f47c seqno=3D141360
>> status=3D0
>>=20
>>=20
>> Note that first need_reencode: the sequence numbers show that the
>> xmit
>> queue has been significantly re-ordered. The request being
>> transmitted is
>> already very close to the lower end of the GSS sequence number
>> window.
>>=20
>> The server then re-ordereds these two slightly because the first one
>> had
>> some Read chunks that need to be pulled over, the second was pure
>> inline
>> and therefore could be processed immediately. That is enough to force
>> the
>> first one outside the GSS sequence number window.
>>=20
>> I haven't looked closely at the pathology of the TCP case.
>=20
> Wait a minute... That's not OK. The client can't be expected to take
> into account reordering that happens on the server side.

Conversely, the client can't assume the transport and the server don't
re-order. This does not appear to be a problem for the v4.19 client:
I don't see disconnect storms with that client.


--
Chuck Lever