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: <1fa9f43b6cc2ba5d4ebd24955bf76454bfab0c18.camel@hammerspace.com>
Date:   Wed, 2 Jan 2019 13:51:05 -0500
Cc:     Linux NFS Mailing List <linux-nfs@vger.kernel.org>
Content-Transfer-Encoding: quoted-printable
Message-Id: <5160E7EB-556C-4099-B564-8EFF7D7D9113@oracle.com>
References: <c4bd04d525a1355e3dfff054985d697f0f391816.camel@hammerspace.com>
 <07dcc1731996d6e59d882c5e4e7e7765d013c337.camel@hammerspace.com>
 <E9A190A9-4A55-4D02-9259-2F26BC41F16C@oracle.com>
 <1fa9f43b6cc2ba5d4ebd24955bf76454bfab0c18.camel@hammerspace.com>
To:     Trond Myklebust <trondmy@hammerspace.com>
Sender: linux-nfs-owner@vger.kernel.org
Precedence: bulk


> 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?

Here's a sample RPC/RDMA case.

My instrumented server reports this:

Jan  2 13:29:00 klimt kernel: gss_check_seq_num: dropped: seq_num=3D141220=
 sd->sd_max=3D141360


ftrace log on the client shows this:

  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


  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


  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


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.

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.

I haven't looked closely at the pathology of the TCP case.


--
Chuck Lever