Re: [PATCH v2 02/12] sunrpc: add info about xprt queue times to svc_xprt_dequeue tracepoint

[Jeff Layton <jlayton@kernel.org>]

On Wed, 2025-04-09 at 11:00 -0400, Chuck Lever wrote:
> On 4/9/25 10:32 AM, Jeff Layton wrote:
> > Currently, this tracepoint displays "wakeup-us", which is the time that
> > the woken thread spent sleeping, before dequeueing the next xprt. Add a
> > new statistic that shows how long the xprt sat on the queue before being
> > serviced.
> 
> I don't understand the difference between "waiting on queue" and
> "sleeping". When are those two latency measurements not the same?
> 

These are measuring two different things:

svc_rqst->rq_qtime represents the time between when thread on the
sp_idle_threads list was woken. This patch adds svc_xprt->xpt_qtime,
which represents the time that the svc_xprt was added to the lwq.

The first tells us how long the interval was between the thread being
woken and the xprt being dequeued. The new statistic tells us how long
between the xprt being enqueued and dequeued.

They could easily diverge if there were not enough threads available to
service all of the queued xprts.

> 
> > Signed-off-by: Jeff Layton <jlayton@kernel.org>
> > ---
> >  include/linux/sunrpc/svc_xprt.h |  1 +
> >  include/trace/events/sunrpc.h   | 13 +++++++------
> >  net/sunrpc/svc_xprt.c           |  1 +
> >  3 files changed, 9 insertions(+), 6 deletions(-)
> > 
> > diff --git a/include/linux/sunrpc/svc_xprt.h b/include/linux/sunrpc/svc_xprt.h
> > index 72be609525796792274d5b8cb5ff37f73723fc23..369a89aea18618748607ee943247c327bf62c8d5 100644
> > --- a/include/linux/sunrpc/svc_xprt.h
> > +++ b/include/linux/sunrpc/svc_xprt.h
> > @@ -53,6 +53,7 @@ struct svc_xprt {
> >  	struct svc_xprt_class	*xpt_class;
> >  	const struct svc_xprt_ops *xpt_ops;
> >  	struct kref		xpt_ref;
> > +	ktime_t			xpt_qtime;
> >  	struct list_head	xpt_list;
> >  	struct lwq_node		xpt_ready;
> >  	unsigned long		xpt_flags;
> > diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
> > index 5d331383047b79b9f6dcd699c87287453c1a5f49..b5a0f0bc1a3b7cfd90ce0181a8a419db810988bb 100644
> > --- a/include/trace/events/sunrpc.h
> > +++ b/include/trace/events/sunrpc.h
> > @@ -2040,19 +2040,20 @@ TRACE_EVENT(svc_xprt_dequeue,
> >  
> >  	TP_STRUCT__entry(
> >  		SVC_XPRT_ENDPOINT_FIELDS(rqst->rq_xprt)
> > -
> >  		__field(unsigned long, wakeup)
> > +		__field(unsigned long, qtime)
> >  	),
> >  
> >  	TP_fast_assign(
> > -		SVC_XPRT_ENDPOINT_ASSIGNMENTS(rqst->rq_xprt);
> > +		ktime_t ktime = ktime_get();
> >  
> > -		__entry->wakeup = ktime_to_us(ktime_sub(ktime_get(),
> > -							rqst->rq_qtime));
> > +		SVC_XPRT_ENDPOINT_ASSIGNMENTS(rqst->rq_xprt);
> > +		__entry->wakeup = ktime_to_us(ktime_sub(ktime, rqst->rq_qtime));
> > +		__entry->qtime = ktime_to_us(ktime_sub(ktime, rqst->rq_xprt->xpt_qtime));
> >  	),
> >  
> > -	TP_printk(SVC_XPRT_ENDPOINT_FORMAT " wakeup-us=%lu",
> > -		SVC_XPRT_ENDPOINT_VARARGS, __entry->wakeup)
> > +	TP_printk(SVC_XPRT_ENDPOINT_FORMAT " wakeup-us=%lu qtime=%lu",
> > +		SVC_XPRT_ENDPOINT_VARARGS, __entry->wakeup, __entry->qtime)
> >  );
> >  
> >  DECLARE_EVENT_CLASS(svc_xprt_event,
> > diff --git a/net/sunrpc/svc_xprt.c b/net/sunrpc/svc_xprt.c
> > index ae25405d8bd22672a361d1fd3adfdcebb403f90f..32018557797b1f683d8b7259f5fccd029aebcd71 100644
> > --- a/net/sunrpc/svc_xprt.c
> > +++ b/net/sunrpc/svc_xprt.c
> > @@ -488,6 +488,7 @@ void svc_xprt_enqueue(struct svc_xprt *xprt)
> >  	pool = svc_pool_for_cpu(xprt->xpt_server);
> >  
> >  	percpu_counter_inc(&pool->sp_sockets_queued);
> > +	xprt->xpt_qtime = ktime_get();
> >  	lwq_enqueue(&xprt->xpt_ready, &pool->sp_xprts);
> >  
> >  	svc_pool_wake_idle_thread(pool);
> > 
> 
> 

-- 
Jeff Layton <jlayton@kernel.org>