* [PATCH v1 0/2] Two more trace point fixes @ 2019-11-20 21:25 Chuck Lever 2019-11-20 21:25 ` [PATCH v1 1/2] SUNRPC: Fix backchannel latency metrics Chuck Lever 2019-11-20 21:25 ` [PATCH v1 2/2] SUNRPC: Capture completion of all RPC tasks Chuck Lever 0 siblings, 2 replies; 4+ messages in thread From: Chuck Lever @ 2019-11-20 21:25 UTC (permalink / raw) To: bfields, trond.myklebust, anna.schumaker; +Cc: linux-nfs Found these today while testing NFS/RDMA patches. --- Chuck Lever (2): SUNRPC: Fix backchannel latency metrics SUNRPC: Capture completion of all RPC tasks include/trace/events/sunrpc.h | 1 + net/sunrpc/sched.c | 1 + net/sunrpc/xprtrdma/svc_rdma_backchannel.c | 1 + net/sunrpc/xprtsock.c | 3 ++- 4 files changed, 5 insertions(+), 1 deletion(-) -- Chuck Lever ^ permalink raw reply [flat|nested] 4+ messages in thread
* [PATCH v1 1/2] SUNRPC: Fix backchannel latency metrics 2019-11-20 21:25 [PATCH v1 0/2] Two more trace point fixes Chuck Lever @ 2019-11-20 21:25 ` Chuck Lever 2019-11-21 21:54 ` J. Bruce Fields 2019-11-20 21:25 ` [PATCH v1 2/2] SUNRPC: Capture completion of all RPC tasks Chuck Lever 1 sibling, 1 reply; 4+ messages in thread From: Chuck Lever @ 2019-11-20 21:25 UTC (permalink / raw) To: bfields, trond.myklebust, anna.schumaker; +Cc: linux-nfs I noticed that for callback requests, the reported backlog latency is always zero, and the rtt value is crazy big. The problem was that rqst->rq_xtime is never set for backchannel requests. Fixes: 78215759e20d ("SUNRPC: Make RTT measurement more ... ") Signed-off-by: Chuck Lever <chuck.lever@oracle.com> --- net/sunrpc/xprtrdma/svc_rdma_backchannel.c | 1 + net/sunrpc/xprtsock.c | 3 ++- 2 files changed, 3 insertions(+), 1 deletion(-) diff --git a/net/sunrpc/xprtrdma/svc_rdma_backchannel.c b/net/sunrpc/xprtrdma/svc_rdma_backchannel.c index d1fcc41d5eb5..908e78bb87c6 100644 --- a/net/sunrpc/xprtrdma/svc_rdma_backchannel.c +++ b/net/sunrpc/xprtrdma/svc_rdma_backchannel.c @@ -195,6 +195,7 @@ static int svc_rdma_bc_sendto(struct svcxprt_rdma *rdma, pr_info("%s: %*ph\n", __func__, 64, rqst->rq_buffer); #endif + rqst->rq_xtime = ktime_get(); rc = svc_rdma_bc_sendto(rdma, rqst, ctxt); if (rc) { svc_rdma_send_ctxt_put(rdma, ctxt); diff --git a/net/sunrpc/xprtsock.c b/net/sunrpc/xprtsock.c index 70e52f567b2a..5361b98f31ae 100644 --- a/net/sunrpc/xprtsock.c +++ b/net/sunrpc/xprtsock.c @@ -2659,6 +2659,8 @@ static int bc_sendto(struct rpc_rqst *req) .iov_len = sizeof(marker), }; + req->rq_xtime = ktime_get(); + len = kernel_sendmsg(transport->sock, &msg, &iov, 1, iov.iov_len); if (len != iov.iov_len) return -EAGAIN; @@ -2684,7 +2686,6 @@ static int bc_send_request(struct rpc_rqst *req) struct svc_xprt *xprt; int len; - dprintk("sending request with xid: %08x\n", ntohl(req->rq_xid)); /* * Get the server socket associated with this callback xprt */ ^ permalink raw reply related [flat|nested] 4+ messages in thread
* Re: [PATCH v1 1/2] SUNRPC: Fix backchannel latency metrics 2019-11-20 21:25 ` [PATCH v1 1/2] SUNRPC: Fix backchannel latency metrics Chuck Lever @ 2019-11-21 21:54 ` J. Bruce Fields 0 siblings, 0 replies; 4+ messages in thread From: J. Bruce Fields @ 2019-11-21 21:54 UTC (permalink / raw) To: Chuck Lever; +Cc: trond.myklebust, anna.schumaker, linux-nfs Applying just this one to the nfsd tree for now. --b. On Wed, Nov 20, 2019 at 04:25:46PM -0500, Chuck Lever wrote: > I noticed that for callback requests, the reported backlog latency > is always zero, and the rtt value is crazy big. The problem was that > rqst->rq_xtime is never set for backchannel requests. > > Fixes: 78215759e20d ("SUNRPC: Make RTT measurement more ... ") > Signed-off-by: Chuck Lever <chuck.lever@oracle.com> > --- > net/sunrpc/xprtrdma/svc_rdma_backchannel.c | 1 + > net/sunrpc/xprtsock.c | 3 ++- > 2 files changed, 3 insertions(+), 1 deletion(-) > > diff --git a/net/sunrpc/xprtrdma/svc_rdma_backchannel.c b/net/sunrpc/xprtrdma/svc_rdma_backchannel.c > index d1fcc41d5eb5..908e78bb87c6 100644 > --- a/net/sunrpc/xprtrdma/svc_rdma_backchannel.c > +++ b/net/sunrpc/xprtrdma/svc_rdma_backchannel.c > @@ -195,6 +195,7 @@ static int svc_rdma_bc_sendto(struct svcxprt_rdma *rdma, > pr_info("%s: %*ph\n", __func__, 64, rqst->rq_buffer); > #endif > > + rqst->rq_xtime = ktime_get(); > rc = svc_rdma_bc_sendto(rdma, rqst, ctxt); > if (rc) { > svc_rdma_send_ctxt_put(rdma, ctxt); > diff --git a/net/sunrpc/xprtsock.c b/net/sunrpc/xprtsock.c > index 70e52f567b2a..5361b98f31ae 100644 > --- a/net/sunrpc/xprtsock.c > +++ b/net/sunrpc/xprtsock.c > @@ -2659,6 +2659,8 @@ static int bc_sendto(struct rpc_rqst *req) > .iov_len = sizeof(marker), > }; > > + req->rq_xtime = ktime_get(); > + > len = kernel_sendmsg(transport->sock, &msg, &iov, 1, iov.iov_len); > if (len != iov.iov_len) > return -EAGAIN; > @@ -2684,7 +2686,6 @@ static int bc_send_request(struct rpc_rqst *req) > struct svc_xprt *xprt; > int len; > > - dprintk("sending request with xid: %08x\n", ntohl(req->rq_xid)); > /* > * Get the server socket associated with this callback xprt > */ ^ permalink raw reply [flat|nested] 4+ messages in thread
* [PATCH v1 2/2] SUNRPC: Capture completion of all RPC tasks 2019-11-20 21:25 [PATCH v1 0/2] Two more trace point fixes Chuck Lever 2019-11-20 21:25 ` [PATCH v1 1/2] SUNRPC: Fix backchannel latency metrics Chuck Lever @ 2019-11-20 21:25 ` Chuck Lever 1 sibling, 0 replies; 4+ messages in thread From: Chuck Lever @ 2019-11-20 21:25 UTC (permalink / raw) To: bfields, trond.myklebust, anna.schumaker; +Cc: linux-nfs RPC tasks on the backchannel never invoke xprt_complete_rqst(), so there is no way to report their tk_status at completion. Also, any RPC task that exits via rpc_exit_task() before it is replied to will also disappear without a trace. Introduce a trace point that is symmetrical with rpc_task_begin that captures the termination status of each RPC task. Sample trace output for callback requests initiated on the server: kworker/u8:12-448 [003] 127.025240: rpc_task_end: task:50@3 flags=ASYNC|DYNAMIC|SOFT|SOFTCONN|SENT runstate=RUNNING|ACTIVE status=0 action=rpc_exit_task kworker/u8:12-448 [002] 127.567310: rpc_task_end: task:51@3 flags=ASYNC|DYNAMIC|SOFT|SOFTCONN|SENT runstate=RUNNING|ACTIVE status=0 action=rpc_exit_task kworker/u8:12-448 [001] 130.506817: rpc_task_end: task:52@3 flags=ASYNC|DYNAMIC|SOFT|SOFTCONN|SENT runstate=RUNNING|ACTIVE status=0 action=rpc_exit_task Odd, though, that I never see trace_rpc_task_complete, either in the forward or backchannel. Should it be removed? Signed-off-by: Chuck Lever <chuck.lever@oracle.com> --- include/trace/events/sunrpc.h | 1 + net/sunrpc/sched.c | 1 + 2 files changed, 2 insertions(+) diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h index c358a0af683b..9972823085ba 100644 --- a/include/trace/events/sunrpc.h +++ b/include/trace/events/sunrpc.h @@ -185,6 +185,7 @@ DEFINE_RPC_RUNNING_EVENT(begin); DEFINE_RPC_RUNNING_EVENT(run_action); DEFINE_RPC_RUNNING_EVENT(complete); +DEFINE_RPC_RUNNING_EVENT(end); DECLARE_EVENT_CLASS(rpc_task_queued, diff --git a/net/sunrpc/sched.c b/net/sunrpc/sched.c index 360afe153193..66a7a81504bf 100644 --- a/net/sunrpc/sched.c +++ b/net/sunrpc/sched.c @@ -824,6 +824,7 @@ void rpc_prepare_task(struct rpc_task *task) */ void rpc_exit_task(struct rpc_task *task) { + trace_rpc_task_end(task, task->tk_action); task->tk_action = NULL; if (task->tk_ops->rpc_count_stats) task->tk_ops->rpc_count_stats(task, task->tk_calldata); ^ permalink raw reply related [flat|nested] 4+ messages in thread
end of thread, other threads:[~2019-11-21 21:54 UTC | newest] Thread overview: 4+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2019-11-20 21:25 [PATCH v1 0/2] Two more trace point fixes Chuck Lever 2019-11-20 21:25 ` [PATCH v1 1/2] SUNRPC: Fix backchannel latency metrics Chuck Lever 2019-11-21 21:54 ` J. Bruce Fields 2019-11-20 21:25 ` [PATCH v1 2/2] SUNRPC: Capture completion of all RPC tasks Chuck Lever
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).