SUNRPC: Update debugging instrumentation in xprt_do_reserve()

Replace a dprintk() with a tracepoint. The tracepoint marks the
point where an RPC request is assigned an XID.

Additional clean up: Remove trace_xprt_enq_xmit, which reports much
the same thing. That tracepoint was added for debugging commit
918f3c1fe83c ("SUNRPC: Improve latency for interactive tasks").

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
Signed-off-by: Anna Schumaker <Anna.Schumaker@Netapp.com>

diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
index 7addf7d1596bd074ad2395cf0a428a61c48b1f23..781277bb9cb240aabf2eee418dc4e3525a65e9b9 100644 (file)
--- a/include/trace/events/sunrpc.h
+++ b/include/trace/events/sunrpc.h
@@ -1031,37 +1031,6 @@ TRACE_EVENT(xprt_transmit,
                __entry->seqno, __entry->status)
 );
 
-TRACE_EVENT(xprt_enq_xmit,
-       TP_PROTO(
-               const struct rpc_task *task,
-               int stage
-       ),
-
-       TP_ARGS(task, stage),
-
-       TP_STRUCT__entry(
-               __field(unsigned int, task_id)
-               __field(unsigned int, client_id)
-               __field(u32, xid)
-               __field(u32, seqno)
-               __field(int, stage)
-       ),
-
-       TP_fast_assign(
-               __entry->task_id = task->tk_pid;
-               __entry->client_id = task->tk_client ?
-                       task->tk_client->cl_clid : -1;
-               __entry->xid = be32_to_cpu(task->tk_rqstp->rq_xid);
-               __entry->seqno = task->tk_rqstp->rq_seqno;
-               __entry->stage = stage;
-       ),
-
-       TP_printk(
-               "task:%u@%u xid=0x%08x seqno=%u stage=%d",
-               __entry->task_id, __entry->client_id, __entry->xid,
-               __entry->seqno, __entry->stage)
-);
-
 TRACE_EVENT(xprt_ping,
        TP_PROTO(const struct rpc_xprt *xprt, int status),
 
@@ -1176,6 +1145,30 @@ DEFINE_CONG_EVENT(release_cong);
 DEFINE_CONG_EVENT(get_cong);
 DEFINE_CONG_EVENT(put_cong);
 
+TRACE_EVENT(xprt_reserve,
+       TP_PROTO(
+               const struct rpc_rqst *rqst
+       ),
+
+       TP_ARGS(rqst),
+
+       TP_STRUCT__entry(
+               __field(unsigned int, task_id)
+               __field(unsigned int, client_id)
+               __field(u32, xid)
+       ),
+
+       TP_fast_assign(
+               __entry->task_id = rqst->rq_task->tk_pid;
+               __entry->client_id = rqst->rq_task->tk_client->cl_clid;
+               __entry->xid = be32_to_cpu(rqst->rq_xid);
+       ),
+
+       TP_printk("task:%u@%u xid=0x%08x",
+               __entry->task_id, __entry->client_id, __entry->xid
+       )
+);
+
 TRACE_EVENT(xs_stream_read_data,
        TP_PROTO(struct rpc_xprt *xprt, ssize_t err, size_t total),
 

diff --git a/net/sunrpc/xprt.c b/net/sunrpc/xprt.c
index 2217dfed8f88ac01e1ad73da753f51181be9a1dc..0e4659bd72f4f2ac2f353f8089da139e52dd720c 100644 (file)
--- a/net/sunrpc/xprt.c
+++ b/net/sunrpc/xprt.c
@@ -1267,7 +1267,6 @@ xprt_request_enqueue_transmit(struct rpc_task *task)
                                /* Note: req is added _before_ pos */
                                list_add_tail(&req->rq_xmit, &pos->rq_xmit);
                                INIT_LIST_HEAD(&req->rq_xmit2);
-                               trace_xprt_enq_xmit(task, 1);
                                goto out;
                        }
                } else if (RPC_IS_SWAPPER(task)) {
@@ -1279,7 +1278,6 @@ xprt_request_enqueue_transmit(struct rpc_task *task)
                                /* Note: req is added _before_ pos */
                                list_add_tail(&req->rq_xmit, &pos->rq_xmit);
                                INIT_LIST_HEAD(&req->rq_xmit2);
-                               trace_xprt_enq_xmit(task, 2);
                                goto out;
                        }
                } else if (!req->rq_seqno) {
@@ -1288,13 +1286,11 @@ xprt_request_enqueue_transmit(struct rpc_task *task)
                                        continue;
                                list_add_tail(&req->rq_xmit2, &pos->rq_xmit2);
                                INIT_LIST_HEAD(&req->rq_xmit);
-                               trace_xprt_enq_xmit(task, 3);
                                goto out;
                        }
                }
                list_add_tail(&req->rq_xmit, &xprt->xmit_queue);
                INIT_LIST_HEAD(&req->rq_xmit2);
-               trace_xprt_enq_xmit(task, 4);
 out:
                set_bit(RPC_TASK_NEED_XMIT, &task->tk_runstate);
                spin_unlock(&xprt->queue_lock);
@@ -1745,8 +1741,8 @@ xprt_request_init(struct rpc_task *task)
        req->rq_rcv_buf.bvec = NULL;
        req->rq_release_snd_buf = NULL;
        xprt_init_majortimeo(task, req);
-       dprintk("RPC: %5u reserved req %p xid %08x\n", task->tk_pid,
-                       req, ntohl(req->rq_xid));
+
+       trace_xprt_reserve(req);
 }
 
 static void