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
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 <[email protected]>
---
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);
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 <[email protected]>
---
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
*/
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 <[email protected]>
> ---
> 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
> */