[PATCH v1 00/12] Add static trace points to xprtrdma

[PATCH v1 00/12] Add static trace points to xprtrdma

[Chuck Lever]

Hi Anna-

For v4.16, please consider this series, which adds a variety of
static trace points to the RPC-over-RDMA client implementation.

One short series of patches for v4.16 remains after this one.

---

Chuck Lever (12):
      rdma/ib: Add trace point macros to display human-readable values
      rpcrdma: infrastructure for static trace points in rpcrdma.ko
      xprtrdma: Add trace points in RPC Call transmit paths
      xprtrdma: Add trace points in the RPC Reply handler paths
      xprtrdma: Add trace points to instrument memory registration
      xprtrdma: Add trace points in reply decoder path
      xprtrdma: Add trace points to instrument memory invalidation
      xprtrdma: Add trace points to instrument MR allocation and recovery
      xprtrdma: Add trace points for connect events
      xprtrdma: Add trace points in the client-side backchannel code paths
      xprtrdma: Add trace points to instrument QP and CQ access upcalls
      xprtrdma: Instrument allocation/release of rpcrdma_req/rep objects


 include/trace/events/rdma.h       |  128 +++++
 include/trace/events/rpcrdma.h    |  889 +++++++++++++++++++++++++++++++++++++
 net/sunrpc/xprtrdma/backchannel.c |    8 
 net/sunrpc/xprtrdma/fmr_ops.c     |    4 
 net/sunrpc/xprtrdma/frwr_ops.c    |   38 +-
 net/sunrpc/xprtrdma/module.c      |   12 
 net/sunrpc/xprtrdma/rpc_rdma.c    |   72 +--
 net/sunrpc/xprtrdma/transport.c   |   24 -
 net/sunrpc/xprtrdma/verbs.c       |   70 +--
 net/sunrpc/xprtrdma/xprt_rdma.h   |    4 
 10 files changed, 1107 insertions(+), 142 deletions(-)
 create mode 100644 include/trace/events/rdma.h
 create mode 100644 include/trace/events/rpcrdma.h

--
Chuck Lever

[PATCH v1 01/12] rdma/ib: Add trace point macros to display human-readable values

[Chuck Lever]

These can be shared with all kernel ULPs, and more can easily be
added as needed.

Note: checkpatch.pl has some heartburn with the TRACE_DEFINE_ENUM
macros and the LIST macros. These follow the same style as other
header files under include/tracing/events , thus should be
considered acceptable exceptions.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 include/trace/events/rdma.h |  128 +++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 128 insertions(+)
 create mode 100644 include/trace/events/rdma.h

diff --git a/include/trace/events/rdma.h b/include/trace/events/rdma.h
new file mode 100644
index 0000000..9d02fbe
--- /dev/null
+++ b/include/trace/events/rdma.h
@@ -0,0 +1,128 @@
+/*
+ * Copyright (c) 2017 Oracle.  All rights reserved.
+ */
+
+/*
+ * enum ib_event_type, from include/rdma/ib_verbs.h
+ */
+
+#define IB_EVENT_LIST				\
+	ib_event(CQ_ERR)			\
+	ib_event(QP_FATAL)			\
+	ib_event(QP_REQ_ERR)			\
+	ib_event(QP_ACCESS_ERR)			\
+	ib_event(COMM_EST)			\
+	ib_event(SQ_DRAINED)			\
+	ib_event(PATH_MIG)			\
+	ib_event(PATH_MIG_ERR)			\
+	ib_event(DEVICE_FATAL)			\
+	ib_event(PORT_ACTIVE)			\
+	ib_event(PORT_ERR)			\
+	ib_event(LID_CHANGE)			\
+	ib_event(PKEY_CHANGE)			\
+	ib_event(SM_CHANGE)			\
+	ib_event(SRQ_ERR)			\
+	ib_event(SRQ_LIMIT_REACHED)		\
+	ib_event(QP_LAST_WQE_REACHED)		\
+	ib_event(CLIENT_REREGISTER)		\
+	ib_event(GID_CHANGE)			\
+	ib_event_end(WQ_FATAL)
+
+#undef ib_event
+#undef ib_event_end
+
+#define ib_event(x)		TRACE_DEFINE_ENUM(IB_EVENT_##x);
+#define ib_event_end(x)		TRACE_DEFINE_ENUM(IB_EVENT_##x);
+
+IB_EVENT_LIST
+
+#undef ib_event
+#undef ib_event_end
+
+#define ib_event(x)		{ IB_EVENT_##x, #x },
+#define ib_event_end(x)		{ IB_EVENT_##x, #x }
+
+#define rdma_show_ib_event(x) \
+		__print_symbolic(x, IB_EVENT_LIST)
+
+/*
+ * enum ib_wc_status type, from include/rdma/ib_verbs.h
+ */
+#define IB_WC_STATUS_LIST			\
+	ib_wc_status(SUCCESS)			\
+	ib_wc_status(LOC_LEN_ERR)		\
+	ib_wc_status(LOC_QP_OP_ERR)		\
+	ib_wc_status(LOC_EEC_OP_ERR)		\
+	ib_wc_status(LOC_PROT_ERR)		\
+	ib_wc_status(WR_FLUSH_ERR)		\
+	ib_wc_status(MW_BIND_ERR)		\
+	ib_wc_status(BAD_RESP_ERR)		\
+	ib_wc_status(LOC_ACCESS_ERR)		\
+	ib_wc_status(REM_INV_REQ_ERR)		\
+	ib_wc_status(REM_ACCESS_ERR)		\
+	ib_wc_status(REM_OP_ERR)		\
+	ib_wc_status(RETRY_EXC_ERR)		\
+	ib_wc_status(RNR_RETRY_EXC_ERR)		\
+	ib_wc_status(LOC_RDD_VIOL_ERR)		\
+	ib_wc_status(REM_INV_RD_REQ_ERR)	\
+	ib_wc_status(REM_ABORT_ERR)		\
+	ib_wc_status(INV_EECN_ERR)		\
+	ib_wc_status(INV_EEC_STATE_ERR)		\
+	ib_wc_status(FATAL_ERR)			\
+	ib_wc_status(RESP_TIMEOUT_ERR)		\
+	ib_wc_status_end(GENERAL_ERR)
+
+#undef ib_wc_status
+#undef ib_wc_status_end
+
+#define ib_wc_status(x)		TRACE_DEFINE_ENUM(IB_WC_##x);
+#define ib_wc_status_end(x)	TRACE_DEFINE_ENUM(IB_WC_##x);
+
+IB_WC_STATUS_LIST
+
+#undef ib_wc_status
+#undef ib_wc_status_end
+
+#define ib_wc_status(x)		{ IB_WC_##x, #x },
+#define ib_wc_status_end(x)	{ IB_WC_##x, #x }
+
+#define rdma_show_wc_status(x) \
+		__print_symbolic(x, IB_WC_STATUS_LIST)
+
+/*
+ * enum rdma_cm_event_type, from include/rdma/rdma_cm.h
+ */
+#define RDMA_CM_EVENT_LIST			\
+	rdma_cm_event(ADDR_RESOLVED)		\
+	rdma_cm_event(ADDR_ERROR)		\
+	rdma_cm_event(ROUTE_RESOLVED)		\
+	rdma_cm_event(ROUTE_ERROR)		\
+	rdma_cm_event(CONNECT_REQUEST)		\
+	rdma_cm_event(CONNECT_RESPONSE)		\
+	rdma_cm_event(CONNECT_ERROR)		\
+	rdma_cm_event(UNREACHABLE)		\
+	rdma_cm_event(REJECTED)			\
+	rdma_cm_event(ESTABLISHED)		\
+	rdma_cm_event(DISCONNECTED)		\
+	rdma_cm_event(DEVICE_REMOVAL)		\
+	rdma_cm_event(MULTICAST_JOIN)		\
+	rdma_cm_event(MULTICAST_ERROR)		\
+	rdma_cm_event(ADDR_CHANGE)		\
+	rdma_cm_event_end(TIMEWAIT_EXIT)
+
+#undef rdma_cm_event
+#undef rdma_cm_event_end
+
+#define rdma_cm_event(x)	TRACE_DEFINE_ENUM(RDMA_CM_EVENT_##x);
+#define rdma_cm_event_end(x)	TRACE_DEFINE_ENUM(RDMA_CM_EVENT_##x);
+
+RDMA_CM_EVENT_LIST
+
+#undef rdma_cm_event
+#undef rdma_cm_event_end
+
+#define rdma_cm_event(x)	{ RDMA_CM_EVENT_##x, #x },
+#define rdma_cm_event_end(x)	{ RDMA_CM_EVENT_##x, #x }
+
+#define rdma_show_cm_event(x) \
+		__print_symbolic(x, RDMA_CM_EVENT_LIST)

Re: [PATCH v1 01/12] rdma/ib: Add trace point macros to display human-readable values

[Anna Schumaker]

Hi Folks,

On 12/20/2017 04:30 PM, Chuck Lever wrote:
> These can be shared with all kernel ULPs, and more can easily be
> added as needed.
> 
> Note: checkpatch.pl has some heartburn with the TRACE_DEFINE_ENUM
> macros and the LIST macros. These follow the same style as other
> header files under include/tracing/events , thus should be
> considered acceptable exceptions.
> 
> Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
> ---
>  include/trace/events/rdma.h |  128 +++++++++++++++++++++++++++++++++++++++++++
>  1 file changed, 128 insertions(+)
>  create mode 100644 include/trace/events/rdma.h

Just checking that it's okay to send this through the NFS tree, since it goes along with the rest of Chuck's patches?

Thanks,
Anna
> 
> diff --git a/include/trace/events/rdma.h b/include/trace/events/rdma.h
> new file mode 100644
> index 0000000..9d02fbe
> --- /dev/null
> +++ b/include/trace/events/rdma.h
> @@ -0,0 +1,128 @@
> +/*
> + * Copyright (c) 2017 Oracle.  All rights reserved.
> + */
> +
> +/*
> + * enum ib_event_type, from include/rdma/ib_verbs.h
> + */
> +
> +#define IB_EVENT_LIST				\
> +	ib_event(CQ_ERR)			\
> +	ib_event(QP_FATAL)			\
> +	ib_event(QP_REQ_ERR)			\
> +	ib_event(QP_ACCESS_ERR)			\
> +	ib_event(COMM_EST)			\
> +	ib_event(SQ_DRAINED)			\
> +	ib_event(PATH_MIG)			\
> +	ib_event(PATH_MIG_ERR)			\
> +	ib_event(DEVICE_FATAL)			\
> +	ib_event(PORT_ACTIVE)			\
> +	ib_event(PORT_ERR)			\
> +	ib_event(LID_CHANGE)			\
> +	ib_event(PKEY_CHANGE)			\
> +	ib_event(SM_CHANGE)			\
> +	ib_event(SRQ_ERR)			\
> +	ib_event(SRQ_LIMIT_REACHED)		\
> +	ib_event(QP_LAST_WQE_REACHED)		\
> +	ib_event(CLIENT_REREGISTER)		\
> +	ib_event(GID_CHANGE)			\
> +	ib_event_end(WQ_FATAL)
> +
> +#undef ib_event
> +#undef ib_event_end
> +
> +#define ib_event(x)		TRACE_DEFINE_ENUM(IB_EVENT_##x);
> +#define ib_event_end(x)		TRACE_DEFINE_ENUM(IB_EVENT_##x);
> +
> +IB_EVENT_LIST
> +
> +#undef ib_event
> +#undef ib_event_end
> +
> +#define ib_event(x)		{ IB_EVENT_##x, #x },
> +#define ib_event_end(x)		{ IB_EVENT_##x, #x }
> +
> +#define rdma_show_ib_event(x) \
> +		__print_symbolic(x, IB_EVENT_LIST)
> +
> +/*
> + * enum ib_wc_status type, from include/rdma/ib_verbs.h
> + */
> +#define IB_WC_STATUS_LIST			\
> +	ib_wc_status(SUCCESS)			\
> +	ib_wc_status(LOC_LEN_ERR)		\
> +	ib_wc_status(LOC_QP_OP_ERR)		\
> +	ib_wc_status(LOC_EEC_OP_ERR)		\
> +	ib_wc_status(LOC_PROT_ERR)		\
> +	ib_wc_status(WR_FLUSH_ERR)		\
> +	ib_wc_status(MW_BIND_ERR)		\
> +	ib_wc_status(BAD_RESP_ERR)		\
> +	ib_wc_status(LOC_ACCESS_ERR)		\
> +	ib_wc_status(REM_INV_REQ_ERR)		\
> +	ib_wc_status(REM_ACCESS_ERR)		\
> +	ib_wc_status(REM_OP_ERR)		\
> +	ib_wc_status(RETRY_EXC_ERR)		\
> +	ib_wc_status(RNR_RETRY_EXC_ERR)		\
> +	ib_wc_status(LOC_RDD_VIOL_ERR)		\
> +	ib_wc_status(REM_INV_RD_REQ_ERR)	\
> +	ib_wc_status(REM_ABORT_ERR)		\
> +	ib_wc_status(INV_EECN_ERR)		\
> +	ib_wc_status(INV_EEC_STATE_ERR)		\
> +	ib_wc_status(FATAL_ERR)			\
> +	ib_wc_status(RESP_TIMEOUT_ERR)		\
> +	ib_wc_status_end(GENERAL_ERR)
> +
> +#undef ib_wc_status
> +#undef ib_wc_status_end
> +
> +#define ib_wc_status(x)		TRACE_DEFINE_ENUM(IB_WC_##x);
> +#define ib_wc_status_end(x)	TRACE_DEFINE_ENUM(IB_WC_##x);
> +
> +IB_WC_STATUS_LIST
> +
> +#undef ib_wc_status
> +#undef ib_wc_status_end
> +
> +#define ib_wc_status(x)		{ IB_WC_##x, #x },
> +#define ib_wc_status_end(x)	{ IB_WC_##x, #x }
> +
> +#define rdma_show_wc_status(x) \
> +		__print_symbolic(x, IB_WC_STATUS_LIST)
> +
> +/*
> + * enum rdma_cm_event_type, from include/rdma/rdma_cm.h
> + */
> +#define RDMA_CM_EVENT_LIST			\
> +	rdma_cm_event(ADDR_RESOLVED)		\
> +	rdma_cm_event(ADDR_ERROR)		\
> +	rdma_cm_event(ROUTE_RESOLVED)		\
> +	rdma_cm_event(ROUTE_ERROR)		\
> +	rdma_cm_event(CONNECT_REQUEST)		\
> +	rdma_cm_event(CONNECT_RESPONSE)		\
> +	rdma_cm_event(CONNECT_ERROR)		\
> +	rdma_cm_event(UNREACHABLE)		\
> +	rdma_cm_event(REJECTED)			\
> +	rdma_cm_event(ESTABLISHED)		\
> +	rdma_cm_event(DISCONNECTED)		\
> +	rdma_cm_event(DEVICE_REMOVAL)		\
> +	rdma_cm_event(MULTICAST_JOIN)		\
> +	rdma_cm_event(MULTICAST_ERROR)		\
> +	rdma_cm_event(ADDR_CHANGE)		\
> +	rdma_cm_event_end(TIMEWAIT_EXIT)
> +
> +#undef rdma_cm_event
> +#undef rdma_cm_event_end
> +
> +#define rdma_cm_event(x)	TRACE_DEFINE_ENUM(RDMA_CM_EVENT_##x);
> +#define rdma_cm_event_end(x)	TRACE_DEFINE_ENUM(RDMA_CM_EVENT_##x);
> +
> +RDMA_CM_EVENT_LIST
> +
> +#undef rdma_cm_event
> +#undef rdma_cm_event_end
> +
> +#define rdma_cm_event(x)	{ RDMA_CM_EVENT_##x, #x },
> +#define rdma_cm_event_end(x)	{ RDMA_CM_EVENT_##x, #x }
> +
> +#define rdma_show_cm_event(x) \
> +		__print_symbolic(x, RDMA_CM_EVENT_LIST)
> 

Fwd: [PATCH v1 01/12] rdma/ib: Add trace point macros to display human-readable values

[Chuck Lever]

Attn: RDMA maintainers - see Anna's question below.


> Begin forwarded message:
>=20
> From: Anna Schumaker <Anna.Schumaker@netapp.com>
> Subject: Re: [PATCH v1 01/12] rdma/ib: Add trace point macros to =
display human-readable values
> Date: January 18, 2018 at 4:49:20 PM EST
> To: Chuck Lever <chuck.lever@oracle.com>
> Cc: <linux-rdma@vger.kernel.org>, <linux-nfs@vger.kernel.org>
>=20
> Hi Folks,
>=20
> On 12/20/2017 04:30 PM, Chuck Lever wrote:
>> These can be shared with all kernel ULPs, and more can easily be
>> added as needed.
>>=20
>> Note: checkpatch.pl has some heartburn with the TRACE_DEFINE_ENUM
>> macros and the LIST macros. These follow the same style as other
>> header files under include/tracing/events , thus should be
>> considered acceptable exceptions.
>>=20
>> Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
>> ---
>> include/trace/events/rdma.h |  128 =
+++++++++++++++++++++++++++++++++++++++++++
>> 1 file changed, 128 insertions(+)
>> create mode 100644 include/trace/events/rdma.h
>=20
> Just checking that it's okay to send this through the NFS tree, since =
it goes along with the rest of Chuck's patches?
>=20
> Thanks,
> Anna
>>=20
>> diff --git a/include/trace/events/rdma.h =
b/include/trace/events/rdma.h
>> new file mode 100644
>> index 0000000..9d02fbe
>> --- /dev/null
>> +++ b/include/trace/events/rdma.h
>> @@ -0,0 +1,128 @@
>> +/*
>> + * Copyright (c) 2017 Oracle.  All rights reserved.
>> + */
>> +
>> +/*
>> + * enum ib_event_type, from include/rdma/ib_verbs.h
>> + */
>> +
>> +#define IB_EVENT_LIST				\
>> +	ib_event(CQ_ERR)			\
>> +	ib_event(QP_FATAL)			\
>> +	ib_event(QP_REQ_ERR)			\
>> +	ib_event(QP_ACCESS_ERR)			\
>> +	ib_event(COMM_EST)			\
>> +	ib_event(SQ_DRAINED)			\
>> +	ib_event(PATH_MIG)			\
>> +	ib_event(PATH_MIG_ERR)			\
>> +	ib_event(DEVICE_FATAL)			\
>> +	ib_event(PORT_ACTIVE)			\
>> +	ib_event(PORT_ERR)			\
>> +	ib_event(LID_CHANGE)			\
>> +	ib_event(PKEY_CHANGE)			\
>> +	ib_event(SM_CHANGE)			\
>> +	ib_event(SRQ_ERR)			\
>> +	ib_event(SRQ_LIMIT_REACHED)		\
>> +	ib_event(QP_LAST_WQE_REACHED)		\
>> +	ib_event(CLIENT_REREGISTER)		\
>> +	ib_event(GID_CHANGE)			\
>> +	ib_event_end(WQ_FATAL)
>> +
>> +#undef ib_event
>> +#undef ib_event_end
>> +
>> +#define ib_event(x)		TRACE_DEFINE_ENUM(IB_EVENT_##x);
>> +#define ib_event_end(x)		TRACE_DEFINE_ENUM(IB_EVENT_##x);
>> +
>> +IB_EVENT_LIST
>> +
>> +#undef ib_event
>> +#undef ib_event_end
>> +
>> +#define ib_event(x)		{ IB_EVENT_##x, #x },
>> +#define ib_event_end(x)		{ IB_EVENT_##x, #x }
>> +
>> +#define rdma_show_ib_event(x) \
>> +		__print_symbolic(x, IB_EVENT_LIST)
>> +
>> +/*
>> + * enum ib_wc_status type, from include/rdma/ib_verbs.h
>> + */
>> +#define IB_WC_STATUS_LIST			\
>> +	ib_wc_status(SUCCESS)			\
>> +	ib_wc_status(LOC_LEN_ERR)		\
>> +	ib_wc_status(LOC_QP_OP_ERR)		\
>> +	ib_wc_status(LOC_EEC_OP_ERR)		\
>> +	ib_wc_status(LOC_PROT_ERR)		\
>> +	ib_wc_status(WR_FLUSH_ERR)		\
>> +	ib_wc_status(MW_BIND_ERR)		\
>> +	ib_wc_status(BAD_RESP_ERR)		\
>> +	ib_wc_status(LOC_ACCESS_ERR)		\
>> +	ib_wc_status(REM_INV_REQ_ERR)		\
>> +	ib_wc_status(REM_ACCESS_ERR)		\
>> +	ib_wc_status(REM_OP_ERR)		\
>> +	ib_wc_status(RETRY_EXC_ERR)		\
>> +	ib_wc_status(RNR_RETRY_EXC_ERR)		\
>> +	ib_wc_status(LOC_RDD_VIOL_ERR)		\
>> +	ib_wc_status(REM_INV_RD_REQ_ERR)	\
>> +	ib_wc_status(REM_ABORT_ERR)		\
>> +	ib_wc_status(INV_EECN_ERR)		\
>> +	ib_wc_status(INV_EEC_STATE_ERR)		\
>> +	ib_wc_status(FATAL_ERR)			\
>> +	ib_wc_status(RESP_TIMEOUT_ERR)		\
>> +	ib_wc_status_end(GENERAL_ERR)
>> +
>> +#undef ib_wc_status
>> +#undef ib_wc_status_end
>> +
>> +#define ib_wc_status(x)		TRACE_DEFINE_ENUM(IB_WC_##x);
>> +#define ib_wc_status_end(x)	TRACE_DEFINE_ENUM(IB_WC_##x);
>> +
>> +IB_WC_STATUS_LIST
>> +
>> +#undef ib_wc_status
>> +#undef ib_wc_status_end
>> +
>> +#define ib_wc_status(x)		{ IB_WC_##x, #x },
>> +#define ib_wc_status_end(x)	{ IB_WC_##x, #x }
>> +
>> +#define rdma_show_wc_status(x) \
>> +		__print_symbolic(x, IB_WC_STATUS_LIST)
>> +
>> +/*
>> + * enum rdma_cm_event_type, from include/rdma/rdma_cm.h
>> + */
>> +#define RDMA_CM_EVENT_LIST			\
>> +	rdma_cm_event(ADDR_RESOLVED)		\
>> +	rdma_cm_event(ADDR_ERROR)		\
>> +	rdma_cm_event(ROUTE_RESOLVED)		\
>> +	rdma_cm_event(ROUTE_ERROR)		\
>> +	rdma_cm_event(CONNECT_REQUEST)		\
>> +	rdma_cm_event(CONNECT_RESPONSE)		\
>> +	rdma_cm_event(CONNECT_ERROR)		\
>> +	rdma_cm_event(UNREACHABLE)		\
>> +	rdma_cm_event(REJECTED)			\
>> +	rdma_cm_event(ESTABLISHED)		\
>> +	rdma_cm_event(DISCONNECTED)		\
>> +	rdma_cm_event(DEVICE_REMOVAL)		\
>> +	rdma_cm_event(MULTICAST_JOIN)		\
>> +	rdma_cm_event(MULTICAST_ERROR)		\
>> +	rdma_cm_event(ADDR_CHANGE)		\
>> +	rdma_cm_event_end(TIMEWAIT_EXIT)
>> +
>> +#undef rdma_cm_event
>> +#undef rdma_cm_event_end
>> +
>> +#define rdma_cm_event(x)	TRACE_DEFINE_ENUM(RDMA_CM_EVENT_##x);
>> +#define rdma_cm_event_end(x)	=
TRACE_DEFINE_ENUM(RDMA_CM_EVENT_##x);
>> +
>> +RDMA_CM_EVENT_LIST
>> +
>> +#undef rdma_cm_event
>> +#undef rdma_cm_event_end
>> +
>> +#define rdma_cm_event(x)	{ RDMA_CM_EVENT_##x, #x },
>> +#define rdma_cm_event_end(x)	{ RDMA_CM_EVENT_##x, #x }
>> +
>> +#define rdma_show_cm_event(x) \
>> +		__print_symbolic(x, RDMA_CM_EVENT_LIST)
>>=20

--
Chuck Lever

Re: [PATCH v1 01/12] rdma/ib: Add trace point macros to display human-readable values

[Jason Gunthorpe]

On Thu, Jan 18, 2018 at 04:49:20PM -0500, Anna Schumaker wrote:
> Hi Folks,
> 
> On 12/20/2017 04:30 PM, Chuck Lever wrote:
> > These can be shared with all kernel ULPs, and more can easily be
> > added as needed.
> > 
> > Note: checkpatch.pl has some heartburn with the TRACE_DEFINE_ENUM
> > macros and the LIST macros. These follow the same style as other
> > header files under include/tracing/events , thus should be
> > considered acceptable exceptions.
> > 
> > Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
> >  include/trace/events/rdma.h |  128 +++++++++++++++++++++++++++++++++++++++++++
> >  1 file changed, 128 insertions(+)
> >  create mode 100644 include/trace/events/rdma.h
> 
> Just checking that it's okay to send this through the NFS tree,
> since it goes along with the rest of Chuck's patches?

New file, won't create any conflicts, so should be fine.

Is this API or anything that needs a really special look?

> > +++ b/include/trace/events/rdma.h
> > @@ -0,0 +1,128 @@
> > +/*
> > + * Copyright (c) 2017 Oracle.  All rights reserved.
> > + */

This should have a SPDX header though, from what I understand.

Jason

Re: [PATCH v1 01/12] rdma/ib: Add trace point macros to display human-readable values

[Leon Romanovsky]

[-- Attachment #1: Type: text/plain, Size: 1583 bytes --]

On Thu, Jan 18, 2018 at 03:34:46PM -0700, Jason Gunthorpe wrote:
> On Thu, Jan 18, 2018 at 04:49:20PM -0500, Anna Schumaker wrote:
> > Hi Folks,
> >
> > On 12/20/2017 04:30 PM, Chuck Lever wrote:
> > > These can be shared with all kernel ULPs, and more can easily be
> > > added as needed.
> > >
> > > Note: checkpatch.pl has some heartburn with the TRACE_DEFINE_ENUM
> > > macros and the LIST macros. These follow the same style as other
> > > header files under include/tracing/events , thus should be
> > > considered acceptable exceptions.
> > >
> > > Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
> > >  include/trace/events/rdma.h |  128 +++++++++++++++++++++++++++++++++++++++++++
> > >  1 file changed, 128 insertions(+)
> > >  create mode 100644 include/trace/events/rdma.h
> >
> > Just checking that it's okay to send this through the NFS tree,
> > since it goes along with the rest of Chuck's patches?
>
> New file, won't create any conflicts, so should be fine.
>
> Is this API or anything that needs a really special look?

It can be easily start to be API, for example "this battle" is not
finished yet: https://lwn.net/Articles/442113/

>
> > > +++ b/include/trace/events/rdma.h
> > > @@ -0,0 +1,128 @@
> > > +/*
> > > + * Copyright (c) 2017 Oracle.  All rights reserved.
> > > + */
>
> This should have a SPDX header though, from what I understand.
>
> Jason
> --
> To unsubscribe from this list: send the line "unsubscribe linux-rdma" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: [PATCH v1 01/12] rdma/ib: Add trace point macros to display human-readable values

[Chuck Lever]

> On Jan 18, 2018, at 5:34 PM, Jason Gunthorpe <jgg@ziepe.ca> wrote:
>=20
> On Thu, Jan 18, 2018 at 04:49:20PM -0500, Anna Schumaker wrote:
>> Hi Folks,
>>=20
>> On 12/20/2017 04:30 PM, Chuck Lever wrote:
>>> These can be shared with all kernel ULPs, and more can easily be
>>> added as needed.
>>>=20
>>> Note: checkpatch.pl has some heartburn with the TRACE_DEFINE_ENUM
>>> macros and the LIST macros. These follow the same style as other
>>> header files under include/tracing/events , thus should be
>>> considered acceptable exceptions.
>>>=20
>>> Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
>>> include/trace/events/rdma.h |  128 =
+++++++++++++++++++++++++++++++++++++++++++
>>> 1 file changed, 128 insertions(+)
>>> create mode 100644 include/trace/events/rdma.h
>>=20
>> Just checking that it's okay to send this through the NFS tree,
>> since it goes along with the rest of Chuck's patches?
>=20
> New file, won't create any conflicts, so should be fine.
>=20
> Is this API or anything that needs a really special look?
>=20
>>> +++ b/include/trace/events/rdma.h
>>> @@ -0,0 +1,128 @@
>>> +/*
>>> + * Copyright (c) 2017 Oracle.  All rights reserved.
>>> + */
>=20
> This should have a SPDX header though, from what I understand.

If Anna adds SPDX headers to the files introduced in this series,
can we get an Acked-by for this patch from one of the RDMA
maintainers? Or is that not necessary?


--
Chuck Lever

Re: [PATCH v1 01/12] rdma/ib: Add trace point macros to display human-readable values

[Jason Gunthorpe]

On Fri, Jan 19, 2018 at 11:19:20AM -0500, Chuck Lever wrote:
> 
> 
> > On Jan 18, 2018, at 5:34 PM, Jason Gunthorpe <jgg@ziepe.ca> wrote:
> > 
> > On Thu, Jan 18, 2018 at 04:49:20PM -0500, Anna Schumaker wrote:
> >> Hi Folks,
> >> 
> >> On 12/20/2017 04:30 PM, Chuck Lever wrote:
> >>> These can be shared with all kernel ULPs, and more can easily be
> >>> added as needed.
> >>> 
> >>> Note: checkpatch.pl has some heartburn with the TRACE_DEFINE_ENUM
> >>> macros and the LIST macros. These follow the same style as other
> >>> header files under include/tracing/events , thus should be
> >>> considered acceptable exceptions.
> >>> 
> >>> Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
> >>> include/trace/events/rdma.h |  128 +++++++++++++++++++++++++++++++++++++++++++
> >>> 1 file changed, 128 insertions(+)
> >>> create mode 100644 include/trace/events/rdma.h
> >> 
> >> Just checking that it's okay to send this through the NFS tree,
> >> since it goes along with the rest of Chuck's patches?
> > 
> > New file, won't create any conflicts, so should be fine.
> > 
> > Is this API or anything that needs a really special look?
> > 
> >>> +++ b/include/trace/events/rdma.h
> >>> @@ -0,0 +1,128 @@
> >>> +/*
> >>> + * Copyright (c) 2017 Oracle.  All rights reserved.
> >>> + */
> > 
> > This should have a SPDX header though, from what I understand.
> 
> If Anna adds SPDX headers to the files introduced in this series,
> can we get an Acked-by for this patch from one of the RDMA
> maintainers? Or is that not necessary?

Probably a MAINTAINERS file entry too.

The patch looks OK to me, it is just boilerplate to make the enums
work right.

Yes, you should have Ack's from maintainers when going through another
tree. Send a v2 of this patch and I can ack it for you.

Jason

[PATCH v1 02/12] rpcrdma: infrastructure for static trace points in rpcrdma.ko

[Chuck Lever]

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 include/trace/events/rpcrdma.h  |   15 +++++++++++++++
 net/sunrpc/xprtrdma/module.c    |   12 +++++++-----
 net/sunrpc/xprtrdma/xprt_rdma.h |    2 ++
 3 files changed, 24 insertions(+), 5 deletions(-)
 create mode 100644 include/trace/events/rpcrdma.h

diff --git a/include/trace/events/rpcrdma.h b/include/trace/events/rpcrdma.h
new file mode 100644
index 0000000..e7ca063
--- /dev/null
+++ b/include/trace/events/rpcrdma.h
@@ -0,0 +1,15 @@
+/*
+ * Copyright (c) 2017 Oracle.  All rights reserved.
+ */
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM rpcrdma
+
+#if !defined(_TRACE_RPCRDMA_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_RPCRDMA_H
+
+#include <linux/tracepoint.h>
+#include <trace/events/rdma.h>
+
+#endif /* _TRACE_RPCRDMA_H */
+
+#include <trace/define_trace.h>
diff --git a/net/sunrpc/xprtrdma/module.c b/net/sunrpc/xprtrdma/module.c
index 560712b..a762d19 100644
--- a/net/sunrpc/xprtrdma/module.c
+++ b/net/sunrpc/xprtrdma/module.c
@@ -1,18 +1,20 @@
 /*
- * Copyright (c) 2015 Oracle.  All rights reserved.
+ * Copyright (c) 2015, 2017 Oracle.  All rights reserved.
  */
 
 /* rpcrdma.ko module initialization
  */
 
+#include <linux/types.h>
+#include <linux/compiler.h>
 #include <linux/module.h>
 #include <linux/init.h>
 #include <linux/sunrpc/svc_rdma.h>
-#include "xprt_rdma.h"
 
-#if IS_ENABLED(CONFIG_SUNRPC_DEBUG)
-# define RPCDBG_FACILITY	RPCDBG_TRANS
-#endif
+#include <asm/swab.h>
+
+#define CREATE_TRACE_POINTS
+#include "xprt_rdma.h"
 
 MODULE_AUTHOR("Open Grid Computing and Network Appliance, Inc.");
 MODULE_DESCRIPTION("RPC/RDMA Transport");
diff --git a/net/sunrpc/xprtrdma/xprt_rdma.h b/net/sunrpc/xprtrdma/xprt_rdma.h
index 28ae1fb..a1ca1b6 100644
--- a/net/sunrpc/xprtrdma/xprt_rdma.h
+++ b/net/sunrpc/xprtrdma/xprt_rdma.h
@@ -675,3 +675,5 @@ static inline void rpcrdma_set_xdrlen(struct xdr_buf *xdr, size_t len)
 extern struct xprt_class xprt_rdma_bc;
 
 #endif				/* _LINUX_SUNRPC_XPRT_RDMA_H */
+
+#include <trace/events/rpcrdma.h>

[PATCH v1 03/12] xprtrdma: Add trace points in RPC Call transmit paths

[Chuck Lever]

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 include/trace/events/rpcrdma.h |  124 ++++++++++++++++++++++++++++++++++++++++
 net/sunrpc/xprtrdma/rpc_rdma.c |    8 ---
 net/sunrpc/xprtrdma/verbs.c    |   12 +---
 3 files changed, 129 insertions(+), 15 deletions(-)

diff --git a/include/trace/events/rpcrdma.h b/include/trace/events/rpcrdma.h
index e7ca063..8efb2c9 100644
--- a/include/trace/events/rpcrdma.h
+++ b/include/trace/events/rpcrdma.h
@@ -10,6 +10,130 @@
 #include <linux/tracepoint.h>
 #include <trace/events/rdma.h>
 
+/**
+ ** Call events
+ **/
+
+TRACE_DEFINE_ENUM(rpcrdma_noch);
+TRACE_DEFINE_ENUM(rpcrdma_readch);
+TRACE_DEFINE_ENUM(rpcrdma_areadch);
+TRACE_DEFINE_ENUM(rpcrdma_writech);
+TRACE_DEFINE_ENUM(rpcrdma_replych);
+
+#define xprtrdma_show_chunktype(x)					\
+		__print_symbolic(x,					\
+				{ rpcrdma_noch, "inline" },		\
+				{ rpcrdma_readch, "read list" },	\
+				{ rpcrdma_areadch, "*read list" },	\
+				{ rpcrdma_writech, "write list" },	\
+				{ rpcrdma_replych, "reply chunk" })
+
+TRACE_EVENT(xprtrdma_marshal,
+	TP_PROTO(
+		const struct rpc_rqst *rqst,
+		unsigned int hdrlen,
+		unsigned int rtype,
+		unsigned int wtype
+	),
+
+	TP_ARGS(rqst, hdrlen, rtype, wtype),
+
+	TP_STRUCT__entry(
+		__field(unsigned int, task_id)
+		__field(unsigned int, client_id)
+		__field(u32, xid)
+		__field(unsigned int, hdrlen)
+		__field(unsigned int, headlen)
+		__field(unsigned int, pagelen)
+		__field(unsigned int, taillen)
+		__field(unsigned int, rtype)
+		__field(unsigned int, wtype)
+	),
+
+	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);
+		__entry->hdrlen = hdrlen;
+		__entry->headlen = rqst->rq_snd_buf.head[0].iov_len;
+		__entry->pagelen = rqst->rq_snd_buf.page_len;
+		__entry->taillen = rqst->rq_snd_buf.tail[0].iov_len;
+		__entry->rtype = rtype;
+		__entry->wtype = wtype;
+	),
+
+	TP_printk("task:%u@%u xid=0x%08x: hdr=%u xdr=%u/%u/%u %s/%s",
+		__entry->task_id, __entry->client_id, __entry->xid,
+		__entry->hdrlen,
+		__entry->headlen, __entry->pagelen, __entry->taillen,
+		xprtrdma_show_chunktype(__entry->rtype),
+		xprtrdma_show_chunktype(__entry->wtype)
+	)
+);
+
+TRACE_EVENT(xprtrdma_post_send,
+	TP_PROTO(
+		const struct rpcrdma_req *req,
+		int status
+	),
+
+	TP_ARGS(req, status),
+
+	TP_STRUCT__entry(
+		__field(const void *, req)
+		__field(int, num_sge)
+		__field(bool, signaled)
+		__field(int, status)
+	),
+
+	TP_fast_assign(
+		__entry->req = req;
+		__entry->num_sge = req->rl_sendctx->sc_wr.num_sge;
+		__entry->signaled = req->rl_sendctx->sc_wr.send_flags &
+				    IB_SEND_SIGNALED;
+		__entry->status = status;
+	),
+
+	TP_printk("req=%p, %d SGEs%s, status=%d",
+		__entry->req, __entry->num_sge,
+		(__entry->signaled ? ", signaled" : ""),
+		__entry->status
+	)
+);
+
+/**
+ ** Completion events
+ **/
+
+TRACE_EVENT(xprtrdma_wc_send,
+	TP_PROTO(
+		const struct rpcrdma_sendctx *sc,
+		const struct ib_wc *wc
+	),
+
+	TP_ARGS(sc, wc),
+
+	TP_STRUCT__entry(
+		__field(const void *, req)
+		__field(unsigned int, unmap_count)
+		__field(unsigned int, status)
+		__field(unsigned int, vendor_err)
+	),
+
+	TP_fast_assign(
+		__entry->req = sc->sc_req;
+		__entry->unmap_count = sc->sc_unmap_count;
+		__entry->status = wc->status;
+		__entry->vendor_err = __entry->status ? wc->vendor_err : 0;
+	),
+
+	TP_printk("req=%p, unmapped %u pages: %s (%u/0x%x)",
+		__entry->req, __entry->unmap_count,
+		rdma_show_wc_status(__entry->status),
+		__entry->status, __entry->vendor_err
+	)
+);
+
 #endif /* _TRACE_RPCRDMA_H */
 
 #include <trace/define_trace.h>
diff --git a/net/sunrpc/xprtrdma/rpc_rdma.c b/net/sunrpc/xprtrdma/rpc_rdma.c
index 9601af0..162c0fd 100644
--- a/net/sunrpc/xprtrdma/rpc_rdma.c
+++ b/net/sunrpc/xprtrdma/rpc_rdma.c
@@ -524,9 +524,6 @@ static bool rpcrdma_results_inline(struct rpcrdma_xprt *r_xprt,
 	struct ib_sge *sge;
 	unsigned int count;
 
-	dprintk("RPC:       %s: unmapping %u sges for sc=%p\n",
-		__func__, sc->sc_unmap_count, sc);
-
 	/* The first two SGEs contain the transport header and
 	 * the inline buffer. These are always left mapped so
 	 * they can be cheaply re-used.
@@ -874,10 +871,7 @@ static bool rpcrdma_results_inline(struct rpcrdma_xprt *r_xprt,
 	if (ret)
 		goto out_err;
 
-	dprintk("RPC: %5u %s: %s/%s: hdrlen %u rpclen\n",
-		rqst->rq_task->tk_pid, __func__,
-		transfertypes[rtype], transfertypes[wtype],
-		xdr_stream_pos(xdr));
+	trace_xprtrdma_marshal(rqst, xdr_stream_pos(xdr), rtype, wtype);
 
 	ret = rpcrdma_prepare_send_sges(r_xprt, req, xdr_stream_pos(xdr),
 					&rqst->rq_snd_buf, rtype);
diff --git a/net/sunrpc/xprtrdma/verbs.c b/net/sunrpc/xprtrdma/verbs.c
index 9cc8abc..06d86b8 100644
--- a/net/sunrpc/xprtrdma/verbs.c
+++ b/net/sunrpc/xprtrdma/verbs.c
@@ -133,6 +133,7 @@
 		container_of(cqe, struct rpcrdma_sendctx, sc_cqe);
 
 	/* WARNING: Only wr_cqe and status are reliable at this point */
+	trace_xprtrdma_wc_send(sc, wc);
 	if (wc->status != IB_WC_SUCCESS && wc->status != IB_WC_WR_FLUSH_ERR)
 		pr_err("rpcrdma: Send: %s (%u/0x%x)\n",
 		       ib_wc_status_msg(wc->status),
@@ -1549,9 +1550,6 @@ struct rpcrdma_regbuf *
 		req->rl_reply = NULL;
 	}
 
-	dprintk("RPC:       %s: posting %d s/g entries\n",
-		__func__, send_wr->num_sge);
-
 	if (!ep->rep_send_count ||
 	    test_bit(RPCRDMA_REQ_F_TX_RESOURCES, &req->rl_flags)) {
 		send_wr->send_flags |= IB_SEND_SIGNALED;
@@ -1560,14 +1558,12 @@ struct rpcrdma_regbuf *
 		send_wr->send_flags &= ~IB_SEND_SIGNALED;
 		--ep->rep_send_count;
 	}
+
 	rc = ib_post_send(ia->ri_id->qp, send_wr, &send_wr_fail);
+	trace_xprtrdma_post_send(req, rc);
 	if (rc)
-		goto out_postsend_err;
+		return -ENOTCONN;
 	return 0;
-
-out_postsend_err:
-	pr_err("rpcrdma: RDMA Send ib_post_send returned %i\n", rc);
-	return -ENOTCONN;
 }
 
 int

[PATCH v1 04/12] xprtrdma: Add trace points in the RPC Reply handler paths

[Chuck Lever]

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 include/trace/events/rpcrdma.h |  162 ++++++++++++++++++++++++++++++++++++++++
 net/sunrpc/xprtrdma/rpc_rdma.c |   17 +---
 net/sunrpc/xprtrdma/verbs.c    |   11 +--
 3 files changed, 171 insertions(+), 19 deletions(-)

diff --git a/include/trace/events/rpcrdma.h b/include/trace/events/rpcrdma.h
index 8efb2c9..e11bb32 100644
--- a/include/trace/events/rpcrdma.h
+++ b/include/trace/events/rpcrdma.h
@@ -11,6 +11,46 @@
 #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
  **/
 
@@ -101,6 +141,29 @@
 	)
 );
 
+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
  **/
@@ -134,6 +197,105 @@
 	)
 );
 
+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>
diff --git a/net/sunrpc/xprtrdma/rpc_rdma.c b/net/sunrpc/xprtrdma/rpc_rdma.c
index 162c0fd..6f774f1e4 100644
--- a/net/sunrpc/xprtrdma/rpc_rdma.c
+++ b/net/sunrpc/xprtrdma/rpc_rdma.c
@@ -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.
diff --git a/net/sunrpc/xprtrdma/verbs.c b/net/sunrpc/xprtrdma/verbs.c
index 06d86b8..cfa3c03 100644
--- a/net/sunrpc/xprtrdma/verbs.c
+++ b/net/sunrpc/xprtrdma/verbs.c
@@ -156,13 +156,11 @@
 					       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 @@ struct rpcrdma_regbuf *
 	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;
 }
 
 /**

[PATCH v1 05/12] xprtrdma: Add trace points to instrument memory registration

[Chuck Lever]

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 include/trace/events/rpcrdma.h |  156 ++++++++++++++++++++++++++++++++++++++++
 net/sunrpc/xprtrdma/frwr_ops.c |   11 +--
 net/sunrpc/xprtrdma/rpc_rdma.c |   18 +----
 3 files changed, 163 insertions(+), 22 deletions(-)

diff --git a/include/trace/events/rpcrdma.h b/include/trace/events/rpcrdma.h
index e11bb32..bc7f2db 100644
--- a/include/trace/events/rpcrdma.h
+++ b/include/trace/events/rpcrdma.h
@@ -50,10 +50,164 @@
 				),					\
 				TP_ARGS(rep))
 
+DECLARE_EVENT_CLASS(xprtrdma_rdch_event,
+	TP_PROTO(
+		const struct rpc_task *task,
+		unsigned int pos,
+		struct rpcrdma_mr *mr,
+		int nsegs
+	),
+
+	TP_ARGS(task, pos, mr, nsegs),
+
+	TP_STRUCT__entry(
+		__field(unsigned int, task_id)
+		__field(unsigned int, client_id)
+		__field(const void *, mr)
+		__field(unsigned int, pos)
+		__field(int, nents)
+		__field(u32, handle)
+		__field(u32, length)
+		__field(u64, offset)
+		__field(int, nsegs)
+	),
+
+	TP_fast_assign(
+		__entry->task_id = task->tk_pid;
+		__entry->client_id = task->tk_client->cl_clid;
+		__entry->mr = mr;
+		__entry->pos = pos;
+		__entry->nents = mr->mr_nents;
+		__entry->handle = mr->mr_handle;
+		__entry->length = mr->mr_length;
+		__entry->offset = mr->mr_offset;
+		__entry->nsegs = nsegs;
+	),
+
+	TP_printk("task:%u@%u mr=%p pos=%u %u@0x%016llx:0x%08x (%s)",
+		__entry->task_id, __entry->client_id, __entry->mr,
+		__entry->pos, __entry->length,
+		(unsigned long long)__entry->offset, __entry->handle,
+		__entry->nents < __entry->nsegs ? "more" : "last"
+	)
+);
+
+#define DEFINE_RDCH_EVENT(name)						\
+		DEFINE_EVENT(xprtrdma_rdch_event, name,			\
+				TP_PROTO(				\
+					const struct rpc_task *task,	\
+					unsigned int pos,		\
+					struct rpcrdma_mr *mr,		\
+					int nsegs			\
+				),					\
+				TP_ARGS(task, pos, mr, nsegs))
+
+DECLARE_EVENT_CLASS(xprtrdma_wrch_event,
+	TP_PROTO(
+		const struct rpc_task *task,
+		struct rpcrdma_mr *mr,
+		int nsegs
+	),
+
+	TP_ARGS(task, mr, nsegs),
+
+	TP_STRUCT__entry(
+		__field(unsigned int, task_id)
+		__field(unsigned int, client_id)
+		__field(const void *, mr)
+		__field(int, nents)
+		__field(u32, handle)
+		__field(u32, length)
+		__field(u64, offset)
+		__field(int, nsegs)
+	),
+
+	TP_fast_assign(
+		__entry->task_id = task->tk_pid;
+		__entry->client_id = task->tk_client->cl_clid;
+		__entry->mr = mr;
+		__entry->nents = mr->mr_nents;
+		__entry->handle = mr->mr_handle;
+		__entry->length = mr->mr_length;
+		__entry->offset = mr->mr_offset;
+		__entry->nsegs = nsegs;
+	),
+
+	TP_printk("task:%u@%u mr=%p %u@0x%016llx:0x%08x (%s)",
+		__entry->task_id, __entry->client_id, __entry->mr,
+		__entry->length, (unsigned long long)__entry->offset,
+		__entry->handle,
+		__entry->nents < __entry->nsegs ? "more" : "last"
+	)
+);
+
+#define DEFINE_WRCH_EVENT(name)						\
+		DEFINE_EVENT(xprtrdma_wrch_event, name,			\
+				TP_PROTO(				\
+					const struct rpc_task *task,	\
+					struct rpcrdma_mr *mr,		\
+					int nsegs			\
+				),					\
+				TP_ARGS(task, mr, nsegs))
+
+TRACE_DEFINE_ENUM(FRWR_IS_INVALID);
+TRACE_DEFINE_ENUM(FRWR_IS_VALID);
+TRACE_DEFINE_ENUM(FRWR_FLUSHED_FR);
+TRACE_DEFINE_ENUM(FRWR_FLUSHED_LI);
+
+#define xprtrdma_show_frwr_state(x)					\
+		__print_symbolic(x,					\
+				{ FRWR_IS_INVALID, "INVALID" },		\
+				{ FRWR_IS_VALID, "VALID" },		\
+				{ FRWR_FLUSHED_FR, "FLUSHED_FR" },	\
+				{ FRWR_FLUSHED_LI, "FLUSHED_LI" })
+
+DECLARE_EVENT_CLASS(xprtrdma_frwr_done,
+	TP_PROTO(
+		const struct ib_wc *wc,
+		const struct rpcrdma_frwr *frwr
+	),
+
+	TP_ARGS(wc, frwr),
+
+	TP_STRUCT__entry(
+		__field(const void *, mr)
+		__field(unsigned int, state)
+		__field(unsigned int, status)
+		__field(unsigned int, vendor_err)
+	),
+
+	TP_fast_assign(
+		__entry->mr = container_of(frwr, struct rpcrdma_mr, frwr);
+		__entry->state = frwr->fr_state;
+		__entry->status = wc->status;
+		__entry->vendor_err = __entry->status ? wc->vendor_err : 0;
+	),
+
+	TP_printk(
+		"mr=%p state=%s: %s (%u/0x%x)",
+		__entry->mr, xprtrdma_show_frwr_state(__entry->state),
+		rdma_show_wc_status(__entry->status),
+		__entry->status, __entry->vendor_err
+	)
+);
+
+#define DEFINE_FRWR_DONE_EVENT(name)					\
+		DEFINE_EVENT(xprtrdma_frwr_done, name,			\
+				TP_PROTO(				\
+					const struct ib_wc *wc,		\
+					const struct rpcrdma_frwr *frwr	\
+				),					\
+				TP_ARGS(wc, frwr))
+
 /**
  ** Call events
  **/
 
+DEFINE_RDCH_EVENT(xprtrdma_read_chunk);
+DEFINE_WRCH_EVENT(xprtrdma_write_chunk);
+DEFINE_WRCH_EVENT(xprtrdma_reply_chunk);
+
 TRACE_DEFINE_ENUM(rpcrdma_noch);
 TRACE_DEFINE_ENUM(rpcrdma_readch);
 TRACE_DEFINE_ENUM(rpcrdma_areadch);
@@ -226,6 +380,8 @@
 	)
 );
 
+DEFINE_FRWR_DONE_EVENT(xprtrdma_wc_fastreg);
+
 /**
  ** Reply events
  **/
diff --git a/net/sunrpc/xprtrdma/frwr_ops.c b/net/sunrpc/xprtrdma/frwr_ops.c
index 35e3a54..afbeb9b 100644
--- a/net/sunrpc/xprtrdma/frwr_ops.c
+++ b/net/sunrpc/xprtrdma/frwr_ops.c
@@ -286,16 +286,16 @@
 static void
 frwr_wc_fastreg(struct ib_cq *cq, struct ib_wc *wc)
 {
-	struct rpcrdma_frwr *frwr;
-	struct ib_cqe *cqe;
+	struct ib_cqe *cqe = wc->wr_cqe;
+	struct rpcrdma_frwr *frwr =
+			container_of(cqe, struct rpcrdma_frwr, fr_cqe);
 
 	/* WARNING: Only wr_cqe and status are reliable at this point */
 	if (wc->status != IB_WC_SUCCESS) {
-		cqe = wc->wr_cqe;
-		frwr = container_of(cqe, struct rpcrdma_frwr, fr_cqe);
 		frwr->fr_state = FRWR_FLUSHED_FR;
 		__frwr_sendcompletion_flush(wc, "fastreg");
 	}
+	trace_xprtrdma_wc_fastreg(wc, frwr);
 }
 
 /**
@@ -401,9 +401,6 @@
 	if (unlikely(n != mr->mr_nents))
 		goto out_mapmr_err;
 
-	dprintk("RPC:       %s: Using frwr %p to map %u segments (%llu bytes)\n",
-		__func__, frwr, mr->mr_nents, ibmr->length);
-
 	key = (u8)(ibmr->rkey & 0x000000FF);
 	ib_update_fast_reg_key(ibmr, ++key);
 
diff --git a/net/sunrpc/xprtrdma/rpc_rdma.c b/net/sunrpc/xprtrdma/rpc_rdma.c
index 6f774f1e4..634496c 100644
--- a/net/sunrpc/xprtrdma/rpc_rdma.c
+++ b/net/sunrpc/xprtrdma/rpc_rdma.c
@@ -371,11 +371,7 @@ static bool rpcrdma_results_inline(struct rpcrdma_xprt *r_xprt,
 		if (encode_read_segment(xdr, mr, pos) < 0)
 			return -EMSGSIZE;
 
-		dprintk("RPC: %5u %s: pos %u %u@0x%016llx:0x%08x (%s)\n",
-			rqst->rq_task->tk_pid, __func__, pos,
-			mr->mr_length, (unsigned long long)mr->mr_offset,
-			mr->mr_handle, mr->mr_nents < nsegs ? "more" : "last");
-
+		trace_xprtrdma_read_chunk(rqst->rq_task, pos, mr, nsegs);
 		r_xprt->rx_stats.read_chunk_count++;
 		nsegs -= mr->mr_nents;
 	} while (nsegs);
@@ -433,11 +429,7 @@ static bool rpcrdma_results_inline(struct rpcrdma_xprt *r_xprt,
 		if (encode_rdma_segment(xdr, mr) < 0)
 			return -EMSGSIZE;
 
-		dprintk("RPC: %5u %s: %u@0x016%llx:0x%08x (%s)\n",
-			rqst->rq_task->tk_pid, __func__,
-			mr->mr_length, (unsigned long long)mr->mr_offset,
-			mr->mr_handle, mr->mr_nents < nsegs ? "more" : "last");
-
+		trace_xprtrdma_write_chunk(rqst->rq_task, mr, nsegs);
 		r_xprt->rx_stats.write_chunk_count++;
 		r_xprt->rx_stats.total_rdma_request += seg->mr_len;
 		nchunks++;
@@ -495,11 +487,7 @@ static bool rpcrdma_results_inline(struct rpcrdma_xprt *r_xprt,
 		if (encode_rdma_segment(xdr, mr) < 0)
 			return -EMSGSIZE;
 
-		dprintk("RPC: %5u %s: %u@0x%016llx:0x%08x (%s)\n",
-			rqst->rq_task->tk_pid, __func__,
-			mr->mr_length, (unsigned long long)mr->mr_offset,
-			mr->mr_handle, mr->mr_nents < nsegs ? "more" : "last");
-
+		trace_xprtrdma_reply_chunk(rqst->rq_task, mr, nsegs);
 		r_xprt->rx_stats.reply_chunk_count++;
 		r_xprt->rx_stats.total_rdma_request += seg->mr_len;
 		nchunks++;

[PATCH v1 06/12] xprtrdma: Add trace points in reply decoder path

[Chuck Lever]

This includes decoding Write and Reply chunks, and fixing up inline
payloads.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 include/trace/events/rpcrdma.h |   93 ++++++++++++++++++++++++++++++++++++++++
 net/sunrpc/xprtrdma/rpc_rdma.c |   29 ++++--------
 2 files changed, 102 insertions(+), 20 deletions(-)

diff --git a/include/trace/events/rpcrdma.h b/include/trace/events/rpcrdma.h
index bc7f2db..8176215 100644
--- a/include/trace/events/rpcrdma.h
+++ b/include/trace/events/rpcrdma.h
@@ -452,6 +452,99 @@
 DEFINE_REPLY_EVENT(xprtrdma_reply_short);
 DEFINE_REPLY_EVENT(xprtrdma_reply_hdr);
 
+TRACE_EVENT(xprtrdma_fixup,
+	TP_PROTO(
+		const struct rpc_rqst *rqst,
+		int len,
+		int hdrlen
+	),
+
+	TP_ARGS(rqst, len, hdrlen),
+
+	TP_STRUCT__entry(
+		__field(unsigned int, task_id)
+		__field(unsigned int, client_id)
+		__field(const void *, base)
+		__field(int, len)
+		__field(int, hdrlen)
+	),
+
+	TP_fast_assign(
+		__entry->task_id = rqst->rq_task->tk_pid;
+		__entry->client_id = rqst->rq_task->tk_client->cl_clid;
+		__entry->base = rqst->rq_rcv_buf.head[0].iov_base;
+		__entry->len = len;
+		__entry->hdrlen = hdrlen;
+	),
+
+	TP_printk("task:%u@%u base=%p len=%d hdrlen=%d",
+		__entry->task_id, __entry->client_id,
+		__entry->base, __entry->len, __entry->hdrlen
+	)
+);
+
+TRACE_EVENT(xprtrdma_fixup_pg,
+	TP_PROTO(
+		const struct rpc_rqst *rqst,
+		int pageno,
+		const void *pos,
+		int len,
+		int curlen
+	),
+
+	TP_ARGS(rqst, pageno, pos, len, curlen),
+
+	TP_STRUCT__entry(
+		__field(unsigned int, task_id)
+		__field(unsigned int, client_id)
+		__field(const void *, pos)
+		__field(int, pageno)
+		__field(int, len)
+		__field(int, curlen)
+	),
+
+	TP_fast_assign(
+		__entry->task_id = rqst->rq_task->tk_pid;
+		__entry->client_id = rqst->rq_task->tk_client->cl_clid;
+		__entry->pos = pos;
+		__entry->pageno = pageno;
+		__entry->len = len;
+		__entry->curlen = curlen;
+	),
+
+	TP_printk("task:%u@%u pageno=%d pos=%p len=%d curlen=%d",
+		__entry->task_id, __entry->client_id,
+		__entry->pageno, __entry->pos, __entry->len, __entry->curlen
+	)
+);
+
+TRACE_EVENT(xprtrdma_decode_seg,
+	TP_PROTO(
+		u32 handle,
+		u32 length,
+		u64 offset
+	),
+
+	TP_ARGS(handle, length, offset),
+
+	TP_STRUCT__entry(
+		__field(u32, handle)
+		__field(u32, length)
+		__field(u64, offset)
+	),
+
+	TP_fast_assign(
+		__entry->handle = handle;
+		__entry->length = length;
+		__entry->offset = offset;
+	),
+
+	TP_printk("%u@0x%016llx:0x%08x",
+		__entry->length, (unsigned long long)__entry->offset,
+		__entry->handle
+	)
+);
+
 #endif /* _TRACE_RPCRDMA_H */
 
 #include <trace/define_trace.h>
diff --git a/net/sunrpc/xprtrdma/rpc_rdma.c b/net/sunrpc/xprtrdma/rpc_rdma.c
index 634496c..1ae9b41 100644
--- a/net/sunrpc/xprtrdma/rpc_rdma.c
+++ b/net/sunrpc/xprtrdma/rpc_rdma.c
@@ -914,8 +914,7 @@ static bool rpcrdma_results_inline(struct rpcrdma_xprt *r_xprt,
 	curlen = rqst->rq_rcv_buf.head[0].iov_len;
 	if (curlen > copy_len)
 		curlen = copy_len;
-	dprintk("RPC:       %s: srcp 0x%p len %d hdrlen %d\n",
-		__func__, srcp, copy_len, curlen);
+	trace_xprtrdma_fixup(rqst, copy_len, curlen);
 	srcp += curlen;
 	copy_len -= curlen;
 
@@ -935,9 +934,8 @@ static bool rpcrdma_results_inline(struct rpcrdma_xprt *r_xprt,
 			if (curlen > pagelist_len)
 				curlen = pagelist_len;
 
-			dprintk("RPC:       %s: page %d"
-				" srcp 0x%p len %d curlen %d\n",
-				__func__, i, srcp, copy_len, curlen);
+			trace_xprtrdma_fixup_pg(rqst, i, srcp,
+						copy_len, curlen);
 			destp = kmap_atomic(ppages[i]);
 			memcpy(destp + page_base, srcp, curlen);
 			flush_dcache_page(ppages[i]);
@@ -1028,26 +1026,19 @@ static bool rpcrdma_results_inline(struct rpcrdma_xprt *r_xprt,
 
 static int decode_rdma_segment(struct xdr_stream *xdr, u32 *length)
 {
+	u32 handle;
+	u64 offset;
 	__be32 *p;
 
 	p = xdr_inline_decode(xdr, 4 * sizeof(*p));
 	if (unlikely(!p))
 		return -EIO;
 
-	ifdebug(FACILITY) {
-		u64 offset;
-		u32 handle;
-
-		handle = be32_to_cpup(p++);
-		*length = be32_to_cpup(p++);
-		xdr_decode_hyper(p, &offset);
-		dprintk("RPC:       %s:   segment %u@0x%016llx:0x%08x\n",
-			__func__, *length, (unsigned long long)offset,
-			handle);
-	} else {
-		*length = be32_to_cpup(p + 1);
-	}
+	handle = be32_to_cpup(p++);
+	*length = be32_to_cpup(p++);
+	xdr_decode_hyper(p, &offset);
 
+	trace_xprtrdma_decode_seg(handle, *length, offset);
 	return 0;
 }
 
@@ -1068,8 +1059,6 @@ static int decode_write_chunk(struct xdr_stream *xdr, u32 *length)
 		*length += seglength;
 	}
 
-	dprintk("RPC:       %s: segcount=%u, %u bytes\n",
-		__func__, be32_to_cpup(p), *length);
 	return 0;
 }
 

[PATCH v1 07/12] xprtrdma: Add trace points to instrument memory invalidation

[Chuck Lever]

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 include/trace/events/rpcrdma.h |   41 ++++++++++++++++++++++++++++++++++++++++
 net/sunrpc/xprtrdma/fmr_ops.c  |    4 ++--
 net/sunrpc/xprtrdma/frwr_ops.c |   27 +++++++++++++-------------
 net/sunrpc/xprtrdma/verbs.c    |    1 +
 4 files changed, 57 insertions(+), 16 deletions(-)

diff --git a/include/trace/events/rpcrdma.h b/include/trace/events/rpcrdma.h
index 8176215..057662b 100644
--- a/include/trace/events/rpcrdma.h
+++ b/include/trace/events/rpcrdma.h
@@ -200,6 +200,41 @@
 				),					\
 				TP_ARGS(wc, frwr))
 
+DECLARE_EVENT_CLASS(xprtrdma_mr,
+	TP_PROTO(
+		const struct rpcrdma_mr *mr
+	),
+
+	TP_ARGS(mr),
+
+	TP_STRUCT__entry(
+		__field(const void *, mr)
+		__field(u32, handle)
+		__field(u32, length)
+		__field(u64, offset)
+	),
+
+	TP_fast_assign(
+		__entry->mr = mr;
+		__entry->handle = mr->mr_handle;
+		__entry->length = mr->mr_length;
+		__entry->offset = mr->mr_offset;
+	),
+
+	TP_printk("mr=%p %u@0x%016llx:0x%08x",
+		__entry->mr, __entry->length,
+		(unsigned long long)__entry->offset,
+		__entry->handle
+	)
+);
+
+#define DEFINE_MR_EVENT(name) \
+		DEFINE_EVENT(xprtrdma_mr, name, \
+				TP_PROTO( \
+					const struct rpcrdma_mr *mr \
+				), \
+				TP_ARGS(mr))
+
 /**
  ** Call events
  **/
@@ -381,6 +416,12 @@
 );
 
 DEFINE_FRWR_DONE_EVENT(xprtrdma_wc_fastreg);
+DEFINE_FRWR_DONE_EVENT(xprtrdma_wc_li);
+DEFINE_FRWR_DONE_EVENT(xprtrdma_wc_li_wake);
+
+DEFINE_MR_EVENT(xprtrdma_localinv);
+DEFINE_MR_EVENT(xprtrdma_dma_unmap);
+DEFINE_MR_EVENT(xprtrdma_remoteinv);
 
 /**
  ** Reply events
diff --git a/net/sunrpc/xprtrdma/fmr_ops.c b/net/sunrpc/xprtrdma/fmr_ops.c
index 7f2f2b7..d5f95bb 100644
--- a/net/sunrpc/xprtrdma/fmr_ops.c
+++ b/net/sunrpc/xprtrdma/fmr_ops.c
@@ -148,6 +148,7 @@ enum {
 	pr_err("rpcrdma: FMR reset failed (%d), %p released\n", rc, mr);
 	r_xprt->rx_stats.mrs_orphaned++;
 
+	trace_xprtrdma_dma_unmap(mr);
 	ib_dma_unmap_sg(r_xprt->rx_ia.ri_device,
 			mr->mr_sg, mr->mr_nents, mr->mr_dir);
 
@@ -273,6 +274,7 @@ enum {
 	list_for_each_entry(mr, mrs, mr_list) {
 		dprintk("RPC:       %s: unmapping fmr %p\n",
 			__func__, &mr->fmr);
+		trace_xprtrdma_localinv(mr);
 		list_add_tail(&mr->fmr.fm_mr->list, &unmap_list);
 	}
 	r_xprt->rx_stats.local_inv_needed++;
@@ -285,8 +287,6 @@ enum {
 	 */
 	while (!list_empty(mrs)) {
 		mr = rpcrdma_mr_pop(mrs);
-		dprintk("RPC:       %s: DMA unmapping fmr %p\n",
-			__func__, &mr->fmr);
 		list_del(&mr->fmr.fm_mr->list);
 		rpcrdma_mr_unmap_and_put(mr);
 	}
diff --git a/net/sunrpc/xprtrdma/frwr_ops.c b/net/sunrpc/xprtrdma/frwr_ops.c
index afbeb9b..90f688f 100644
--- a/net/sunrpc/xprtrdma/frwr_ops.c
+++ b/net/sunrpc/xprtrdma/frwr_ops.c
@@ -182,9 +182,11 @@
 	int rc;
 
 	rc = __frwr_mr_reset(ia, mr);
-	if (state != FRWR_FLUSHED_LI)
+	if (state != FRWR_FLUSHED_LI) {
+		trace_xprtrdma_dma_unmap(mr);
 		ib_dma_unmap_sg(ia->ri_device,
 				mr->mr_sg, mr->mr_nents, mr->mr_dir);
+	}
 	if (rc)
 		goto out_release;
 
@@ -307,16 +309,16 @@
 static void
 frwr_wc_localinv(struct ib_cq *cq, struct ib_wc *wc)
 {
-	struct rpcrdma_frwr *frwr;
-	struct ib_cqe *cqe;
+	struct ib_cqe *cqe = wc->wr_cqe;
+	struct rpcrdma_frwr *frwr = container_of(cqe, struct rpcrdma_frwr,
+						 fr_cqe);
 
 	/* WARNING: Only wr_cqe and status are reliable at this point */
 	if (wc->status != IB_WC_SUCCESS) {
-		cqe = wc->wr_cqe;
-		frwr = container_of(cqe, struct rpcrdma_frwr, fr_cqe);
 		frwr->fr_state = FRWR_FLUSHED_LI;
 		__frwr_sendcompletion_flush(wc, "localinv");
 	}
+	trace_xprtrdma_wc_li(wc, frwr);
 }
 
 /**
@@ -329,17 +331,17 @@
 static void
 frwr_wc_localinv_wake(struct ib_cq *cq, struct ib_wc *wc)
 {
-	struct rpcrdma_frwr *frwr;
-	struct ib_cqe *cqe;
+	struct ib_cqe *cqe = wc->wr_cqe;
+	struct rpcrdma_frwr *frwr = container_of(cqe, struct rpcrdma_frwr,
+						 fr_cqe);
 
 	/* WARNING: Only wr_cqe and status are reliable at this point */
-	cqe = wc->wr_cqe;
-	frwr = container_of(cqe, struct rpcrdma_frwr, fr_cqe);
 	if (wc->status != IB_WC_SUCCESS) {
 		frwr->fr_state = FRWR_FLUSHED_LI;
 		__frwr_sendcompletion_flush(wc, "localinv");
 	}
 	complete(&frwr->fr_linv_done);
+	trace_xprtrdma_wc_li_wake(wc, frwr);
 }
 
 /* Post a REG_MR Work Request to register a memory region
@@ -457,6 +459,7 @@
 	list_for_each_entry(mr, mrs, mr_list)
 		if (mr->mr_handle == rep->rr_inv_rkey) {
 			list_del(&mr->mr_list);
+			trace_xprtrdma_remoteinv(mr);
 			mr->frwr.fr_state = FRWR_IS_INVALID;
 			rpcrdma_mr_unmap_and_put(mr);
 			break;	/* only one invalidated MR per RPC */
@@ -492,9 +495,7 @@
 		mr->frwr.fr_state = FRWR_IS_INVALID;
 
 		frwr = &mr->frwr;
-
-		dprintk("RPC:       %s: invalidating frwr %p\n",
-			__func__, frwr);
+		trace_xprtrdma_localinv(mr);
 
 		frwr->fr_cqe.done = frwr_wc_localinv;
 		last = &frwr->fr_invwr;
@@ -536,8 +537,6 @@
 unmap:
 	while (!list_empty(mrs)) {
 		mr = rpcrdma_mr_pop(mrs);
-		dprintk("RPC:       %s: DMA unmapping frwr %p\n",
-			__func__, &mr->frwr);
 		rpcrdma_mr_unmap_and_put(mr);
 	}
 	return;
diff --git a/net/sunrpc/xprtrdma/verbs.c b/net/sunrpc/xprtrdma/verbs.c
index cfa3c03..0e89e55 100644
--- a/net/sunrpc/xprtrdma/verbs.c
+++ b/net/sunrpc/xprtrdma/verbs.c
@@ -1349,6 +1349,7 @@ struct rpcrdma_mr *
 {
 	struct rpcrdma_xprt *r_xprt = mr->mr_xprt;
 
+	trace_xprtrdma_dma_unmap(mr);
 	ib_dma_unmap_sg(r_xprt->rx_ia.ri_device,
 			mr->mr_sg, mr->mr_nents, mr->mr_dir);
 	__rpcrdma_mr_put(&r_xprt->rx_buf, mr);

[PATCH v1 08/12] xprtrdma: Add trace points to instrument MR allocation and recovery

[Chuck Lever]

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 include/trace/events/rpcrdma.h |   57 ++++++++++++++++++++++++++++++++++++++++
 net/sunrpc/xprtrdma/verbs.c    |    6 ++--
 2 files changed, 60 insertions(+), 3 deletions(-)

diff --git a/include/trace/events/rpcrdma.h b/include/trace/events/rpcrdma.h
index 057662b..d4dad18 100644
--- a/include/trace/events/rpcrdma.h
+++ b/include/trace/events/rpcrdma.h
@@ -50,6 +50,37 @@
 				),					\
 				TP_ARGS(rep))
 
+DECLARE_EVENT_CLASS(xprtrdma_rxprt,
+	TP_PROTO(
+		const struct rpcrdma_xprt *r_xprt
+	),
+
+	TP_ARGS(r_xprt),
+
+	TP_STRUCT__entry(
+		__field(const void *, r_xprt)
+		__string(addr, rpcrdma_addrstr(r_xprt))
+		__string(port, rpcrdma_portstr(r_xprt))
+	),
+
+	TP_fast_assign(
+		__entry->r_xprt = r_xprt;
+		__assign_str(addr, rpcrdma_addrstr(r_xprt));
+		__assign_str(port, rpcrdma_portstr(r_xprt));
+	),
+
+	TP_printk("peer=[%s]:%s r_xprt=%p",
+		__get_str(addr), __get_str(port), __entry->r_xprt
+	)
+);
+
+#define DEFINE_RXPRT_EVENT(name)					\
+		DEFINE_EVENT(xprtrdma_rxprt, name,			\
+				TP_PROTO(				\
+					const struct rpcrdma_xprt *r_xprt \
+				),					\
+				TP_ARGS(r_xprt))
+
 DECLARE_EVENT_CLASS(xprtrdma_rdch_event,
 	TP_PROTO(
 		const struct rpc_task *task,
@@ -239,6 +270,31 @@
  ** Call events
  **/
 
+TRACE_EVENT(xprtrdma_createmrs,
+	TP_PROTO(
+		const struct rpcrdma_xprt *r_xprt,
+		unsigned int count
+	),
+
+	TP_ARGS(r_xprt, count),
+
+	TP_STRUCT__entry(
+		__field(const void *, r_xprt)
+		__field(unsigned int, count)
+	),
+
+	TP_fast_assign(
+		__entry->r_xprt = r_xprt;
+		__entry->count = count;
+	),
+
+	TP_printk("r_xprt=%p: created %u MRs",
+		__entry->r_xprt, __entry->count
+	)
+);
+
+DEFINE_RXPRT_EVENT(xprtrdma_nomrs);
+
 DEFINE_RDCH_EVENT(xprtrdma_read_chunk);
 DEFINE_WRCH_EVENT(xprtrdma_write_chunk);
 DEFINE_WRCH_EVENT(xprtrdma_reply_chunk);
@@ -422,6 +478,7 @@
 DEFINE_MR_EVENT(xprtrdma_localinv);
 DEFINE_MR_EVENT(xprtrdma_dma_unmap);
 DEFINE_MR_EVENT(xprtrdma_remoteinv);
+DEFINE_MR_EVENT(xprtrdma_recover_mr);
 
 /**
  ** Reply events
diff --git a/net/sunrpc/xprtrdma/verbs.c b/net/sunrpc/xprtrdma/verbs.c
index 0e89e55..1addcc9 100644
--- a/net/sunrpc/xprtrdma/verbs.c
+++ b/net/sunrpc/xprtrdma/verbs.c
@@ -998,7 +998,7 @@ void rpcrdma_sendctx_put_locked(struct rpcrdma_sendctx *sc)
 		mr = rpcrdma_mr_pop(&buf->rb_stale_mrs);
 		spin_unlock(&buf->rb_recovery_lock);
 
-		dprintk("RPC:       %s: recovering MR %p\n", __func__, mr);
+		trace_xprtrdma_recover_mr(mr);
 		mr->mr_xprt->rx_ia.ri_ops->ro_recover_mr(mr);
 
 		spin_lock(&buf->rb_recovery_lock);
@@ -1054,7 +1054,7 @@ void rpcrdma_sendctx_put_locked(struct rpcrdma_sendctx *sc)
 	r_xprt->rx_stats.mrs_allocated += count;
 	spin_unlock(&buf->rb_mrlock);
 
-	dprintk("RPC:       %s: created %u MRs\n", __func__, count);
+	trace_xprtrdma_createmrs(r_xprt, count);
 }
 
 static void
@@ -1310,7 +1310,7 @@ struct rpcrdma_mr *
 	return mr;
 
 out_nomrs:
-	dprintk("RPC:       %s: no MRs available\n", __func__);
+	trace_xprtrdma_nomrs(r_xprt);
 	if (r_xprt->rx_ep.rep_connected != -ENODEV)
 		schedule_delayed_work(&buf->rb_refresh_worker, 0);
 

[PATCH v1 09/12] xprtrdma: Add trace points for connect events

[Chuck Lever]

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 include/trace/events/rpcrdma.h  |   75 +++++++++++++++++++++++++++++++++++++++
 net/sunrpc/xprtrdma/transport.c |   12 ++----
 net/sunrpc/xprtrdma/verbs.c     |   33 +++++++----------
 3 files changed, 92 insertions(+), 28 deletions(-)

diff --git a/include/trace/events/rpcrdma.h b/include/trace/events/rpcrdma.h
index d4dad18..79cc487 100644
--- a/include/trace/events/rpcrdma.h
+++ b/include/trace/events/rpcrdma.h
@@ -267,6 +267,81 @@
 				TP_ARGS(mr))
 
 /**
+ ** Connection events
+ **/
+
+TRACE_EVENT(xprtrdma_conn_upcall,
+	TP_PROTO(
+		const struct rpcrdma_xprt *r_xprt,
+		struct rdma_cm_event *event
+	),
+
+	TP_ARGS(r_xprt, event),
+
+	TP_STRUCT__entry(
+		__field(const void *, r_xprt)
+		__field(unsigned int, event)
+		__field(int, status)
+		__string(addr, rpcrdma_addrstr(r_xprt))
+		__string(port, rpcrdma_portstr(r_xprt))
+	),
+
+	TP_fast_assign(
+		__entry->r_xprt = r_xprt;
+		__entry->event = event->event;
+		__entry->status = event->status;
+		__assign_str(addr, rpcrdma_addrstr(r_xprt));
+		__assign_str(port, rpcrdma_portstr(r_xprt));
+	),
+
+	TP_printk("peer=[%s]:%s r_xprt=%p: %s (%u/%d)",
+		__get_str(addr), __get_str(port),
+		__entry->r_xprt, rdma_show_cm_event(__entry->event),
+		__entry->event, __entry->status
+	)
+);
+
+TRACE_EVENT(xprtrdma_disconnect,
+	TP_PROTO(
+		const struct rpcrdma_xprt *r_xprt,
+		int status
+	),
+
+	TP_ARGS(r_xprt, status),
+
+	TP_STRUCT__entry(
+		__field(const void *, r_xprt)
+		__field(int, status)
+		__field(int, connected)
+		__string(addr, rpcrdma_addrstr(r_xprt))
+		__string(port, rpcrdma_portstr(r_xprt))
+	),
+
+	TP_fast_assign(
+		__entry->r_xprt = r_xprt;
+		__entry->status = status;
+		__entry->connected = r_xprt->rx_ep.rep_connected;
+		__assign_str(addr, rpcrdma_addrstr(r_xprt));
+		__assign_str(port, rpcrdma_portstr(r_xprt));
+	),
+
+	TP_printk("peer=[%s]:%s r_xprt=%p: status=%d %sconnected",
+		__get_str(addr), __get_str(port),
+		__entry->r_xprt, __entry->status,
+		__entry->connected == 1 ? "still " : "dis"
+	)
+);
+
+DEFINE_RXPRT_EVENT(xprtrdma_conn_start);
+DEFINE_RXPRT_EVENT(xprtrdma_conn_tout);
+DEFINE_RXPRT_EVENT(xprtrdma_create);
+DEFINE_RXPRT_EVENT(xprtrdma_destroy);
+DEFINE_RXPRT_EVENT(xprtrdma_remove);
+DEFINE_RXPRT_EVENT(xprtrdma_reinsert);
+DEFINE_RXPRT_EVENT(xprtrdma_reconnect);
+DEFINE_RXPRT_EVENT(xprtrdma_inject_dsc);
+
+/**
  ** Call events
  **/
 
diff --git a/net/sunrpc/xprtrdma/transport.c b/net/sunrpc/xprtrdma/transport.c
index ddf0d87..25d1160 100644
--- a/net/sunrpc/xprtrdma/transport.c
+++ b/net/sunrpc/xprtrdma/transport.c
@@ -259,13 +259,10 @@
 
 	xprt_clear_connected(xprt);
 
-	dprintk("RPC:       %s: %sconnect\n", __func__,
-			r_xprt->rx_ep.rep_connected != 0 ? "re" : "");
 	rc = rpcrdma_ep_connect(&r_xprt->rx_ep, &r_xprt->rx_ia);
 	if (rc)
 		xprt_wake_pending_tasks(xprt, rc);
 
-	dprintk("RPC:       %s: exit\n", __func__);
 	xprt_clear_connecting(xprt);
 }
 
@@ -275,7 +272,7 @@
 	struct rpcrdma_xprt *r_xprt = container_of(xprt, struct rpcrdma_xprt,
 						   rx_xprt);
 
-	pr_info("rpcrdma: injecting transport disconnect on xprt=%p\n", xprt);
+	trace_xprtrdma_inject_dsc(r_xprt);
 	rdma_disconnect(r_xprt->rx_ia.ri_id);
 }
 
@@ -295,7 +292,7 @@
 {
 	struct rpcrdma_xprt *r_xprt = rpcx_to_rdmax(xprt);
 
-	dprintk("RPC:       %s: called\n", __func__);
+	trace_xprtrdma_destroy(r_xprt);
 
 	cancel_delayed_work_sync(&r_xprt->rx_connect_worker);
 
@@ -306,11 +303,8 @@
 	rpcrdma_ia_close(&r_xprt->rx_ia);
 
 	xprt_rdma_free_addresses(xprt);
-
 	xprt_free(xprt);
 
-	dprintk("RPC:       %s: returning\n", __func__);
-
 	module_put(THIS_MODULE);
 }
 
@@ -430,6 +424,7 @@
 	dprintk("RPC:       %s: %s:%s\n", __func__,
 		xprt->address_strings[RPC_DISPLAY_ADDR],
 		xprt->address_strings[RPC_DISPLAY_PORT]);
+	trace_xprtrdma_create(new_xprt);
 	return xprt;
 
 out4:
@@ -440,6 +435,7 @@
 out2:
 	rpcrdma_ia_close(&new_xprt->rx_ia);
 out1:
+	trace_xprtrdma_destroy(new_xprt);
 	xprt_rdma_free_addresses(xprt);
 	xprt_free(xprt);
 	return ERR_PTR(rc);
diff --git a/net/sunrpc/xprtrdma/verbs.c b/net/sunrpc/xprtrdma/verbs.c
index 1addcc9..7f9e902 100644
--- a/net/sunrpc/xprtrdma/verbs.c
+++ b/net/sunrpc/xprtrdma/verbs.c
@@ -220,6 +220,7 @@
 	struct rpcrdma_ep *ep = &xprt->rx_ep;
 	int connstate = 0;
 
+	trace_xprtrdma_conn_upcall(xprt, event);
 	switch (event->event) {
 	case RDMA_CM_EVENT_ADDR_RESOLVED:
 	case RDMA_CM_EVENT_ROUTE_RESOLVED:
@@ -228,14 +229,10 @@
 		break;
 	case RDMA_CM_EVENT_ADDR_ERROR:
 		ia->ri_async_rc = -EHOSTUNREACH;
-		dprintk("RPC:       %s: CM address resolution error, ep 0x%p\n",
-			__func__, ep);
 		complete(&ia->ri_done);
 		break;
 	case RDMA_CM_EVENT_ROUTE_ERROR:
 		ia->ri_async_rc = -ENETUNREACH;
-		dprintk("RPC:       %s: CM route resolution error, ep 0x%p\n",
-			__func__, ep);
 		complete(&ia->ri_done);
 		break;
 	case RDMA_CM_EVENT_DEVICE_REMOVAL:
@@ -299,6 +296,8 @@
 	struct rdma_cm_id *id;
 	int rc;
 
+	trace_xprtrdma_conn_start(xprt);
+
 	init_completion(&ia->ri_done);
 	init_completion(&ia->ri_remove_done);
 
@@ -322,8 +321,7 @@
 	}
 	rc = wait_for_completion_interruptible_timeout(&ia->ri_done, wtimeout);
 	if (rc < 0) {
-		dprintk("RPC:       %s: wait() exited: %i\n",
-			__func__, rc);
+		trace_xprtrdma_conn_tout(xprt);
 		goto out;
 	}
 
@@ -340,8 +338,7 @@
 	}
 	rc = wait_for_completion_interruptible_timeout(&ia->ri_done, wtimeout);
 	if (rc < 0) {
-		dprintk("RPC:       %s: wait() exited: %i\n",
-			__func__, rc);
+		trace_xprtrdma_conn_tout(xprt);
 		goto out;
 	}
 	rc = ia->ri_async_rc;
@@ -461,6 +458,8 @@
 
 	/* Allow waiters to continue */
 	complete(&ia->ri_remove_done);
+
+	trace_xprtrdma_remove(r_xprt);
 }
 
 /**
@@ -471,7 +470,6 @@
 void
 rpcrdma_ia_close(struct rpcrdma_ia *ia)
 {
-	dprintk("RPC:       %s: entering\n", __func__);
 	if (ia->ri_id != NULL && !IS_ERR(ia->ri_id)) {
 		if (ia->ri_id->qp)
 			rdma_destroy_qp(ia->ri_id);
@@ -625,9 +623,6 @@
 void
 rpcrdma_ep_destroy(struct rpcrdma_ep *ep, struct rpcrdma_ia *ia)
 {
-	dprintk("RPC:       %s: entering, connected is %d\n",
-		__func__, ep->rep_connected);
-
 	cancel_delayed_work_sync(&ep->rep_connect_worker);
 
 	if (ia->ri_id->qp) {
@@ -650,7 +645,7 @@
 {
 	int rc, err;
 
-	pr_info("%s: r_xprt = %p\n", __func__, r_xprt);
+	trace_xprtrdma_reinsert(r_xprt);
 
 	rc = -EHOSTUNREACH;
 	if (rpcrdma_ia_open(r_xprt))
@@ -688,7 +683,7 @@
 	struct rdma_cm_id *id, *old;
 	int err, rc;
 
-	dprintk("RPC:       %s: reconnecting...\n", __func__);
+	trace_xprtrdma_reconnect(r_xprt);
 
 	rpcrdma_ep_disconnect(ep, ia);
 
@@ -810,16 +805,14 @@
 	int rc;
 
 	rc = rdma_disconnect(ia->ri_id);
-	if (!rc) {
+	if (!rc)
 		/* returns without wait if not connected */
 		wait_event_interruptible(ep->rep_connect_wait,
 							ep->rep_connected != 1);
-		dprintk("RPC:       %s: after wait, %sconnected\n", __func__,
-			(ep->rep_connected == 1) ? "still " : "dis");
-	} else {
-		dprintk("RPC:       %s: rdma_disconnect %i\n", __func__, rc);
+	else
 		ep->rep_connected = rc;
-	}
+	trace_xprtrdma_disconnect(container_of(ep, struct rpcrdma_xprt,
+					       rx_ep), rc);
 
 	ib_drain_qp(ia->ri_id->qp);
 }

[PATCH v1 10/12] xprtrdma: Add trace points in the client-side backchannel code paths

[Chuck Lever]

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 include/trace/events/rpcrdma.h    |   68 +++++++++++++++++++++++++++++++++++++
 net/sunrpc/xprtrdma/backchannel.c |    8 ++--
 net/sunrpc/xprtrdma/xprt_rdma.h   |    2 +
 3 files changed, 73 insertions(+), 5 deletions(-)

diff --git a/include/trace/events/rpcrdma.h b/include/trace/events/rpcrdma.h
index 79cc487..16ac4d4 100644
--- a/include/trace/events/rpcrdma.h
+++ b/include/trace/events/rpcrdma.h
@@ -266,6 +266,39 @@
 				), \
 				TP_ARGS(mr))
 
+DECLARE_EVENT_CLASS(xprtrdma_cb_event,
+	TP_PROTO(
+		const struct rpc_rqst *rqst
+	),
+
+	TP_ARGS(rqst),
+
+	TP_STRUCT__entry(
+		__field(const void *, rqst)
+		__field(const void *, rep)
+		__field(const void *, req)
+		__field(u32, xid)
+	),
+
+	TP_fast_assign(
+		__entry->rqst = rqst;
+		__entry->req = rpcr_to_rdmar(rqst);
+		__entry->rep = rpcr_to_rdmar(rqst)->rl_reply;
+		__entry->xid = be32_to_cpu(rqst->rq_xid);
+	),
+
+	TP_printk("xid=0x%08x, rqst=%p req=%p rep=%p",
+		__entry->xid, __entry->rqst, __entry->req, __entry->rep
+	)
+);
+
+#define DEFINE_CB_EVENT(name)						\
+		DEFINE_EVENT(xprtrdma_cb_event, name,			\
+				TP_PROTO(				\
+					const struct rpc_rqst *rqst	\
+				),					\
+				TP_ARGS(rqst))
+
 /**
  ** Connection events
  **/
@@ -718,6 +751,41 @@
 	)
 );
 
+/**
+ ** Callback events
+ **/
+
+TRACE_EVENT(xprtrdma_cb_setup,
+	TP_PROTO(
+		const struct rpcrdma_xprt *r_xprt,
+		unsigned int reqs
+	),
+
+	TP_ARGS(r_xprt, reqs),
+
+	TP_STRUCT__entry(
+		__field(const void *, r_xprt)
+		__field(unsigned int, reqs)
+		__string(addr, rpcrdma_addrstr(r_xprt))
+		__string(port, rpcrdma_portstr(r_xprt))
+	),
+
+	TP_fast_assign(
+		__entry->r_xprt = r_xprt;
+		__entry->reqs = reqs;
+		__assign_str(addr, rpcrdma_addrstr(r_xprt));
+		__assign_str(port, rpcrdma_portstr(r_xprt));
+	),
+
+	TP_printk("peer=[%s]:%s r_xprt=%p: %u reqs",
+		__get_str(addr), __get_str(port),
+		__entry->r_xprt, __entry->reqs
+	)
+);
+
+DEFINE_CB_EVENT(xprtrdma_cb_call);
+DEFINE_CB_EVENT(xprtrdma_cb_reply);
+
 #endif /* _TRACE_RPCRDMA_H */
 
 #include <trace/define_trace.h>
diff --git a/net/sunrpc/xprtrdma/backchannel.c b/net/sunrpc/xprtrdma/backchannel.c
index 3c7998a..ca0c5d3 100644
--- a/net/sunrpc/xprtrdma/backchannel.c
+++ b/net/sunrpc/xprtrdma/backchannel.c
@@ -140,7 +140,7 @@ int xprt_rdma_bc_setup(struct rpc_xprt *xprt, unsigned int reqs)
 
 	buffer->rb_bc_srv_max_requests = reqs;
 	request_module("svcrdma");
-
+	trace_xprtrdma_cb_setup(r_xprt, reqs);
 	return 0;
 
 out_free:
@@ -212,6 +212,8 @@ static int rpcrdma_bc_marshal_reply(struct rpc_rqst *rqst)
 	if (rpcrdma_prepare_send_sges(r_xprt, req, RPCRDMA_HDRLEN_MIN,
 				      &rqst->rq_snd_buf, rpcrdma_noch))
 		return -EIO;
+
+	trace_xprtrdma_cb_reply(rqst);
 	return 0;
 }
 
@@ -331,7 +333,6 @@ void rpcrdma_bc_receive_call(struct rpcrdma_xprt *r_xprt,
 				struct rpc_rqst, rq_bc_pa_list);
 	list_del(&rqst->rq_bc_pa_list);
 	spin_unlock(&xprt->bc_pa_lock);
-	dprintk("RPC:       %s: using rqst %p\n", __func__, rqst);
 
 	/* Prepare rqst */
 	rqst->rq_reply_bytes_recvd = 0;
@@ -352,9 +353,8 @@ void rpcrdma_bc_receive_call(struct rpcrdma_xprt *r_xprt,
 	 * the Upper Layer is done decoding it.
 	 */
 	req = rpcr_to_rdmar(rqst);
-	dprintk("RPC:       %s: attaching rep %p to req %p\n",
-		__func__, rep, req);
 	req->rl_reply = rep;
+	trace_xprtrdma_cb_call(rqst);
 
 	/* Queue rqst for ULP's callback service */
 	bc_serv = xprt->bc_serv;
diff --git a/net/sunrpc/xprtrdma/xprt_rdma.h b/net/sunrpc/xprtrdma/xprt_rdma.h
index a1ca1b6..69883a9 100644
--- a/net/sunrpc/xprtrdma/xprt_rdma.h
+++ b/net/sunrpc/xprtrdma/xprt_rdma.h
@@ -365,7 +365,7 @@ enum {
 }
 
 static inline struct rpcrdma_req *
-rpcr_to_rdmar(struct rpc_rqst *rqst)
+rpcr_to_rdmar(const struct rpc_rqst *rqst)
 {
 	return rqst->rq_xprtdata;
 }

[PATCH v1 11/12] xprtrdma: Add trace points to instrument QP and CQ access upcalls

[Chuck Lever]

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 include/trace/events/rpcrdma.h |   31 +++++++++++++++++++++++++++++++
 net/sunrpc/xprtrdma/verbs.c    |    3 +++
 2 files changed, 34 insertions(+)

diff --git a/include/trace/events/rpcrdma.h b/include/trace/events/rpcrdma.h
index 16ac4d4..5aa3ec7 100644
--- a/include/trace/events/rpcrdma.h
+++ b/include/trace/events/rpcrdma.h
@@ -374,6 +374,37 @@
 DEFINE_RXPRT_EVENT(xprtrdma_reconnect);
 DEFINE_RXPRT_EVENT(xprtrdma_inject_dsc);
 
+TRACE_EVENT(xprtrdma_qp_error,
+	TP_PROTO(
+		const struct rpcrdma_xprt *r_xprt,
+		const struct ib_event *event
+	),
+
+	TP_ARGS(r_xprt, event),
+
+	TP_STRUCT__entry(
+		__field(const void *, r_xprt)
+		__field(unsigned int, event)
+		__string(name, event->device->name)
+		__string(addr, rpcrdma_addrstr(r_xprt))
+		__string(port, rpcrdma_portstr(r_xprt))
+	),
+
+	TP_fast_assign(
+		__entry->r_xprt = r_xprt;
+		__entry->event = event->event;
+		__assign_str(name, event->device->name);
+		__assign_str(addr, rpcrdma_addrstr(r_xprt));
+		__assign_str(port, rpcrdma_portstr(r_xprt));
+	),
+
+	TP_printk("peer=[%s]:%s r_xprt=%p: dev %s: %s (%u)",
+		__get_str(addr), __get_str(port), __entry->r_xprt,
+		__get_str(name), rdma_show_ib_event(__entry->event),
+		__entry->event
+	)
+);
+
 /**
  ** Call events
  **/
diff --git a/net/sunrpc/xprtrdma/verbs.c b/net/sunrpc/xprtrdma/verbs.c
index 7f9e902..fb81d3a 100644
--- a/net/sunrpc/xprtrdma/verbs.c
+++ b/net/sunrpc/xprtrdma/verbs.c
@@ -108,7 +108,10 @@
 rpcrdma_qp_async_error_upcall(struct ib_event *event, void *context)
 {
 	struct rpcrdma_ep *ep = context;
+	struct rpcrdma_xprt *r_xprt = container_of(ep, struct rpcrdma_xprt,
+						   rx_ep);
 
+	trace_xprtrdma_qp_error(r_xprt, event);
 	pr_err("rpcrdma: %s on device %s ep %p\n",
 	       ib_event_msg(event->event), event->device->name, context);
 

[PATCH v1 12/12] xprtrdma: Instrument allocation/release of rpcrdma_req/rep objects

[Chuck Lever]

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 include/trace/events/rpcrdma.h  |   67 +++++++++++++++++++++++++++++++++++++++
 net/sunrpc/xprtrdma/transport.c |   12 +++----
 net/sunrpc/xprtrdma/verbs.c     |    4 +-
 3 files changed, 74 insertions(+), 9 deletions(-)

diff --git a/include/trace/events/rpcrdma.h b/include/trace/events/rpcrdma.h
index 5aa3ec7..27fd452 100644
--- a/include/trace/events/rpcrdma.h
+++ b/include/trace/events/rpcrdma.h
@@ -783,6 +783,73 @@
 );
 
 /**
+ ** Allocation/release of rpcrdma_reqs and rpcrdma_reps
+ **/
+
+TRACE_EVENT(xprtrdma_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(const void *, rep)
+		__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->rep = req ? req->rl_reply : NULL;
+		__entry->callsize = task->tk_rqstp->rq_callsize;
+		__entry->rcvsize = task->tk_rqstp->rq_rcvsize;
+	),
+
+	TP_printk("task:%u@%u req=%p rep=%p (%zu, %zu)",
+		__entry->task_id, __entry->client_id,
+		__entry->req, __entry->rep,
+		__entry->callsize, __entry->rcvsize
+	)
+);
+
+TRACE_EVENT(xprtrdma_rpc_done,
+	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(const void *, rep)
+	),
+
+	TP_fast_assign(
+		__entry->task_id = task->tk_pid;
+		__entry->client_id = task->tk_client->cl_clid;
+		__entry->req = req;
+		__entry->rep = req->rl_reply;
+	),
+
+	TP_printk("task:%u@%u req=%p rep=%p",
+		__entry->task_id, __entry->client_id,
+		__entry->req, __entry->rep
+	)
+);
+
+DEFINE_RXPRT_EVENT(xprtrdma_noreps);
+
+/**
  ** Callback events
  **/
 
diff --git a/net/sunrpc/xprtrdma/transport.c b/net/sunrpc/xprtrdma/transport.c
index 25d1160..b90179a 100644
--- a/net/sunrpc/xprtrdma/transport.c
+++ b/net/sunrpc/xprtrdma/transport.c
@@ -640,7 +640,7 @@
 
 	req = rpcrdma_buffer_get(&r_xprt->rx_buf);
 	if (req == NULL)
-		return -ENOMEM;
+		goto out_get;
 
 	flags = RPCRDMA_DEF_GFP;
 	if (RPC_IS_SWAPPER(task))
@@ -653,19 +653,18 @@
 	if (!rpcrdma_get_recvbuf(r_xprt, req, rqst->rq_rcvsize, flags))
 		goto out_fail;
 
-	dprintk("RPC: %5u %s: send size = %zd, recv size = %zd, req = %p\n",
-		task->tk_pid, __func__, rqst->rq_callsize,
-		rqst->rq_rcvsize, req);
-
 	req->rl_cpu = smp_processor_id();
 	req->rl_connect_cookie = 0;	/* our reserved value */
 	rpcrdma_set_xprtdata(rqst, req);
 	rqst->rq_buffer = req->rl_sendbuf->rg_base;
 	rqst->rq_rbuffer = req->rl_recvbuf->rg_base;
+	trace_xprtrdma_allocate(task, req);
 	return 0;
 
 out_fail:
 	rpcrdma_buffer_put(req);
+out_get:
+	trace_xprtrdma_allocate(task, NULL);
 	return -ENOMEM;
 }
 
@@ -682,10 +681,9 @@
 	struct rpcrdma_xprt *r_xprt = rpcx_to_rdmax(rqst->rq_xprt);
 	struct rpcrdma_req *req = rpcr_to_rdmar(rqst);
 
-	dprintk("RPC:       %s: called on 0x%p\n", __func__, req->rl_reply);
-
 	if (test_bit(RPCRDMA_REQ_F_PENDING, &req->rl_flags))
 		rpcrdma_release_rqst(r_xprt, req);
+	trace_xprtrdma_rpc_done(task, req);
 	rpcrdma_buffer_put(req);
 }
 
diff --git a/net/sunrpc/xprtrdma/verbs.c b/net/sunrpc/xprtrdma/verbs.c
index fb81d3a..57e1139 100644
--- a/net/sunrpc/xprtrdma/verbs.c
+++ b/net/sunrpc/xprtrdma/verbs.c
@@ -1385,11 +1385,11 @@ struct rpcrdma_req *
 	req = rpcrdma_buffer_get_req_locked(buffers);
 	req->rl_reply = rpcrdma_buffer_get_rep(buffers);
 	spin_unlock(&buffers->rb_lock);
+
 	return req;
 
 out_reqbuf:
 	spin_unlock(&buffers->rb_lock);
-	pr_warn("RPC:       %s: out of request buffers\n", __func__);
 	return NULL;
 }
 
@@ -1612,7 +1612,7 @@ struct rpcrdma_regbuf *
 
 out_reqbuf:
 	spin_unlock(&buffers->rb_lock);
-	pr_warn("%s: no extra receive buffers\n", __func__);
+	trace_xprtrdma_noreps(r_xprt);
 	return -ENOMEM;
 
 out_rc: