SUNRPC: Hoist trace_xprtrdma_op_allocate into generic code
authorChuck Lever <chuck.lever@oracle.com>
Wed, 8 Jul 2020 20:09:11 +0000 (16:09 -0400)
committerAnna Schumaker <Anna.Schumaker@Netapp.com>
Mon, 21 Sep 2020 14:21:08 +0000 (10:21 -0400)
Introduce a tracepoint in call_allocate that reports the exact
sizes in the RPC buffer allocation request and the status of the
result. This helps catch problems with XDR buffer provisioning,
and replaces transport-specific debugging instrumentation.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
Signed-off-by: Anna Schumaker <Anna.Schumaker@Netapp.com>
include/trace/events/rpcrdma.h
include/trace/events/sunrpc.h
net/sunrpc/clnt.c
net/sunrpc/sched.c
net/sunrpc/xprtrdma/transport.c

index abe9422..c187a9a 100644 (file)
@@ -1191,36 +1191,6 @@ TRACE_EVENT(xprtrdma_decode_seg,
  ** Allocation/release of rpcrdma_reqs and rpcrdma_reps
  **/
 
-TRACE_EVENT(xprtrdma_op_allocate,
-       TP_PROTO(
-               const struct rpc_task *task,
-               const struct rpcrdma_req *req
-       ),
-
-       TP_ARGS(task, req),
-
-       TP_STRUCT__entry(
-               __field(unsigned int, task_id)
-               __field(unsigned int, client_id)
-               __field(const void *, req)
-               __field(size_t, callsize)
-               __field(size_t, rcvsize)
-       ),
-
-       TP_fast_assign(
-               __entry->task_id = task->tk_pid;
-               __entry->client_id = task->tk_client->cl_clid;
-               __entry->req = req;
-               __entry->callsize = task->tk_rqstp->rq_callsize;
-               __entry->rcvsize = task->tk_rqstp->rq_rcvsize;
-       ),
-
-       TP_printk("task:%u@%u req=%p (%zu, %zu)",
-               __entry->task_id, __entry->client_id,
-               __entry->req, __entry->callsize, __entry->rcvsize
-       )
-);
-
 TRACE_EVENT(xprtrdma_op_free,
        TP_PROTO(
                const struct rpc_task *task,
index 75b5df2..7addf7d 100644 (file)
@@ -517,6 +517,36 @@ DEFINE_RPC_REPLY_EVENT(stale_creds);
 DEFINE_RPC_REPLY_EVENT(bad_creds);
 DEFINE_RPC_REPLY_EVENT(auth_tooweak);
 
+TRACE_EVENT(rpc_buf_alloc,
+       TP_PROTO(
+               const struct rpc_task *task,
+               int status
+       ),
+
+       TP_ARGS(task, status),
+
+       TP_STRUCT__entry(
+               __field(unsigned int, task_id)
+               __field(unsigned int, client_id)
+               __field(size_t, callsize)
+               __field(size_t, recvsize)
+               __field(int, status)
+       ),
+
+       TP_fast_assign(
+               __entry->task_id = task->tk_pid;
+               __entry->client_id = task->tk_client->cl_clid;
+               __entry->callsize = task->tk_rqstp->rq_callsize;
+               __entry->recvsize = task->tk_rqstp->rq_rcvsize;
+               __entry->status = status;
+       ),
+
+       TP_printk("task:%u@%u callsize=%zu recvsize=%zu status=%d",
+               __entry->task_id, __entry->client_id,
+               __entry->callsize, __entry->recvsize, __entry->status
+       )
+);
+
 TRACE_EVENT(rpc_call_rpcerror,
        TP_PROTO(
                const struct rpc_task *task,
index 35bbd9c..3ab9e6a 100644 (file)
@@ -1823,6 +1823,7 @@ call_allocate(struct rpc_task *task)
        req->rq_rcvsize <<= 2;
 
        status = xprt->ops->buf_alloc(task);
+       trace_rpc_buf_alloc(task, status);
        xprt_inject_disconnect(xprt);
        if (status == 0)
                return;
@@ -1831,8 +1832,6 @@ call_allocate(struct rpc_task *task)
                return;
        }
 
-       dprintk("RPC: %5u rpc_buffer allocation failed\n", task->tk_pid);
-
        if (RPC_IS_ASYNC(task) || !fatal_signal_pending(current)) {
                task->tk_action = call_allocate;
                rpc_delay(task, HZ>>4);
index 7eba20a..adce1e2 100644 (file)
@@ -1036,8 +1036,6 @@ int rpc_malloc(struct rpc_task *task)
                return -ENOMEM;
 
        buf->len = size;
-       dprintk("RPC: %5u allocated buffer of size %zu at %p\n",
-                       task->tk_pid, size, buf);
        rqst->rq_buffer = buf->data;
        rqst->rq_rbuffer = (char *)rqst->rq_buffer + rqst->rq_callsize;
        return 0;
index 053c8ab..612b60f 100644 (file)
@@ -586,11 +586,9 @@ xprt_rdma_allocate(struct rpc_task *task)
 
        rqst->rq_buffer = rdmab_data(req->rl_sendbuf);
        rqst->rq_rbuffer = rdmab_data(req->rl_recvbuf);
-       trace_xprtrdma_op_allocate(task, req);
        return 0;
 
 out_fail:
-       trace_xprtrdma_op_allocate(task, NULL);
        return -ENOMEM;
 }