Received-SPF: pass (google.com: domain of linux-nfs-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) client-ip=23.128.96.18;
Content-Type: text/plain;
        charset=us-ascii
Mime-Version: 1.0 (Mac OS X Mail 12.4 \(3445.104.11\))
Subject: Re: [PATCH v1 4/4] SUNRPC: Clean up request deferral tracepoints
From:   Chuck Lever <chuck.lever@oracle.com>
In-Reply-To: <20200504160414.GA2757@fieldses.org>
Date:   Mon, 4 May 2020 13:12:02 -0400
Cc:     Linux NFS Mailing List <linux-nfs@vger.kernel.org>
Content-Transfer-Encoding: quoted-printable
Message-Id: <0A259214-3C62-46C2-842B-8CEBDA7B9256@oracle.com>
References: <20200501171750.3764.7676.stgit@klimt.1015granger.net>
 <20200501172227.3764.74938.stgit@klimt.1015granger.net>
 <20200504160414.GA2757@fieldses.org>
To:     Bruce Fields <bfields@fieldses.org>
Sender: linux-nfs-owner@vger.kernel.org
Precedence: bulk


> On May 4, 2020, at 12:04 PM, bfields@fieldses.org wrote:
>=20
> On Fri, May 01, 2020 at 01:22:27PM -0400, Chuck Lever wrote:
>> - Rename these so they are easy to enable and search for as a set
>> - Move the tracepoints to get a more accurate sense of control flow
>> - Tracepoints should not fire on xprt shutdown
>> - Display memory address in case data structure had been corrupted
>> - Abandon dprintk in these paths
>>=20
>> I haven't ever gotten one of these tracepoints to trigger. I wonder
>> if we should simply remove them.
>=20
> It's definitely not dead code.

Sure. I'm just suggesting that maybe we could make do with just a single
tracepoint here (or maybe, no tracepoints) since these paths don't seem
to trigger often.


> But I forget the conditions required to
> hit those cases.  Looking.... So, we in cache_check we have a cache =
miss
> that requires an upcall, and call cache_defer_req, which will wait for =
a
> response 1 or 5 seconds (depending on how busy server threads are) and
> then calls svc_defer().

It would be valuable to have some stock test cases in our community =
tools
that would exercise these paths.


> --b.
>=20
>>=20
>> Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
>> ---
>> include/trace/events/sunrpc.h |   11 ++++++++---
>> net/sunrpc/svc_xprt.c         |   12 ++++++------
>> 2 files changed, 14 insertions(+), 9 deletions(-)
>>=20
>> diff --git a/include/trace/events/sunrpc.h =
b/include/trace/events/sunrpc.h
>> index ffd2215950dc..3158b3f7e01e 100644
>> --- a/include/trace/events/sunrpc.h
>> +++ b/include/trace/events/sunrpc.h
>> @@ -1313,27 +1313,32 @@ DECLARE_EVENT_CLASS(svc_deferred_event,
>> 	TP_ARGS(dr),
>>=20
>> 	TP_STRUCT__entry(
>> +		__field(const void *, dr)
>> 		__field(u32, xid)
>> 		__string(addr, dr->xprt->xpt_remotebuf)
>> 	),
>>=20
>> 	TP_fast_assign(
>> +		__entry->dr =3D dr;
>> 		__entry->xid =3D be32_to_cpu(*(__be32 *)(dr->args +
>> 						       =
(dr->xprt_hlen>>2)));
>> 		__assign_str(addr, dr->xprt->xpt_remotebuf);
>> 	),
>>=20
>> -	TP_printk("addr=3D%s xid=3D0x%08x", __get_str(addr), =
__entry->xid)
>> +	TP_printk("addr=3D%s dr=3D%p xid=3D0x%08x", __get_str(addr), =
__entry->dr,
>> +		__entry->xid)
>> );
>> +
>> #define DEFINE_SVC_DEFERRED_EVENT(name) \
>> -	DEFINE_EVENT(svc_deferred_event, svc_##name##_deferred, \
>> +	DEFINE_EVENT(svc_deferred_event, svc_defer_##name, \
>> 			TP_PROTO( \
>> 				const struct svc_deferred_req *dr \
>> 			), \
>> 			TP_ARGS(dr))
>>=20
>> DEFINE_SVC_DEFERRED_EVENT(drop);
>> -DEFINE_SVC_DEFERRED_EVENT(revisit);
>> +DEFINE_SVC_DEFERRED_EVENT(queue);
>> +DEFINE_SVC_DEFERRED_EVENT(recv);
>>=20
>> DECLARE_EVENT_CLASS(cache_event,
>> 	TP_PROTO(
>> diff --git a/net/sunrpc/svc_xprt.c b/net/sunrpc/svc_xprt.c
>> index 2284ff038dad..e12ec68cd0ff 100644
>> --- a/net/sunrpc/svc_xprt.c
>> +++ b/net/sunrpc/svc_xprt.c
>> @@ -1158,16 +1158,15 @@ static void svc_revisit(struct =
cache_deferred_req *dreq, int too_many)
>> 	set_bit(XPT_DEFERRED, &xprt->xpt_flags);
>> 	if (too_many || test_bit(XPT_DEAD, &xprt->xpt_flags)) {
>> 		spin_unlock(&xprt->xpt_lock);
>> -		dprintk("revisit canceled\n");
>> +		trace_svc_defer_drop(dr);
>> 		svc_xprt_put(xprt);
>> -		trace_svc_drop_deferred(dr);
>> 		kfree(dr);
>> 		return;
>> 	}
>> -	dprintk("revisit queued\n");
>> 	dr->xprt =3D NULL;
>> 	list_add(&dr->handle.recent, &xprt->xpt_deferred);
>> 	spin_unlock(&xprt->xpt_lock);
>> +	trace_svc_defer_queue(dr);
>> 	svc_xprt_enqueue(xprt);
>> 	svc_xprt_put(xprt);
>> }
>> @@ -1213,22 +1212,24 @@ static struct cache_deferred_req =
*svc_defer(struct cache_req *req)
>> 		memcpy(dr->args, rqstp->rq_arg.head[0].iov_base - skip,
>> 		       dr->argslen << 2);
>> 	}
>> +	trace_svc_defer(rqstp);
>> 	svc_xprt_get(rqstp->rq_xprt);
>> 	dr->xprt =3D rqstp->rq_xprt;
>> 	set_bit(RQ_DROPME, &rqstp->rq_flags);
>>=20
>> 	dr->handle.revisit =3D svc_revisit;
>> -	trace_svc_defer(rqstp);
>> 	return &dr->handle;
>> }
>>=20
>> /*
>>  * recv data from a deferred request into an active one
>>  */
>> -static int svc_deferred_recv(struct svc_rqst *rqstp)
>> +static noinline int svc_deferred_recv(struct svc_rqst *rqstp)
>> {
>> 	struct svc_deferred_req *dr =3D rqstp->rq_deferred;
>>=20
>> +	trace_svc_defer_recv(dr);
>> +
>> 	/* setup iov_base past transport header */
>> 	rqstp->rq_arg.head[0].iov_base =3D dr->args + =
(dr->xprt_hlen>>2);
>> 	/* The iov_len does not include the transport header bytes */
>> @@ -1259,7 +1260,6 @@ static struct svc_deferred_req =
*svc_deferred_dequeue(struct svc_xprt *xprt)
>> 				struct svc_deferred_req,
>> 				handle.recent);
>> 		list_del_init(&dr->handle.recent);
>> -		trace_svc_revisit_deferred(dr);
>> 	} else
>> 		clear_bit(XPT_DEFERRED, &xprt->xpt_flags);
>> 	spin_unlock(&xprt->xpt_lock);

--
Chuck Lever