Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 55f5088c authored by Chuck Lever's avatar Chuck Lever Committed by J. Bruce Fields
Browse files

svc: Report xprt dequeue latency 



Record the time between when a rqstp is enqueued on a transport
and when it is dequeued. This includes how long the rqstp waits on
the queue and how long it takes the kernel scheduler to wake a
nfsd thread to service it.

The svc_xprt_dequeue trace point is altered to include the number
of microseconds between xprt_enqueue and xprt_dequeue.

Signed-off-by: default avatarChuck Lever <chuck.lever@oracle.com>
Signed-off-by: default avatarJ. Bruce Fields <bfields@redhat.com>
parent aaba72cd

include/linux/sunrpc/svc.h

+1 −0
Original line number Diff line number Diff line
@@ -272,6 +272,7 @@ struct svc_rqst { 
#define	RQ_BUSY		(6)			/* request is busy */

#define	RQ_DATA		(7)			/* request has data */

	unsigned long		rq_flags;	/* flags field */

	ktime_t			rq_qtime;	/* enqueue time */



	void *			rq_argp;	/* decoded arguments */

	void *			rq_resp;	/* xdr'd results */

include/trace/events/sunrpc.h

+26 −4
Original line number Diff line number Diff line
@@ -657,14 +657,36 @@ DECLARE_EVENT_CLASS(svc_xprt_event, 
			show_svc_xprt_flags(__entry->flags))

);



DEFINE_EVENT(svc_xprt_event, svc_xprt_dequeue,

	TP_PROTO(struct svc_xprt *xprt),

	TP_ARGS(xprt));



DEFINE_EVENT(svc_xprt_event, svc_xprt_no_write_space,

	TP_PROTO(struct svc_xprt *xprt),

	TP_ARGS(xprt));



TRACE_EVENT(svc_xprt_dequeue,

	TP_PROTO(struct svc_rqst *rqst),



	TP_ARGS(rqst),



	TP_STRUCT__entry(

		__field(struct svc_xprt *, xprt)

		__field(unsigned long, flags)

		__field(unsigned long, wakeup)

		__string(addr, rqst->rq_xprt->xpt_remotebuf)

	),



	TP_fast_assign(

		__entry->xprt = rqst->rq_xprt;

		__entry->flags = rqst->rq_xprt->xpt_flags;

		__entry->wakeup = ktime_to_us(ktime_sub(ktime_get(),

							rqst->rq_qtime));

		__assign_str(addr, rqst->rq_xprt->xpt_remotebuf);

	),



	TP_printk("xprt=%p addr=%s flags=%s wakeup-us=%lu",

			__entry->xprt, __get_str(addr),

			show_svc_xprt_flags(__entry->flags),

			__entry->wakeup)

);



TRACE_EVENT(svc_wake_up,

	TP_PROTO(int pid),

net/sunrpc/svc_xprt.c

+2 −2
Original line number Diff line number Diff line
@@ -409,6 +409,7 @@ void svc_xprt_do_enqueue(struct svc_xprt *xprt) 
		if (test_and_set_bit(RQ_BUSY, &rqstp->rq_flags))

			continue;

		atomic_long_inc(&pool->sp_stats.threads_woken);

		rqstp->rq_qtime = ktime_get();

		wake_up_process(rqstp->rq_task);

		goto out_unlock;

	}
@@ -530,7 +531,6 @@ void svc_wake_up(struct svc_serv *serv) 
		if (test_bit(RQ_BUSY, &rqstp->rq_flags))

			continue;

		rcu_read_unlock();

		dprintk("svc: daemon %p woken up.\n", rqstp);

		wake_up_process(rqstp->rq_task);

		trace_svc_wake_up(rqstp->rq_task->pid);

		return;
@@ -726,7 +726,7 @@ static struct svc_xprt *svc_get_next_xprt(struct svc_rqst *rqstp, long timeout) 
		rqstp->rq_chandle.thread_wait = 5*HZ;

	else

		rqstp->rq_chandle.thread_wait = 1*HZ;

	trace_svc_xprt_dequeue(rqstp->rq_xprt);

	trace_svc_xprt_dequeue(rqstp);

	return rqstp->rq_xprt;

}