| Message ID | 20250409-nfsd-tracepoints-v2-2-cf4e084fdd9c@kernel.org (mailing list archive) |
|---|---|
| State | Under Review, archived |
| Delegated to: | Chuck Lever |
| Headers | show |
| Series | nfsd: observability improvements | expand |
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? > 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); >
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); > > > >
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? > > > > > 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); > > > > > > > >
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. 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. >>>> 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); >>>> >>> >>> >> >
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@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); > > > > > > > > > > > > > > > > > > > >
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);
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. 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(-)