Linux-NFS Archive on lore.kernel.org
 help / color / Atom feed
From: Trond Myklebust <trondmy@hammerspace.com>
To: "chuck.lever@oracle.com" <chuck.lever@oracle.com>
Cc: "linux-nfs@vger.kernel.org" <linux-nfs@vger.kernel.org>,
	"anna.schumaker@netapp.com" <anna.schumaker@netapp.com>
Subject: Re: [PATCH 2/3] SUNRPC: Fix trace_xprt_transmit_queued()
Date: Wed, 31 Mar 2021 19:40:02 +0000
Message-ID: <918f9ec8cc88d1d37f402bd4f0b1b664f558923e.camel@hammerspace.com> (raw)
In-Reply-To: <DA345B72-D2B5-44E0-83A8-CD641274BE9B@oracle.com>

On Wed, 2021-03-31 at 19:22 +0000, Chuck Lever III wrote:
> 
> 
> > On Mar 31, 2021, at 1:52 PM, Trond Myklebust <
> > trondmy@hammerspace.com> wrote:
> > 
> > On Wed, 2021-03-31 at 13:22 -0400, Chuck Lever wrote:
> > > This tracepoint can crash when dereferencing snd_task because
> > > when some transports connect, they put a cookie in that field
> > > instead of a pointer to an rpc_task.
> > > 
> > > BUG: KASAN: use-after-free in
> > > trace_event_raw_event_xprt_writelock_event+0x141/0x18e [sunrpc]
> > > Read of size 2 at addr ffff8881a83bd3a0 by task git/331872
> > > 
> > > CPU: 11 PID: 331872 Comm: git Tainted: G S                5.12.0-
> > > rc2-
> > > 00007-g3ab6e585a7f9 #1453
> > > Hardware name: Supermicro SYS-6028R-T/X10DRi, BIOS 1.1a
> > > 10/16/2015
> > > Call Trace:
> > >  dump_stack+0x9c/0xcf
> > >  print_address_description.constprop.0+0x18/0x239
> > >  kasan_report+0x174/0x1b0
> > >  trace_event_raw_event_xprt_writelock_event+0x141/0x18e [sunrpc]
> > >  xprt_prepare_transmit+0x8e/0xc1 [sunrpc]
> > >  call_transmit+0x4d/0xc6 [sunrpc]
> > > 
> > > Fixes: 9ce07ae5eb1d ("SUNRPC: Replace dprintk() call site in
> > > xprt_prepare_transmit")
> > > Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
> > > ---
> > >  include/trace/events/sunrpc.h |   35
> > > ++++++++++++++++++++++++++++++++++-
> > >  net/sunrpc/xprt.c             |    2 +-
> > >  2 files changed, 35 insertions(+), 2 deletions(-)
> > > 
> > > diff --git a/include/trace/events/sunrpc.h
> > > b/include/trace/events/sunrpc.h
> > > index 036eb1f5c133..690988530d60 100644
> > > --- a/include/trace/events/sunrpc.h
> > > +++ b/include/trace/events/sunrpc.h
> > > @@ -1141,7 +1141,40 @@ DECLARE_EVENT_CLASS(xprt_writelock_event,
> > >  
> > >  DEFINE_WRITELOCK_EVENT(reserve_xprt);
> > >  DEFINE_WRITELOCK_EVENT(release_xprt);
> > > -DEFINE_WRITELOCK_EVENT(transmit_queued);
> > > +
> > > +TRACE_EVENT(xprt_transmit_queued,
> > > +       TP_PROTO(
> > > +               const struct rpc_task *task
> > > +       ),
> > > +
> > > +       TP_ARGS(task),
> > > +
> > > +       TP_STRUCT__entry(
> > > +               __field(unsigned int, task_id)
> > > +               __field(unsigned int, client_id)
> > > +               __field(unsigned long, runstate)
> > > +               __field(u32, xid)
> > > +               __field(int, status)
> > > +               __field(unsigned short, flags)
> > > +       ),
> > > +
> > > +       TP_fast_assign(
> > > +               __entry->task_id = task->tk_pid;
> > > +               __entry->client_id =
> > > +                       task->tk_client ? task->tk_client-
> > > >cl_clid :
> > > -1;
> > > +               __entry->runstate = task->tk_runstate;
> > > +               __entry->xid = be32_to_cpu(task->tk_rqstp-
> > > >rq_xid);
> > > +               __entry->status = task->tk_status;
> > > +               __entry->flags = task->tk_flags;
> > > +       ),
> > > +
> > > +       TP_printk("task:%u@%u xid=0x%08x flags=%s runstate=%s
> > > status=%d",
> > > +               __entry->task_id, __entry->client_id, __entry-
> > > >xid,
> > > +               rpc_show_task_flags(__entry->flags),
> > > +               rpc_show_runstate(__entry->runstate),
> > > +               __entry->status
> > > +       )
> > > +);
> > >  
> > >  DECLARE_EVENT_CLASS(xprt_cong_event,
> > >         TP_PROTO(
> > > diff --git a/net/sunrpc/xprt.c b/net/sunrpc/xprt.c
> > > index d616b93751d8..b694af4504c4 100644
> > > --- a/net/sunrpc/xprt.c
> > > +++ b/net/sunrpc/xprt.c
> > > @@ -1469,7 +1469,7 @@ bool xprt_prepare_transmit(struct rpc_task
> > > *task)
> > >         struct rpc_xprt *xprt = req->rq_xprt;
> > >  
> > >         if (!xprt_lock_write(xprt, task)) {
> > > -               trace_xprt_transmit_queued(xprt, task);
> > > +               trace_xprt_transmit_queued(task);
> > 
> > Why do we need this tracepoint? The event we're logging is just
> > "grabbing the transport write lock failed due to external
> > circumstances".
> 
> This tracepoint records the decision to queue rather than send
> immediately.

The request is already queued before we call xprt_prepare_transmit().

The decision being made here is whether or not we can move forward with
driving the bind or connect or transmission. This tracepoint just
records the case where something is blocking this specific rpc_task
from doing so.

> You can count the number of these to get an idea whether the
> transport
> is backed up.
> 
> You can trigger on this event if you want to capture the events that
> lead up to queuing a request.

The lock can be unavailable simply because some other rpc_task is
already in the process of draining the queue.

If you want to find out if transmission is actually blocked, you're
better off triggering on the event that caused the blockage (either a
disconnect or a failure to reconnect or rebind). This tracepoint is
going to cause way too many false positives to be of any use for
tracing blockage.

> You can see whether the client logic is making the right choice when
> congestion control is in play.

Don't we already have a tracepoint in xprt_reserve_xprt_cong() for
this?

> 
> 
> > >                 /* Race breaker: someone may have transmitted us
> > > */
> > >                 if (!test_bit(RPC_TASK_NEED_XMIT, &task-
> > > > tk_runstate))
> > > 
> > > 
> > 
> > -- 
> > Trond Myklebust
> > Linux NFS client maintainer, Hammerspace
> > trond.myklebust@hammerspace.com
> 
> --
> Chuck Lever
> 
> 
> 

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



  reply index

Thread overview: 6+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2021-03-31 17:22 [PATCH 1/3] SUNRPC: Move fault injection call sites Chuck Lever
2021-03-31 17:22 ` [PATCH 2/3] SUNRPC: Fix trace_xprt_transmit_queued() Chuck Lever
2021-03-31 17:52   ` Trond Myklebust
2021-03-31 19:22     ` Chuck Lever III
2021-03-31 19:40       ` Trond Myklebust [this message]
2021-03-31 17:22 ` [PATCH 3/3] SUNRPC: Add tracepoint that fires when an RPC is retransmitted Chuck Lever

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to=918f9ec8cc88d1d37f402bd4f0b1b664f558923e.camel@hammerspace.com \
    --to=trondmy@hammerspace.com \
    --cc=anna.schumaker@netapp.com \
    --cc=chuck.lever@oracle.com \
    --cc=linux-nfs@vger.kernel.org \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link

Linux-NFS Archive on lore.kernel.org

Archives are clonable:
	git clone --mirror https://lore.kernel.org/linux-nfs/0 linux-nfs/git/0.git

	# If you have public-inbox 1.1+ installed, you may
	# initialize and index your mirror using the following commands:
	public-inbox-init -V2 linux-nfs linux-nfs/ https://lore.kernel.org/linux-nfs \
		linux-nfs@vger.kernel.org
	public-inbox-index linux-nfs

Example config snippet for mirrors

Newsgroup available over NNTP:
	nntp://nntp.lore.kernel.org/org.kernel.vger.linux-nfs


AGPL code for this site: git clone https://public-inbox.org/public-inbox.git