leandrof/linux
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

sunrpc: Report per-RPC execution stats

Browse Source 
Introduce a mechanism to report the server-side execution latency of
each RPC. The goal is to enable user space to filter the trace
record for latency outliers, build histograms, etc.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
Signed-off-by: J. Bruce Fields <bfields@redhat.com>
This commit is contained in:
Chuck Lever 2018-03-27 10:51:39 -04:00 committed by J. Bruce Fields
parent 0b9547bf6b
commit aaba72cd4e
3 changed files with 24 additions and 1 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

1
include/linux/sunrpc/svc.h
View File

@ -283,6 +283,7 @@ struct svc_rqst {
int rq_reserved; /* space on socket outq int rq_reserved; /* space on socket outq
* reserved for this request * reserved for this request
*/ */
ktime_t rq_stime; /* start time */
struct cache_req rq_chandle; /* handle passed to caches for struct cache_req rq_chandle; /* handle passed to caches for
* request delaying * request delaying

21
include/trace/events/sunrpc.h
View File

@ -705,6 +705,27 @@ TRACE_EVENT(svc_handle_xprt,
__entry->len, show_svc_xprt_flags(__entry->flags)) __entry->len, show_svc_xprt_flags(__entry->flags))
); );
TRACE_EVENT(svc_stats_latency,
TP_PROTO(const struct svc_rqst *rqst),
TP_ARGS(rqst),
TP_STRUCT__entry(
__field(u32, xid)
__field(unsigned long, execute)
__string(addr, rqst->rq_xprt->xpt_remotebuf)
),
TP_fast_assign(
__entry->xid = be32_to_cpu(rqst->rq_xid);
__entry->execute = ktime_to_us(ktime_sub(ktime_get(),
rqst->rq_stime));
__assign_str(addr, rqst->rq_xprt->xpt_remotebuf);
),
TP_printk("addr=%s xid=0x%08x execute-us=%lu",
__get_str(addr), __entry->xid, __entry->execute)
);
DECLARE_EVENT_CLASS(svc_deferred_event, DECLARE_EVENT_CLASS(svc_deferred_event,
TP_PROTO(struct svc_deferred_req *dr), TP_PROTO(struct svc_deferred_req *dr),

3
net/sunrpc/svc_xprt.c
View File

@ -782,7 +782,7 @@ static int svc_handle_xprt(struct svc_rqst *rqstp, struct svc_xprt *xprt)
len = svc_deferred_recv(rqstp); len = svc_deferred_recv(rqstp);
else else
len = xprt->xpt_ops->xpo_recvfrom(rqstp); len = xprt->xpt_ops->xpo_recvfrom(rqstp);
dprintk("svc: got len=%d\n", len); rqstp->rq_stime = ktime_get();
rqstp->rq_reserved = serv->sv_max_mesg; rqstp->rq_reserved = serv->sv_max_mesg;
atomic_add(rqstp->rq_reserved, &xprt->xpt_reserved); atomic_add(rqstp->rq_reserved, &xprt->xpt_reserved);
} }
@ -888,6 +888,7 @@ int svc_send(struct svc_rqst *rqstp)
/* Grab mutex to serialize outgoing data. */ /* Grab mutex to serialize outgoing data. */
mutex_lock(&xprt->xpt_mutex); mutex_lock(&xprt->xpt_mutex);
trace_svc_stats_latency(rqstp);
if (test_bit(XPT_DEAD, &xprt->xpt_flags) if (test_bit(XPT_DEAD, &xprt->xpt_flags)
|| test_bit(XPT_CLOSE, &xprt->xpt_flags)) || test_bit(XPT_CLOSE, &xprt->xpt_flags))
len = -ENOTCONN; len = -ENOTCONN;