Commit b4a7f91c authored by Chuck Lever's avatar Chuck Lever Committed by Anna Schumaker
Browse files

xprtrdma: Add trace points in the RPC Reply handler paths 



Signed-off-by: default avatarChuck Lever <chuck.lever@oracle.com>
Signed-off-by: default avatarAnna Schumaker <Anna.Schumaker@Netapp.com>
parent ab03eff5

include/trace/events/rpcrdma.h

+162 −0
Original line number Diff line number Diff line
@@ -11,6 +11,46 @@ 
#include <linux/tracepoint.h>

#include <trace/events/rdma.h>



/**

 ** Event classes

 **/



DECLARE_EVENT_CLASS(xprtrdma_reply_event,

	TP_PROTO(

		const struct rpcrdma_rep *rep

	),



	TP_ARGS(rep),



	TP_STRUCT__entry(

		__field(const void *, rep)

		__field(const void *, r_xprt)

		__field(u32, xid)

		__field(u32, version)

		__field(u32, proc)

	),



	TP_fast_assign(

		__entry->rep = rep;

		__entry->r_xprt = rep->rr_rxprt;

		__entry->xid = be32_to_cpu(rep->rr_xid);

		__entry->version = be32_to_cpu(rep->rr_vers);

		__entry->proc = be32_to_cpu(rep->rr_proc);

	),



	TP_printk("rxprt %p xid=0x%08x rep=%p: version %u proc %u",

		__entry->r_xprt, __entry->xid, __entry->rep,

		__entry->version, __entry->proc

	)

);



#define DEFINE_REPLY_EVENT(name)					\

		DEFINE_EVENT(xprtrdma_reply_event, name,		\

				TP_PROTO(				\

					const struct rpcrdma_rep *rep	\

				),					\

				TP_ARGS(rep))



/**

 ** Call events

 **/
@@ -102,6 +142,29 @@ TRACE_EVENT(xprtrdma_post_send, 
	)

);



TRACE_EVENT(xprtrdma_post_recv,

	TP_PROTO(

		const struct rpcrdma_rep *rep,

		int status

	),



	TP_ARGS(rep, status),



	TP_STRUCT__entry(

		__field(const void *, rep)

		__field(int, status)

	),



	TP_fast_assign(

		__entry->rep = rep;

		__entry->status = status;

	),



	TP_printk("rep=%p status=%d",

		__entry->rep, __entry->status

	)

);



/**

 ** Completion events

 **/
@@ -135,6 +198,105 @@ TRACE_EVENT(xprtrdma_wc_send, 
	)

);



TRACE_EVENT(xprtrdma_wc_receive,

	TP_PROTO(

		const struct rpcrdma_rep *rep,

		const struct ib_wc *wc

	),



	TP_ARGS(rep, wc),



	TP_STRUCT__entry(

		__field(const void *, rep)

		__field(unsigned int, byte_len)

		__field(unsigned int, status)

		__field(unsigned int, vendor_err)

	),



	TP_fast_assign(

		__entry->rep = rep;

		__entry->byte_len = wc->byte_len;

		__entry->status = wc->status;

		__entry->vendor_err = __entry->status ? wc->vendor_err : 0;

	),



	TP_printk("rep=%p, %u bytes: %s (%u/0x%x)",

		__entry->rep, __entry->byte_len,

		rdma_show_wc_status(__entry->status),

		__entry->status, __entry->vendor_err

	)

);



/**

 ** Reply events

 **/



TRACE_EVENT(xprtrdma_reply,

	TP_PROTO(

		const struct rpc_task *task,

		const struct rpcrdma_rep *rep,

		const struct rpcrdma_req *req,

		unsigned int credits

	),



	TP_ARGS(task, rep, req, credits),



	TP_STRUCT__entry(

		__field(unsigned int, task_id)

		__field(unsigned int, client_id)

		__field(const void *, rep)

		__field(const void *, req)

		__field(u32, xid)

		__field(unsigned int, credits)

	),



	TP_fast_assign(

		__entry->task_id = task->tk_pid;

		__entry->client_id = task->tk_client->cl_clid;

		__entry->rep = rep;

		__entry->req = req;

		__entry->xid = be32_to_cpu(rep->rr_xid);

		__entry->credits = credits;

	),



	TP_printk("task:%u@%u xid=0x%08x, %u credits, rep=%p -> req=%p",

		__entry->task_id, __entry->client_id, __entry->xid,

		__entry->credits, __entry->rep, __entry->req

	)

);



TRACE_EVENT(xprtrdma_defer_cmp,

	TP_PROTO(

		const struct rpcrdma_rep *rep

	),



	TP_ARGS(rep),



	TP_STRUCT__entry(

		__field(unsigned int, task_id)

		__field(unsigned int, client_id)

		__field(const void *, rep)

		__field(u32, xid)

	),



	TP_fast_assign(

		__entry->task_id = rep->rr_rqst->rq_task->tk_pid;

		__entry->client_id = rep->rr_rqst->rq_task->tk_client->cl_clid;

		__entry->rep = rep;

		__entry->xid = be32_to_cpu(rep->rr_xid);

	),



	TP_printk("task:%u@%u xid=0x%08x rep=%p",

		__entry->task_id, __entry->client_id, __entry->xid,

		__entry->rep

	)

);



DEFINE_REPLY_EVENT(xprtrdma_reply_vers);

DEFINE_REPLY_EVENT(xprtrdma_reply_rqst);

DEFINE_REPLY_EVENT(xprtrdma_reply_short);

DEFINE_REPLY_EVENT(xprtrdma_reply_hdr);



#endif /* _TRACE_RPCRDMA_H */



#include <trace/define_trace.h>

net/sunrpc/xprtrdma/rpc_rdma.c

+6 −11
Original line number Diff line number Diff line
@@ -1278,8 +1278,7 @@ void rpcrdma_complete_rqst(struct rpcrdma_rep *rep) 
 * being marshaled.

 */

out_badheader:

	dprintk("RPC: %5u %s: invalid rpcrdma reply (type %u)\n",

		rqst->rq_task->tk_pid, __func__, be32_to_cpu(rep->rr_proc));

	trace_xprtrdma_reply_hdr(rep);

	r_xprt->rx_stats.bad_reply_count++;

	status = -EIO;

	goto out;
@@ -1323,6 +1322,7 @@ void rpcrdma_deferred_completion(struct work_struct *work) 
	struct rpcrdma_req *req = rpcr_to_rdmar(rep->rr_rqst);

	struct rpcrdma_xprt *r_xprt = rep->rr_rxprt;



	trace_xprtrdma_defer_cmp(rep);

	if (rep->rr_wc_flags & IB_WC_WITH_INVALIDATE)

		r_xprt->rx_ia.ri_ops->ro_reminv(rep, &req->rl_registered);

	rpcrdma_release_rqst(r_xprt, req);
@@ -1344,8 +1344,6 @@ void rpcrdma_reply_handler(struct rpcrdma_rep *rep) 
	u32 credits;

	__be32 *p;



	dprintk("RPC:       %s: incoming rep %p\n", __func__, rep);



	if (rep->rr_hdrbuf.head[0].iov_len == 0)

		goto out_badstatus;
@@ -1389,8 +1387,7 @@ void rpcrdma_reply_handler(struct rpcrdma_rep *rep) 
	rep->rr_rqst = rqst;

	clear_bit(RPCRDMA_REQ_F_PENDING, &req->rl_flags);



	dprintk("RPC:       %s: reply %p completes request %p (xid 0x%08x)\n",

		__func__, rep, req, be32_to_cpu(rep->rr_xid));

	trace_xprtrdma_reply(rqst->rq_task, rep, req, credits);



	queue_work_on(req->rl_cpu, rpcrdma_receive_wq, &rep->rr_work);

	return;
@@ -1404,8 +1401,7 @@ void rpcrdma_reply_handler(struct rpcrdma_rep *rep) 
	return;



out_badversion:

	dprintk("RPC:       %s: invalid version %d\n",

		__func__, be32_to_cpu(rep->rr_vers));

	trace_xprtrdma_reply_vers(rep);

	goto repost;



/* The RPC transaction has already been terminated, or the header
@@ -1413,12 +1409,11 @@ void rpcrdma_reply_handler(struct rpcrdma_rep *rep) 
 */

out_norqst:

	spin_unlock(&xprt->recv_lock);

	dprintk("RPC:       %s: no match for incoming xid 0x%08x\n",

		__func__, be32_to_cpu(rep->rr_xid));

	trace_xprtrdma_reply_rqst(rep);

	goto repost;



out_shortreply:

	dprintk("RPC:       %s: short/invalid reply\n", __func__);

	trace_xprtrdma_reply_short(rep);



/* If no pending RPC transaction was matched, post a replacement

 * receive buffer before returning.

net/sunrpc/xprtrdma/verbs.c

+3 −8
Original line number Diff line number Diff line
@@ -156,13 +156,11 @@ rpcrdma_wc_receive(struct ib_cq *cq, struct ib_wc *wc) 
					       rr_cqe);



	/* WARNING: Only wr_id and status are reliable at this point */

	trace_xprtrdma_wc_receive(rep, wc);

	if (wc->status != IB_WC_SUCCESS)

		goto out_fail;



	/* status == SUCCESS means all fields in wc are trustworthy */

	dprintk("RPC:       %s: rep %p opcode 'recv', length %u: success\n",

		__func__, rep, wc->byte_len);



	rpcrdma_set_xdrlen(&rep->rr_hdrbuf, wc->byte_len);

	rep->rr_wc_flags = wc->wc_flags;

	rep->rr_inv_rkey = wc->ex.invalidate_rkey;
@@ -1576,17 +1574,14 @@ rpcrdma_ep_post_recv(struct rpcrdma_ia *ia, 
	if (!rpcrdma_dma_map_regbuf(ia, rep->rr_rdmabuf))

		goto out_map;

	rc = ib_post_recv(ia->ri_id->qp, &rep->rr_recv_wr, &recv_wr_fail);

	trace_xprtrdma_post_recv(rep, rc);

	if (rc)

		goto out_postrecv;

		return -ENOTCONN;

	return 0;



out_map:

	pr_err("rpcrdma: failed to DMA map the Receive buffer\n");

	return -EIO;



out_postrecv:

	pr_err("rpcrdma: ib_post_recv returned %i\n", rc);

	return -ENOTCONN;

}



/**