| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Message-ID: <3a0f1d72228621e970307c9d0d49dc12995e2c50.camel@kernel.org>
Date: Fri, 11 Apr 2025 09:40:51 -0400
From: Jeff Layton <jlayton@...nel.org>
To: Chuck Lever <chuck.lever@...cle.com>, Neil Brown <neilb@...e.de>, Olga
Kornievskaia <okorniev@...hat.com>, Dai Ngo <Dai.Ngo@...cle.com>, Tom
Talpey <tom@...pey.com>, Trond Myklebust <trondmy@...nel.org>, Anna
Schumaker <anna@...nel.org>
Cc: Sargun Dillon <sargun@...gun.me>, linux-nfs@...r.kernel.org,
linux-kernel@...r.kernel.org
Subject: Re: [PATCH v2 02/12] sunrpc: add info about xprt queue times to
svc_xprt_dequeue tracepoint
On Fri, 2025-04-11 at 09:24 -0400, Chuck Lever wrote:
> On 4/11/25 9:10 AM, Jeff Layton wrote:
> > On Wed, 2025-04-09 at 11:26 -0400, Jeff Layton wrote:
> > > 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.
> > >
> >
> > Hi Chuck! If you're OK with my rationale above, I'd like to expedite
> > merging this patch in particular.
> >
> > The reason is that we have clients with the nfs_layout_flexfiles
> > dataserver_timeo module parameter set for 6s. This helps them switch to
> > an alternate mirror when a DS goes down, but we see a lot of RPC
> > timeouts when this is set.
> >
> > My theory is that the xprts are getting queued and it's taking a long
> > time for a thread to pick it up. That should show up as a large value
> > in the qtime field in this tracepoint if I'm correct.
> >
> > Would you be amenable to that?
>
> No objection, repost this one with the beefier rationale.
>
Will do.
> But it depends on what you mean by "expedite" -- v6.16 would be the
> next "normal" opportunity, since this change doesn't qualify as a
> bug fix.
>
I was hoping for v6.15, as I don't want to wait months to figure this
out. Eventually, I need this in a particular downstream distribution
that is reticent to take patches that aren't already merged.
>
> > > > > Signed-off-by: Jeff Layton <jlayton@...nel.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@...nel.org>
Powered by blists - more mailing lists