sunrpc: new tracepoints for call/reply tracking

PATCH In review Jeff Layton 3 participants 7 messages Oct 28, 2014 – Nov 7, 2014

Subsystems (4)

Networking NFS client NFS server Tracing

lore

Share & tools

lore

Jeff Layton

author

2014-10-28 18:24 UTC #0 lore raw

cover sunrpc: new tracepoints for call/reply tracking

These patches add some tracepoints that I recently used when tracking down the hang that Christoph reported recently. At this point, I still haven't followed the trail to completion, but I think the problem is not likely to be in the RPC code.

Please consider these for v3.19? Some of these are for client RPC and some for server-side. I'll assume that Trond will merge these, but review by others would be appreciated as well.

Jeff Layton (3):
sunrpc: add some tracepoints in svc_rqst handling functions
sunrpc: add new tracepoints in xprt handling code
sunrpc: add tracepoints in xs_tcp_data_recv

 include/linux/sunrpc/xprtsock.h |  59 +++++++++++++++
 include/trace/events/sunrpc.h   | 160 ++++++++++++++++++++++++++++++++++++++++
 net/sunrpc/svc.c                |  21 +++---
 net/sunrpc/svc_xprt.c           |  31 +++++---
 net/sunrpc/xprt.c               |   9 ++-
 net/sunrpc/xprtsock.c           |  69 +++--------------
 6 files changed, 269 insertions(+), 80 deletions(-)

Signature · 1 line

1.9.3

Jeff Layton

author

2014-10-28 18:24 UTC #1 lore raw

PATCH 1/3 sunrpc: add some tracepoints in svc_rqst handling functions

...just around svc_send, svc_recv and svc_process for now.

Signed-off-by Jeff Layton <[email protected]>

---
 include/trace/events/sunrpc.h | 55 +++++++++++++++++++++++++++++++++++++++++++
 net/sunrpc/svc.c              | 21 ++++++++++-------
 net/sunrpc/svc_xprt.c         | 31 ++++++++++++++++--------
 3 files changed, 88 insertions(+), 19 deletions(-)

include/trace/events/sunrpc.h +55 -0

index 1fef3e6e9436..6260f5134212 100644
@@ -6,6 +6,7 @@
 
 #include <linux/sunrpc/sched.h>
 #include <linux/sunrpc/clnt.h>
+#include <linux/sunrpc/svc.h>
 #include <net/tcp_states.h>
 #include <linux/net.h>
 #include <linux/tracepoint.h>

@@ -306,6 +307,60 @@ DEFINE_RPC_SOCKET_EVENT_DONE(rpc_socket_reset_connection);
 DEFINE_RPC_SOCKET_EVENT(rpc_socket_close);
 DEFINE_RPC_SOCKET_EVENT(rpc_socket_shutdown);
 
+TRACE_EVENT(svc_recv,
+	TP_PROTO(struct svc_rqst *rqst, int status),
+
+	TP_ARGS(rqst, status),
+
+	TP_STRUCT__entry(
+		__field(struct sockaddr *, addr)
+		__field(__be32, xid)
+		__field(int, status)
+	),
+
+	TP_fast_assign(
+		__entry->addr = (struct sockaddr *)&rqst->rq_addr;
+		__entry->xid = status > 0 ? rqst->rq_xid : 0;
+		__entry->status = status;
+	),
+
+	TP_printk("addr=%pIScp xid=0x%x status=%d", __entry->addr,
+			be32_to_cpu(__entry->xid), __entry->status)
+);
+
+DECLARE_EVENT_CLASS(svc_rqst_status,
+
+	TP_PROTO(struct svc_rqst *rqst, int status),
+
+	TP_ARGS(rqst, status),
+
+	TP_STRUCT__entry(
+		__field(struct sockaddr *, addr)
+		__field(__be32, xid)
+		__field(int, dropme)
+		__field(int, status)
+	),
+
+	TP_fast_assign(
+		__entry->addr = (struct sockaddr *)&rqst->rq_addr;
+		__entry->xid = rqst->rq_xid;
+		__entry->dropme = (int)rqst->rq_dropme;
+		__entry->status = status;
+	),
+
+	TP_printk("addr=%pIScp rq_xid=0x%x dropme=%d status=%d",
+		__entry->addr, be32_to_cpu(__entry->xid), __entry->dropme,
+		__entry->status)
+);
+
+DEFINE_EVENT(svc_rqst_status, svc_process,
+	TP_PROTO(struct svc_rqst *rqst, int status),
+	TP_ARGS(rqst, status));
+
+DEFINE_EVENT(svc_rqst_status, svc_send,
+	TP_PROTO(struct svc_rqst *rqst, int status),
+	TP_ARGS(rqst, status));
+
 #endif /* _TRACE_SUNRPC_H */
 
 #include <trace/define_trace.h>

net/sunrpc/svc.c +12 -9

index ca8a7958f4e6..371a8bbb43d6 100644
@@ -28,6 +28,8 @@
 #include <linux/sunrpc/clnt.h>
 #include <linux/sunrpc/bc_xprt.h>
 
+#include <trace/events/sunrpc.h>
+
 #define RPCDBG_FACILITY	RPCDBG_SVCDSP
 
 static void svc_unregister(const struct svc_serv *serv, struct net *net);

@@ -1314,24 +1316,25 @@ svc_process(struct svc_rqst *rqstp)
 	rqstp->rq_res.tail[0].iov_base = NULL;
 	rqstp->rq_res.tail[0].iov_len = 0;
 
-	rqstp->rq_xid = svc_getu32(argv);
-
 	dir  = svc_getnl(argv);
 	if (dir != 0) {
 		/* direction != CALL */
 		svc_printk(rqstp, "bad direction %d, dropping request\n", dir);
 		serv->sv_stats->rpcbadfmt++;
-		svc_drop(rqstp);
-		return 0;
+		goto out_drop;
 	}
 
 	/* Returns 1 for send, 0 for drop */
-	if (svc_process_common(rqstp, argv, resv))
-		return svc_send(rqstp);
-	else {
-		svc_drop(rqstp);
-		return 0;
+	if (likely(svc_process_common(rqstp, argv, resv))) {
+		int ret = svc_send(rqstp);
+
+		trace_svc_process(rqstp, ret);
+		return ret;
 	}
+out_drop:
+	trace_svc_process(rqstp, 0);
+	svc_drop(rqstp);
+	return 0;
 }
 
 #if defined(CONFIG_SUNRPC_BACKCHANNEL)

net/sunrpc/svc_xprt.c +21 ~~-10~~

index c179ca2a5aa4..bbb3b044b877 100644
@@ -15,6 +15,7 @@
 #include <linux/sunrpc/svcsock.h>
 #include <linux/sunrpc/xprt.h>
 #include <linux/module.h>
+#include <trace/events/sunrpc.h>
 
 #define RPCDBG_FACILITY	RPCDBG_SVCXPRT

@@ -773,35 +774,43 @@ int svc_recv(struct svc_rqst *rqstp, long timeout)
 
 	err = svc_alloc_arg(rqstp);
 	if (err)
-		return err;
+		goto out;
 
 	try_to_freeze();
 	cond_resched();
+	err = -EINTR;
 	if (signalled() || kthread_should_stop())
-		return -EINTR;
+		goto out;
 
 	xprt = svc_get_next_xprt(rqstp, timeout);
-	if (IS_ERR(xprt))
-		return PTR_ERR(xprt);
+	if (IS_ERR(xprt)) {
+		err = PTR_ERR(xprt);
+		goto out;
+	}
 
 	len = svc_handle_xprt(rqstp, xprt);
 
 	/* No data, incomplete (TCP) read, or accept() */
+	err = -EAGAIN;
 	if (len <= 0)
-		goto out;
+		goto out_release;
 
 	clear_bit(XPT_OLD, &xprt->xpt_flags);
 
 	rqstp->rq_secure = xprt->xpt_ops->xpo_secure_port(rqstp);
 	rqstp->rq_chandle.defer = svc_defer;
+	rqstp->rq_xid = svc_getu32(&rqstp->rq_arg.head[0]);
 
 	if (serv->sv_stats)
 		serv->sv_stats->netcnt++;
+	trace_svc_recv(rqstp, len);
 	return len;
-out:
+out_release:
 	rqstp->rq_res.len = 0;
 	svc_xprt_release(rqstp);
-	return -EAGAIN;
+out:
+	trace_svc_recv(rqstp, err);
+	return err;
 }
 EXPORT_SYMBOL_GPL(svc_recv);

@@ -821,12 +830,12 @@ EXPORT_SYMBOL_GPL(svc_drop);
 int svc_send(struct svc_rqst *rqstp)
 {
 	struct svc_xprt	*xprt;
-	int		len;
+	int		len = -EFAULT;
 	struct xdr_buf	*xb;
 
 	xprt = rqstp->rq_xprt;
 	if (!xprt)
-		return -EFAULT;
+		goto out;
 
 	/* release the receive skb before sending the reply */
 	rqstp->rq_xprt->xpt_ops->xpo_release_rqst(rqstp);

@@ -849,7 +858,9 @@ int svc_send(struct svc_rqst *rqstp)
 	svc_xprt_release(rqstp);
 
 	if (len == -ECONNREFUSED || len == -ENOTCONN || len == -EAGAIN)
-		return 0;
+		len = 0;
+out:
+	trace_svc_send(rqstp, len);
 	return len;
 }

Signature · 1 line

1.9.3

Jeff Layton

author

2014-10-28 18:24 UTC #2 lore raw

PATCH 2/3 sunrpc: add new tracepoints in xprt handling code

In reply to Jeff Layton

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

Signed-off-by Jeff Layton <[email protected]>

---
 include/trace/events/sunrpc.h | 63 +++++++++++++++++++++++++++++++++++++++++++
 net/sunrpc/xprt.c             |  9 ++++++-
 net/sunrpc/xprtsock.c         |  8 +++++-
 3 files changed, 78 insertions(+), 2 deletions(-)

include/trace/events/sunrpc.h +63 -0

index 6260f5134212..5edb16bcd836 100644
@@ -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

index 56e4e150e80e..1b2e5e616cae 100644
@@ -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

index 3b305ab17afe..b63e26272dc2 100644
@@ -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);
 }

Signature · 1 line

1.9.3

Jeff Layton

author

2014-10-28 18:24 UTC #3 lore raw

PATCH 3/3 sunrpc: add tracepoints in xs_tcp_data_recv

In reply to Jeff Layton

Add tracepoints inside the main loop on xs_tcp_data_recv that allow us to keep an eye on what's happening during each phase of it.

Signed-off-by Jeff Layton <[email protected]>

---
 include/linux/sunrpc/xprtsock.h | 59 +++++++++++++++++++++++++++++++++++++++
 include/trace/events/sunrpc.h   | 44 ++++++++++++++++++++++++++++-
 net/sunrpc/xprtsock.c           | 61 ++---------------------------------------
 3 files changed, 104 insertions(+), 60 deletions(-)

include/linux/sunrpc/xprtsock.h +59 -0

index 1ad36cc25b2e..7591788e9fbf 100644
@@ -17,6 +17,65 @@ void		cleanup_socket_xprt(void);
 #define RPC_DEF_MIN_RESVPORT	(665U)
 #define RPC_DEF_MAX_RESVPORT	(1023U)
 
+struct sock_xprt {
+	struct rpc_xprt		xprt;
+
+	/*
+	 * Network layer
+	 */
+	struct socket *		sock;
+	struct sock *		inet;
+
+	/*
+	 * State of TCP reply receive
+	 */
+	__be32			tcp_fraghdr,
+				tcp_xid,
+				tcp_calldir;
+
+	u32			tcp_offset,
+				tcp_reclen;
+
+	unsigned long		tcp_copied,
+				tcp_flags;
+
+	/*
+	 * Connection of transports
+	 */
+	struct delayed_work	connect_worker;
+	struct sockaddr_storage	srcaddr;
+	unsigned short		srcport;
+
+	/*
+	 * UDP socket buffer size parameters
+	 */
+	size_t			rcvsize,
+				sndsize;
+
+	/*
+	 * Saved socket callback addresses
+	 */
+	void			(*old_data_ready)(struct sock *);
+	void			(*old_state_change)(struct sock *);
+	void			(*old_write_space)(struct sock *);
+	void			(*old_error_report)(struct sock *);
+};
+
+/*
+ * TCP receive state flags
+ */
+#define TCP_RCV_LAST_FRAG	(1UL << 0)
+#define TCP_RCV_COPY_FRAGHDR	(1UL << 1)
+#define TCP_RCV_COPY_XID	(1UL << 2)
+#define TCP_RCV_COPY_DATA	(1UL << 3)
+#define TCP_RCV_READ_CALLDIR	(1UL << 4)
+#define TCP_RCV_COPY_CALLDIR	(1UL << 5)
+
+/*
+ * TCP RPC flags
+ */
+#define TCP_RPC_REPLY		(1UL << 6)
+
 #endif /* __KERNEL__ */
 
 #endif /* _LINUX_SUNRPC_XPRTSOCK_H */

include/trace/events/sunrpc.h +43 -1

62 lines not on this page · raw message

net/sunrpc/xprtsock.c +2 ~~-59~~

79 lines not on this page · raw message

Signature · 1 line

1.9.3

J. Bruce Fields

2014-11-06 20:20 UTC #4 lore raw

In reply to Jeff Layton

Quoted 8 lines · Jeff Layton

These patches add some tracepoints that I recently used when tracking down the hang that Christoph reported recently. At this point, I still haven't followed the trail to completion, but I think the problem is not likely to be in the RPC code.
Please consider these for v3.19? Some of these are for client RPC and some for server-side. I'll assume that Trond will merge these, but review by others would be appreciated as well.

Looks fine to me, thanks, I'll assume Trond's applying all three unless I hear otherwise.

(Separate issue: the server-side rpc dprintk's need review: they're much too frequent to be useful, I think.)

--b.

Quoted 17 lines

Jeff Layton (3):
sunrpc: add some tracepoints in svc_rqst handling functions
sunrpc: add new tracepoints in xprt handling code
sunrpc: add tracepoints in xs_tcp_data_recv
 include/linux/sunrpc/xprtsock.h |  59 +++++++++++++++
 include/trace/events/sunrpc.h   | 160 ++++++++++++++++++++++++++++++++++++++++
 net/sunrpc/svc.c                |  21 +++---
 net/sunrpc/svc_xprt.c           |  31 +++++---
 net/sunrpc/xprt.c               |   9 ++-
 net/sunrpc/xprtsock.c           |  69 +++--------------
 6 files changed, 269 insertions(+), 80 deletions(-)
Signature · 1 line
1.9.3

Jeff Layton

2014-11-06 21:58 UTC #5 lore raw

Quoted 10 lines · On Thu, 6 Nov 2014 15:20:09 -0500 "J. Bruce Fields" <[email protected]>…

Quoted 8 lines · Jeff Layton
These patches add some tracepoints that I recently used when tracking down the hang that Christoph reported recently. At this point, I still haven't followed the trail to completion, but I think the problem is not likely to be in the RPC code.
Please consider these for v3.19? Some of these are for client RPC and some for server-side. I'll assume that Trond will merge these, but review by others would be appreciated as well.

Quoted 6 lines

Looks fine to me, thanks, I'll assume Trond's applying all three unless I hear otherwise.
(Separate issue: the server-side rpc dprintk's need review: they're much too frequent to be useful, I think.)

Thanks.

Yeah. Probably best to just slowly phase those out in favor of tracepoints. Is there any way to do that that's less labor intensive?

Quoted 23 lines

--b.
Quoted 6 lines
Jeff Layton (3):
sunrpc: add some tracepoints in svc_rqst handling functions
sunrpc: add new tracepoints in xprt handling code
sunrpc: add tracepoints in xs_tcp_data_recv
Quoted 11 lines
 include/linux/sunrpc/xprtsock.h |  59 +++++++++++++++
 include/trace/events/sunrpc.h   | 160 ++++++++++++++++++++++++++++++++++++++++
 net/sunrpc/svc.c                |  21 +++---
 net/sunrpc/svc_xprt.c           |  31 +++++---
 net/sunrpc/xprt.c               |   9 ++-
 net/sunrpc/xprtsock.c           |  69 +++--------------
 6 files changed, 269 insertions(+), 80 deletions(-)
Signature · 1 line
1.9.3
--
To unsubscribe from this list: send the line "unsubscribe linux-nfs" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Signature · 1 line

Jeff Layton <[email protected]>

J. Bruce Fields

2014-11-07 16:05 UTC #6 lore raw

Quoted 16 lines · Jeff Layton

Quoted 13 lines · On Thu, 6 Nov 2014 15:20:09 -0500 "J. Bruce Fields" <[email protected]>…
Quoted 8 lines · Jeff Layton
These patches add some tracepoints that I recently used when tracking down the hang that Christoph reported recently. At this point, I still haven't followed the trail to completion, but I think the problem is not likely to be in the RPC code.
Please consider these for v3.19? Some of these are for client RPC and some for server-side. I'll assume that Trond will merge these, but review by others would be appreciated as well.
Looks fine to me, thanks, I'll assume Trond's applying all three unless I hear otherwise.

Quoted 8 lines

Quoted 3 lines
(Separate issue: the server-side rpc dprintk's need review: they're much too frequent to be useful, I think.)
Thanks.
Yeah. Probably best to just slowly phase those out in favor of tracepoints. Is there any way to do that that's less labor intensive?

No idea.

I'm hoping we can just get of some of them entirely, but I don't know, I really haven't tried to look through them.

(I've just noticed that there's usually a ton of output, and recall it interfering with testing in some cases--admittedly I might just be remembering cases where someone was trying to use a slow serial interface for logging.)

--b.