Re: [PATCH v3 26/44] SUNRPC: Improve latency for interactive tasks

[Trond Myklebust <trondmy@hammerspace.com>]

On Wed, 2019-01-02 at 14:06 -0500, Trond Myklebust wrote:
> On Wed, 2019-01-02 at 13:57 -0500, Trond Myklebust wrote:
> > 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:
> > > > 
> > > > 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:
> > > > > > 
> > > > > > 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:
> > > > > > > > > 
> > > > > > > > > 
> > > > > > > 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.
> > > > > > > 
> > > > > > > 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?
> > > > > > 
> > > > > > 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.
> > > > > 
> > > > > 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.
> > > > > 
> > > > 
> > > > 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=141220 sd->sd_max=141360
> > > 
> > > 
> > > ftrace log on the client shows this:
> > > 
> > >   kworker/u28:12-2191  [004]   194.048534: rpcgss_need_reencode:
> > > task:1761@5 xid=0x88f4f47c rq_seqno=141220 seq_xmit=141336
> > > reencode
> > > unneeded
> > >   kworker/u28:12-2191  [004]   194.048534:
> > > xprt_transmit:        task:1761@5 xid=0x88f4f47c seqno=141220
> > > status=-57
> > >   kworker/u28:12-2191  [004]   194.048534:
> > > rpc_task_run_action:  task:1779@5 flags=ASYNC
> > > runstate=RUNNING|ACTIVE|NEED_XMIT|NEED_RECV status=-57
> > > action=call_transmit_status
> > >   kworker/u28:12-2191  [004]   194.048535:
> > > rpc_task_run_action:  task:1779@5 flags=ASYNC
> > > runstate=RUNNING|ACTIVE|NEED_XMIT|NEED_RECV status=0
> > > action=call_transmit
> > >   kworker/u28:12-2191  [004]   194.048535:
> > > rpc_task_sleep:       task:1779@5 flags=ASYNC
> > > runstate=RUNNING|ACTIVE|NEED_XMIT|NEED_RECV status=-11 timeout=0
> > > queue=xprt_sending
> > > 
> > > 
> > >   kworker/u28:12-2191  [004]   194.048552: rpcgss_need_reencode:
> > > task:1761@5 xid=0x88f4f47c rq_seqno=141220 seq_xmit=141336
> > > reencode
> > > unneeded
> > >   kworker/u28:12-2191  [004]   194.048557:
> > > xprt_transmit:        task:1761@5 xid=0x88f4f47c seqno=141220
> > > status=0
> > > 
> > > 
> > >   kworker/u28:12-2191  [004]   194.048559: rpcgss_need_reencode:
> > > task:1902@5 xid=0x14f5f47c rq_seqno=141360 seq_xmit=141336
> > > reencode
> > > unneeded
> > >   kworker/u28:12-2191  [004]   194.048563:
> > > xprt_transmit:        task:1902@5 xid=0x14f5f47c seqno=141360
> > > status=0
> > > 
> > > 
> > > 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.
> > 
> > Wait a minute... That's not OK. The client can't be expected to
> > take
> > into account reordering that happens on the server side.
> 
> If that's the case, then we would need to halt transmission as soon
> as
> we hit the RPCSEC_GSS window edge. Off the cuff, I'm not sure how to
> do
> that, since those windows are per session (i.e. per user).

So here is something we probably could do: modify
xprt_request_enqueue_transmit() to order the list in req->rq_xmit2 by
req->rq_seqno. Since task->tk_owner is actually a pid, then that's not
a perfect solution, but we could further mitigate by modifying
gss_xmit_need_reencode() to only allow transmission of requests that
are within 2/3 of the window.
-- 
Trond Myklebust
Linux NFS client maintainer, Hammerspace
trond.myklebust@hammerspace.com