Commit 3705ad64 authored by Jeff Layton's avatar Jeff Layton Committed by Trond Myklebust
Browse files

sunrpc: add new tracepoints in xprt handling code 



...so we can keep track of when calls are sent and replies received.

Signed-off-by: default avatarJeff Layton <jlayton@primarydata.com>
Signed-off-by: default avatarTrond Myklebust <trond.myklebust@primarydata.com>
parent 860a0d9e

include/trace/events/sunrpc.h

+63 −0
Original line number Diff line number Diff line
@@ -307,6 +307,69 @@ DEFINE_RPC_SOCKET_EVENT_DONE(rpc_socket_reset_connection); 
DEFINE_RPC_SOCKET_EVENT(rpc_socket_close);

DEFINE_RPC_SOCKET_EVENT(rpc_socket_shutdown);



DECLARE_EVENT_CLASS(rpc_xprt_event,

	TP_PROTO(struct rpc_xprt *xprt, __be32 xid, int status),



	TP_ARGS(xprt, xid, status),



	TP_STRUCT__entry(

		__field(__be32, xid)

		__field(int, status)

		__string(addr, xprt->address_strings[RPC_DISPLAY_ADDR])

		__string(port, xprt->address_strings[RPC_DISPLAY_PORT])

	),



	TP_fast_assign(

		__entry->xid = xid;

		__entry->status = status;

		__assign_str(addr, xprt->address_strings[RPC_DISPLAY_ADDR]);

		__assign_str(port, xprt->address_strings[RPC_DISPLAY_PORT]);

	),



	TP_printk("peer=%s/%s xid=0x%x status=%d", __get_str(addr),

			__get_str(port), be32_to_cpu(__entry->xid),

			__entry->status)

);



DEFINE_EVENT(rpc_xprt_event, xprt_lookup_rqst,

	TP_PROTO(struct rpc_xprt *xprt, __be32 xid, int status),

	TP_ARGS(xprt, xid, status));



DEFINE_EVENT(rpc_xprt_event, xprt_transmit,

	TP_PROTO(struct rpc_xprt *xprt, __be32 xid, int status),

	TP_ARGS(xprt, xid, status));



DEFINE_EVENT(rpc_xprt_event, xprt_complete_rqst,

	TP_PROTO(struct rpc_xprt *xprt, __be32 xid, int status),

	TP_ARGS(xprt, xid, status));



TRACE_EVENT(xs_tcp_data_ready,

	TP_PROTO(struct rpc_xprt *xprt, int err, unsigned int total),



	TP_ARGS(xprt, err, total),



	TP_STRUCT__entry(

		__field(int, err)

		__field(unsigned int, total)

		__string(addr, xprt ? xprt->address_strings[RPC_DISPLAY_ADDR] :

				"(null)")

		__string(port, xprt ? xprt->address_strings[RPC_DISPLAY_PORT] :

				"(null)")

	),



	TP_fast_assign(

		__entry->err = err;

		__entry->total = total;

		__assign_str(addr, xprt ?

			xprt->address_strings[RPC_DISPLAY_ADDR] : "(null)");

		__assign_str(port, xprt ?

			xprt->address_strings[RPC_DISPLAY_PORT] : "(null)");

	),



	TP_printk("peer=[%s]:%s err=%d total=%u", __get_str(addr),

			__get_str(port), __entry->err, __entry->total)

);



TRACE_EVENT(svc_recv,

	TP_PROTO(struct svc_rqst *rqst, int status),

net/sunrpc/xprt.c

+8 −1
Original line number Diff line number Diff line
@@ -49,6 +49,8 @@ 
#include <linux/sunrpc/metrics.h>

#include <linux/sunrpc/bc_xprt.h>



#include <trace/events/sunrpc.h>



#include "sunrpc.h"



/*
@@ -772,11 +774,14 @@ struct rpc_rqst *xprt_lookup_rqst(struct rpc_xprt *xprt, __be32 xid) 
	struct rpc_rqst *entry;



	list_for_each_entry(entry, &xprt->recv, rq_list)

		if (entry->rq_xid == xid)

		if (entry->rq_xid == xid) {

			trace_xprt_lookup_rqst(xprt, xid, 0);

			return entry;

		}



	dprintk("RPC:       xprt_lookup_rqst did not find xid %08x\n",

			ntohl(xid));

	trace_xprt_lookup_rqst(xprt, xid, -ENOENT);

	xprt->stat.bad_xids++;

	return NULL;

}
@@ -810,6 +815,7 @@ void xprt_complete_rqst(struct rpc_task *task, int copied) 


	dprintk("RPC: %5u xid %08x complete (%d bytes received)\n",

			task->tk_pid, ntohl(req->rq_xid), copied);

	trace_xprt_complete_rqst(xprt, req->rq_xid, copied);



	xprt->stat.recvs++;

	req->rq_rtt = ktime_sub(ktime_get(), req->rq_xtime);
@@ -926,6 +932,7 @@ void xprt_transmit(struct rpc_task *task) 


	req->rq_xtime = ktime_get();

	status = xprt->ops->send_request(task);

	trace_xprt_transmit(xprt, req->rq_xid, status);

	if (status != 0) {

		task->tk_status = status;

		return;

net/sunrpc/xprtsock.c

+7 −1
Original line number Diff line number Diff line
@@ -1454,12 +1454,15 @@ static void xs_tcp_data_ready(struct sock *sk) 
	struct rpc_xprt *xprt;

	read_descriptor_t rd_desc;

	int read;

	unsigned long total = 0;



	dprintk("RPC:       xs_tcp_data_ready...\n");



	read_lock_bh(&sk->sk_callback_lock);

	if (!(xprt = xprt_from_sock(sk)))

	if (!(xprt = xprt_from_sock(sk))) {

		read = 0;

		goto out;

	}

	/* Any data means we had a useful conversation, so

	 * the we don't need to delay the next reconnect

	 */
@@ -1471,8 +1474,11 @@ static void xs_tcp_data_ready(struct sock *sk) 
	do {

		rd_desc.count = 65536;

		read = tcp_read_sock(sk, &rd_desc, xs_tcp_data_recv);

		if (read > 0)

			total += read;

	} while (read > 0);

out:

	trace_xs_tcp_data_ready(xprt, read, total);

	read_unlock_bh(&sk->sk_callback_lock);

}