[PATCH v1 0/2] Two more trace point fixes

[PATCH v1 0/2] Two more trace point fixes

[Chuck Lever]

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

[PATCH v1 1/2] SUNRPC: Fix backchannel latency metrics

[Chuck Lever]

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
 	 */

[PATCH v1 2/2] SUNRPC: Capture completion of all RPC tasks

[Chuck Lever]

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);

Re: [PATCH v1 1/2] SUNRPC: Fix backchannel latency metrics

[J. Bruce Fields]

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
>  	 */