[PATCH v6 0/2] Proposed trace points for RDMA/core

[PATCH v6 0/2] Proposed trace points for RDMA/core

[Chuck Lever]

Changes since v5:
- Add low-overhead trace points in the Connection Manager
- Address #include heartburn found by lkp

Changes since v4:
- Removed __ib_poll_cq, uninlined ib_poll_cq

Changes since v3:
- Reverted unnecessary behavior change in __ib_process_cq
- Clarified what "id" is in trace point output
- Added comment before new fields in struct ib_cq
- New trace point that fires when there is a CQ allocation failure

Changes since v2:
- Removed extraneous changes to include/trace/events/rdma.h

Changes since RFC:
- Display CQ's global resource ID instead of it's pointer address

---

Chuck Lever (2):
      RDMA/core: Trace points for diagnosing completion queue issues
      RDMA/cma: Add trace points in RDMA Connection Manager


 drivers/infiniband/core/Makefile    |    4 -
 drivers/infiniband/core/cma.c       |   60 ++++++--
 drivers/infiniband/core/cma_trace.c |   16 ++
 drivers/infiniband/core/cq.c        |   36 +++++
 drivers/infiniband/core/trace.c     |   14 ++
 include/rdma/ib_verbs.h             |   11 +-
 include/trace/events/rdma_cma.h     |  218 +++++++++++++++++++++++++++++++
 include/trace/events/rdma_core.h    |  250 +++++++++++++++++++++++++++++++++++
 8 files changed, 585 insertions(+), 24 deletions(-)
 create mode 100644 drivers/infiniband/core/cma_trace.c
 create mode 100644 drivers/infiniband/core/trace.c
 create mode 100644 include/trace/events/rdma_cma.h
 create mode 100644 include/trace/events/rdma_core.h

--
Chuck Lever

[PATCH v6 1/2] RDMA/core: Trace points for diagnosing completion queue issues

[Chuck Lever]

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
Reviewed-by: Parav Pandit <parav@mellanox.com>
---
 drivers/infiniband/core/Makefile |    2 
 drivers/infiniband/core/cq.c     |   36 +++++
 drivers/infiniband/core/trace.c  |   14 ++
 include/rdma/ib_verbs.h          |   11 +-
 include/trace/events/rdma_core.h |  250 ++++++++++++++++++++++++++++++++++++++
 5 files changed, 306 insertions(+), 7 deletions(-)
 create mode 100644 drivers/infiniband/core/trace.c
 create mode 100644 include/trace/events/rdma_core.h

diff --git a/drivers/infiniband/core/Makefile b/drivers/infiniband/core/Makefile
index 09881bd5f12d..68d9e27c3c61 100644
--- a/drivers/infiniband/core/Makefile
+++ b/drivers/infiniband/core/Makefile
@@ -11,7 +11,7 @@ ib_core-y :=			packer.o ud_header.o verbs.o cq.o rw.o sysfs.o \
 				device.o fmr_pool.o cache.o netlink.o \
 				roce_gid_mgmt.o mr_pool.o addr.o sa_query.o \
 				multicast.o mad.o smi.o agent.o mad_rmpp.o \
-				nldev.o restrack.o counters.o
+				nldev.o restrack.o counters.o trace.o
 
 ib_core-$(CONFIG_SECURITY_INFINIBAND) += security.o
 ib_core-$(CONFIG_CGROUP_RDMA) += cgroup.o
diff --git a/drivers/infiniband/core/cq.c b/drivers/infiniband/core/cq.c
index bbfded6d5d3d..98931472eaa0 100644
--- a/drivers/infiniband/core/cq.c
+++ b/drivers/infiniband/core/cq.c
@@ -7,6 +7,8 @@
 #include <linux/slab.h>
 #include <rdma/ib_verbs.h>
 
+#include <trace/events/rdma_core.h>
+
 /* # of WCs to poll for with a single call to ib_poll_cq */
 #define IB_POLL_BATCH			16
 #define IB_POLL_BATCH_DIRECT		8
@@ -41,6 +43,7 @@ static void ib_cq_rdma_dim_work(struct work_struct *w)
 
 	dim->state = DIM_START_MEASURE;
 
+	trace_cq_modify(cq, comps, usec);
 	cq->device->ops.modify_cq(cq, comps, usec);
 }
 
@@ -65,11 +68,35 @@ static void rdma_dim_init(struct ib_cq *cq)
 	INIT_WORK(&dim->work, ib_cq_rdma_dim_work);
 }
 
+/**
+ * ib_poll_cq - poll a CQ for completion(s)
+ * @cq: the CQ being polled
+ * @num_entries: maximum number of completions to return
+ * @wc: array of at least @num_entries &struct ib_wc where completions
+ *      will be returned
+ *
+ * Poll a CQ for (possibly multiple) completions.  If the return value
+ * is < 0, an error occurred.  If the return value is >= 0, it is the
+ * number of completions returned.  If the return value is
+ * non-negative and < num_entries, then the CQ was emptied.
+ */
+int ib_poll_cq(struct ib_cq *cq, int num_entries, struct ib_wc *wc)
+{
+	int rc;
+
+	rc = cq->device->ops.poll_cq(cq, num_entries, wc);
+	trace_cq_poll(cq, num_entries, rc);
+	return rc;
+}
+EXPORT_SYMBOL(ib_poll_cq);
+
 static int __ib_process_cq(struct ib_cq *cq, int budget, struct ib_wc *wcs,
 			   int batch)
 {
 	int i, n, completed = 0;
 
+	trace_cq_process(cq);
+
 	/*
 	 * budget might be (-1) if the caller does not
 	 * want to bound this call, thus we need unsigned
@@ -131,8 +158,10 @@ static int ib_poll_handler(struct irq_poll *iop, int budget)
 	completed = __ib_process_cq(cq, budget, cq->wc, IB_POLL_BATCH);
 	if (completed < budget) {
 		irq_poll_complete(&cq->iop);
-		if (ib_req_notify_cq(cq, IB_POLL_FLAGS) > 0)
+		if (ib_req_notify_cq(cq, IB_POLL_FLAGS) > 0) {
+			trace_cq_reschedule(cq);
 			irq_poll_sched(&cq->iop);
+		}
 	}
 
 	if (dim)
@@ -143,6 +172,7 @@ static int ib_poll_handler(struct irq_poll *iop, int budget)
 
 static void ib_cq_completion_softirq(struct ib_cq *cq, void *private)
 {
+	trace_cq_schedule(cq);
 	irq_poll_sched(&cq->iop);
 }
 
@@ -162,6 +192,7 @@ static void ib_cq_poll_work(struct work_struct *work)
 
 static void ib_cq_completion_workqueue(struct ib_cq *cq, void *private)
 {
+	trace_cq_schedule(cq);
 	queue_work(cq->comp_wq, &cq->work);
 }
 
@@ -239,6 +270,7 @@ struct ib_cq *__ib_alloc_cq_user(struct ib_device *dev, void *private,
 		goto out_destroy_cq;
 	}
 
+	trace_cq_alloc(cq, nr_cqe, comp_vector, poll_ctx);
 	return cq;
 
 out_destroy_cq:
@@ -248,6 +280,7 @@ struct ib_cq *__ib_alloc_cq_user(struct ib_device *dev, void *private,
 	kfree(cq->wc);
 out_free_cq:
 	kfree(cq);
+	trace_cq_alloc_error(nr_cqe, comp_vector, poll_ctx, ret);
 	return ERR_PTR(ret);
 }
 EXPORT_SYMBOL(__ib_alloc_cq_user);
@@ -304,6 +337,7 @@ void ib_free_cq_user(struct ib_cq *cq, struct ib_udata *udata)
 		WARN_ON_ONCE(1);
 	}
 
+	trace_cq_free(cq);
 	rdma_restrack_del(&cq->res);
 	cq->device->ops.destroy_cq(cq, udata);
 	if (cq->dim)
diff --git a/drivers/infiniband/core/trace.c b/drivers/infiniband/core/trace.c
new file mode 100644
index 000000000000..6c3514beac4d
--- /dev/null
+++ b/drivers/infiniband/core/trace.c
@@ -0,0 +1,14 @@
+// SPDX-License-Identifier: GPL-2.0-only
+/*
+ * Trace points for core RDMA functions.
+ *
+ * Author: Chuck Lever <chuck.lever@oracle.com>
+ *
+ * Copyright (c) 2019, Oracle and/or its affiliates. All rights reserved.
+ */
+
+#define CREATE_TRACE_POINTS
+
+#include <rdma/ib_verbs.h>
+
+#include <trace/events/rdma_core.h>
diff --git a/include/rdma/ib_verbs.h b/include/rdma/ib_verbs.h
index e7e733add99f..71353f81caf1 100644
--- a/include/rdma/ib_verbs.h
+++ b/include/rdma/ib_verbs.h
@@ -1555,6 +1555,11 @@ struct ib_cq {
 	};
 	struct workqueue_struct *comp_wq;
 	struct dim *dim;
+
+	/* updated only by trace points */
+	ktime_t timestamp;
+	bool interrupt;
+
 	/*
 	 * Implementation details of the RDMA core, don't use in drivers:
 	 */
@@ -3868,11 +3873,7 @@ static inline void ib_destroy_cq(struct ib_cq *cq)
  * number of completions returned.  If the return value is
  * non-negative and < num_entries, then the CQ was emptied.
  */
-static inline int ib_poll_cq(struct ib_cq *cq, int num_entries,
-			     struct ib_wc *wc)
-{
-	return cq->device->ops.poll_cq(cq, num_entries, wc);
-}
+int ib_poll_cq(struct ib_cq *cq, int num_entries, struct ib_wc *wc);
 
 /**
  * ib_req_notify_cq - Request completion notification on a CQ.
diff --git a/include/trace/events/rdma_core.h b/include/trace/events/rdma_core.h
new file mode 100644
index 000000000000..45f74c52ae24
--- /dev/null
+++ b/include/trace/events/rdma_core.h
@@ -0,0 +1,250 @@
+/* SPDX-License-Identifier: GPL-2.0-only */
+/*
+ * Trace point definitions for core RDMA functions.
+ *
+ * Author: Chuck Lever <chuck.lever@oracle.com>
+ *
+ * Copyright (c) 2019, Oracle and/or its affiliates. All rights reserved.
+ */
+
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM rdma_core
+
+#if !defined(_TRACE_RDMA_CORE_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_RDMA_CORE_H
+
+#include <linux/tracepoint.h>
+#include <rdma/ib_verbs.h>
+
+/*
+ * enum ib_poll_context, from include/rdma/ib_verbs.h
+ */
+#define IB_POLL_CTX_LIST			\
+	ib_poll_ctx(DIRECT)			\
+	ib_poll_ctx(SOFTIRQ)			\
+	ib_poll_ctx(WORKQUEUE)			\
+	ib_poll_ctx_end(UNBOUND_WORKQUEUE)
+
+#undef ib_poll_ctx
+#undef ib_poll_ctx_end
+
+#define ib_poll_ctx(x)		TRACE_DEFINE_ENUM(IB_POLL_##x);
+#define ib_poll_ctx_end(x)	TRACE_DEFINE_ENUM(IB_POLL_##x);
+
+IB_POLL_CTX_LIST
+
+#undef ib_poll_ctx
+#undef ib_poll_ctx_end
+
+#define ib_poll_ctx(x)		{ IB_POLL_##x, #x },
+#define ib_poll_ctx_end(x)	{ IB_POLL_##x, #x }
+
+#define rdma_show_ib_poll_ctx(x) \
+		__print_symbolic(x, IB_POLL_CTX_LIST)
+
+/**
+ ** Completion Queue events
+ **/
+
+TRACE_EVENT(cq_schedule,
+	TP_PROTO(
+		struct ib_cq *cq
+	),
+
+	TP_ARGS(cq),
+
+	TP_STRUCT__entry(
+		__field(u32, id)
+	),
+
+	TP_fast_assign(
+		cq->timestamp = ktime_get();
+		cq->interrupt = true;
+
+		__entry->id = cq->res.id;
+	),
+
+	TP_printk("cq.id=%u", __entry->id)
+);
+
+TRACE_EVENT(cq_reschedule,
+	TP_PROTO(
+		struct ib_cq *cq
+	),
+
+	TP_ARGS(cq),
+
+	TP_STRUCT__entry(
+		__field(u32, id)
+	),
+
+	TP_fast_assign(
+		cq->timestamp = ktime_get();
+		cq->interrupt = false;
+
+		__entry->id = cq->res.id;
+	),
+
+	TP_printk("cq.id=%u", __entry->id)
+);
+
+TRACE_EVENT(cq_process,
+	TP_PROTO(
+		const struct ib_cq *cq
+	),
+
+	TP_ARGS(cq),
+
+	TP_STRUCT__entry(
+		__field(s64, latency)
+		__field(u32, id)
+		__field(bool, interrupt)
+	),
+
+	TP_fast_assign(
+		ktime_t latency = ktime_sub(ktime_get(), cq->timestamp);
+
+		__entry->id = cq->res.id;
+		__entry->latency = ktime_to_us(latency);
+		__entry->interrupt = cq->interrupt;
+	),
+
+	TP_printk("cq.id=%u wake-up took %lld [us] from %s",
+		__entry->id, __entry->latency,
+		__entry->interrupt ? "interrupt" : "reschedule"
+	)
+);
+
+TRACE_EVENT(cq_poll,
+	TP_PROTO(
+		const struct ib_cq *cq,
+		int requested,
+		int rc
+	),
+
+	TP_ARGS(cq, requested, rc),
+
+	TP_STRUCT__entry(
+		__field(u32, id)
+		__field(int, requested)
+		__field(int, rc)
+	),
+
+	TP_fast_assign(
+		__entry->id = cq->res.id;
+		__entry->requested = requested;
+		__entry->rc = rc;
+	),
+
+	TP_printk("cq.id=%u requested %d, returned %d",
+		__entry->id, __entry->requested, __entry->rc
+	)
+);
+
+TRACE_EVENT(cq_modify,
+	TP_PROTO(
+		const struct ib_cq *cq,
+		u16 comps,
+		u16 usec
+	),
+
+	TP_ARGS(cq, comps, usec),
+
+	TP_STRUCT__entry(
+		__field(u32, id)
+		__field(unsigned int, comps)
+		__field(unsigned int, usec)
+	),
+
+	TP_fast_assign(
+		__entry->id = cq->res.id;
+		__entry->comps = comps;
+		__entry->usec = usec;
+	),
+
+	TP_printk("cq.id=%u comps=%u usec=%u",
+		__entry->id, __entry->comps, __entry->usec
+	)
+);
+
+TRACE_EVENT(cq_alloc,
+	TP_PROTO(
+		const struct ib_cq *cq,
+		int nr_cqe,
+		int comp_vector,
+		enum ib_poll_context poll_ctx
+	),
+
+	TP_ARGS(cq, nr_cqe, comp_vector, poll_ctx),
+
+	TP_STRUCT__entry(
+		__field(u32, id)
+		__field(int, nr_cqe)
+		__field(int, comp_vector)
+		__field(unsigned long, poll_ctx)
+	),
+
+	TP_fast_assign(
+		__entry->id = cq->res.id;
+		__entry->nr_cqe = nr_cqe;
+		__entry->comp_vector = comp_vector;
+		__entry->poll_ctx = poll_ctx;
+	),
+
+	TP_printk("cq.id=%u nr_cqe=%d comp_vector=%d poll_ctx=%s",
+		__entry->id, __entry->nr_cqe, __entry->comp_vector,
+		rdma_show_ib_poll_ctx(__entry->poll_ctx)
+	)
+);
+
+TRACE_EVENT(cq_alloc_error,
+	TP_PROTO(
+		int nr_cqe,
+		int comp_vector,
+		enum ib_poll_context poll_ctx,
+		int rc
+	),
+
+	TP_ARGS(nr_cqe, comp_vector, poll_ctx, rc),
+
+	TP_STRUCT__entry(
+		__field(int, rc)
+		__field(int, nr_cqe)
+		__field(int, comp_vector)
+		__field(unsigned long, poll_ctx)
+	),
+
+	TP_fast_assign(
+		__entry->rc = rc;
+		__entry->nr_cqe = nr_cqe;
+		__entry->comp_vector = comp_vector;
+		__entry->poll_ctx = poll_ctx;
+	),
+
+	TP_printk("nr_cqe=%d comp_vector=%d poll_ctx=%s rc=%d",
+		__entry->nr_cqe, __entry->comp_vector,
+		rdma_show_ib_poll_ctx(__entry->poll_ctx), __entry->rc
+	)
+);
+
+TRACE_EVENT(cq_free,
+	TP_PROTO(
+		const struct ib_cq *cq
+	),
+
+	TP_ARGS(cq),
+
+	TP_STRUCT__entry(
+		__field(u32, id)
+	),
+
+	TP_fast_assign(
+		__entry->id = cq->res.id;
+	),
+
+	TP_printk("cq.id=%u", __entry->id)
+);
+
+#endif /* _TRACE_RDMA_CORE_H */
+
+#include <trace/define_trace.h>

[PATCH v6 2/2] RDMA/cma: Add trace points in RDMA Connection Manager

[Chuck Lever]

Record state transitions as each connection is established. The IP
address of both peers and the Type of Service is reported. These
new trace points are not in performance hot paths.

Also, record each cm_event_handler call to ULPs. This eliminates the
need for each ULP to add its own similar trace point in its CM event
handler function.

These new trace points appear in a new trace subsystem called
"rdma_cma".

This patch is based on previous work by:

Saeed Mahameed <saeedm@mellanox.com>
Mukesh Kacker <mukesh.kacker@oracle.com>
Ajaykumar Hotchandani <ajaykumar.hotchandani@oracle.com>
Aron Silverton <aron.silverton@oracle.com>
Avinash Repaka <avinash.repaka@oracle.com>
Somasundaram Krishnasamy <somasundaram.krishnasamy@oracle.com>

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 drivers/infiniband/core/Makefile    |    2 
 drivers/infiniband/core/cma.c       |   60 +++++++---
 drivers/infiniband/core/cma_trace.c |   16 +++
 include/trace/events/rdma_cma.h     |  218 +++++++++++++++++++++++++++++++++++
 4 files changed, 279 insertions(+), 17 deletions(-)
 create mode 100644 drivers/infiniband/core/cma_trace.c
 create mode 100644 include/trace/events/rdma_cma.h

diff --git a/drivers/infiniband/core/Makefile b/drivers/infiniband/core/Makefile
index 68d9e27c3c61..bab7b6f01982 100644
--- a/drivers/infiniband/core/Makefile
+++ b/drivers/infiniband/core/Makefile
@@ -20,7 +20,7 @@ ib_cm-y :=			cm.o
 
 iw_cm-y :=			iwcm.o iwpm_util.o iwpm_msg.o
 
-rdma_cm-y :=			cma.o
+rdma_cm-y :=			cma.o cma_trace.o
 
 rdma_cm-$(CONFIG_INFINIBAND_ADDR_TRANS_CONFIGFS) += cma_configfs.o
 
diff --git a/drivers/infiniband/core/cma.c b/drivers/infiniband/core/cma.c
index d78f67623f24..5d5e63336954 100644
--- a/drivers/infiniband/core/cma.c
+++ b/drivers/infiniband/core/cma.c
@@ -64,6 +64,8 @@
 #include "core_priv.h"
 #include "cma_priv.h"
 
+#include <trace/events/rdma_cma.h>
+
 MODULE_AUTHOR("Sean Hefty");
 MODULE_DESCRIPTION("Generic RDMA CM Agent");
 MODULE_LICENSE("Dual BSD/GPL");
@@ -1890,6 +1892,7 @@ static int cma_rep_recv(struct rdma_id_private *id_priv)
 	if (ret)
 		goto reject;
 
+	trace_cm_send_rtu(id_priv);
 	ret = ib_send_cm_rtu(id_priv->cm_id.ib, NULL, 0);
 	if (ret)
 		goto reject;
@@ -1898,6 +1901,7 @@ static int cma_rep_recv(struct rdma_id_private *id_priv)
 reject:
 	pr_debug_ratelimited("RDMA CM: CONNECT_ERROR: failed to handle reply. status %d\n", ret);
 	cma_modify_qp_err(id_priv);
+	trace_cm_send_rej(id_priv);
 	ib_send_cm_rej(id_priv->cm_id.ib, IB_CM_REJ_CONSUMER_DEFINED,
 		       NULL, 0, NULL, 0);
 	return ret;
@@ -1917,6 +1921,13 @@ static void cma_set_rep_event_data(struct rdma_cm_event *event,
 	event->param.conn.qp_num = rep_data->remote_qpn;
 }
 
+static int cma_cm_event_handler(struct rdma_id_private *id_priv,
+				struct rdma_cm_event *event)
+{
+	trace_cm_event_handler(id_priv, event);
+	return id_priv->id.event_handler(&id_priv->id, event);
+}
+
 static int cma_ib_handler(struct ib_cm_id *cm_id,
 			  const struct ib_cm_event *ib_event)
 {
@@ -1939,8 +1950,10 @@ static int cma_ib_handler(struct ib_cm_id *cm_id,
 		break;
 	case IB_CM_REP_RECEIVED:
 		if (cma_comp(id_priv, RDMA_CM_CONNECT) &&
-		    (id_priv->id.qp_type != IB_QPT_UD))
+		    (id_priv->id.qp_type != IB_QPT_UD)) {
+			trace_cm_send_mra(id_priv);
 			ib_send_cm_mra(cm_id, CMA_CM_MRA_SETTING, NULL, 0);
+		}
 		if (id_priv->id.qp) {
 			event.status = cma_rep_recv(id_priv);
 			event.event = event.status ? RDMA_CM_EVENT_CONNECT_ERROR :
@@ -1985,7 +1998,7 @@ static int cma_ib_handler(struct ib_cm_id *cm_id,
 		goto out;
 	}
 
-	ret = id_priv->id.event_handler(&id_priv->id, &event);
+	ret = cma_cm_event_handler(id_priv, &event);
 	if (ret) {
 		/* Destroy the CM ID by returning a non-zero value. */
 		id_priv->cm_id.ib = NULL;
@@ -2146,6 +2159,7 @@ static int cma_ib_req_handler(struct ib_cm_id *cm_id,
 	if (IS_ERR(listen_id))
 		return PTR_ERR(listen_id);
 
+	trace_cm_req_handler(listen_id, ib_event->event);
 	if (!cma_ib_check_req_qp_type(&listen_id->id, ib_event)) {
 		ret = -EINVAL;
 		goto net_dev_put;
@@ -2188,7 +2202,7 @@ static int cma_ib_req_handler(struct ib_cm_id *cm_id,
 	 * until we're done accessing it.
 	 */
 	atomic_inc(&conn_id->refcount);
-	ret = conn_id->id.event_handler(&conn_id->id, &event);
+	ret = cma_cm_event_handler(conn_id, &event);
 	if (ret)
 		goto err3;
 	/*
@@ -2197,8 +2211,10 @@ static int cma_ib_req_handler(struct ib_cm_id *cm_id,
 	 */
 	mutex_lock(&lock);
 	if (cma_comp(conn_id, RDMA_CM_CONNECT) &&
-	    (conn_id->id.qp_type != IB_QPT_UD))
+	    (conn_id->id.qp_type != IB_QPT_UD)) {
+		trace_cm_send_mra(cm_id->context);
 		ib_send_cm_mra(cm_id, CMA_CM_MRA_SETTING, NULL, 0);
+	}
 	mutex_unlock(&lock);
 	mutex_unlock(&conn_id->handler_mutex);
 	mutex_unlock(&listen_id->handler_mutex);
@@ -2313,7 +2329,7 @@ static int cma_iw_handler(struct iw_cm_id *iw_id, struct iw_cm_event *iw_event)
 	event.status = iw_event->status;
 	event.param.conn.private_data = iw_event->private_data;
 	event.param.conn.private_data_len = iw_event->private_data_len;
-	ret = id_priv->id.event_handler(&id_priv->id, &event);
+	ret = cma_cm_event_handler(id_priv, &event);
 	if (ret) {
 		/* Destroy the CM ID by returning a non-zero value. */
 		id_priv->cm_id.iw = NULL;
@@ -2390,7 +2406,7 @@ static int iw_conn_req_handler(struct iw_cm_id *cm_id,
 	 * until we're done accessing it.
 	 */
 	atomic_inc(&conn_id->refcount);
-	ret = conn_id->id.event_handler(&conn_id->id, &event);
+	ret = cma_cm_event_handler(conn_id, &event);
 	if (ret) {
 		/* User wants to destroy the CM ID */
 		conn_id->cm_id.iw = NULL;
@@ -2462,6 +2478,7 @@ static int cma_listen_handler(struct rdma_cm_id *id,
 
 	id->context = id_priv->id.context;
 	id->event_handler = id_priv->id.event_handler;
+	trace_cm_event_handler(id_priv, event);
 	return id_priv->id.event_handler(id, event);
 }
 
@@ -2636,7 +2653,7 @@ static void cma_work_handler(struct work_struct *_work)
 	if (!cma_comp_exch(id_priv, work->old_state, work->new_state))
 		goto out;
 
-	if (id_priv->id.event_handler(&id_priv->id, &work->event)) {
+	if (cma_cm_event_handler(id_priv, &work->event)) {
 		cma_exch(id_priv, RDMA_CM_DESTROYING);
 		destroy = 1;
 	}
@@ -2659,7 +2676,7 @@ static void cma_ndev_work_handler(struct work_struct *_work)
 	    id_priv->state == RDMA_CM_DEVICE_REMOVAL)
 		goto out;
 
-	if (id_priv->id.event_handler(&id_priv->id, &work->event)) {
+	if (cma_cm_event_handler(id_priv, &work->event)) {
 		cma_exch(id_priv, RDMA_CM_DESTROYING);
 		destroy = 1;
 	}
@@ -3062,7 +3079,7 @@ static void addr_handler(int status, struct sockaddr *src_addr,
 	} else
 		event.event = RDMA_CM_EVENT_ADDR_RESOLVED;
 
-	if (id_priv->id.event_handler(&id_priv->id, &event)) {
+	if (cma_cm_event_handler(id_priv, &event)) {
 		cma_exch(id_priv, RDMA_CM_DESTROYING);
 		mutex_unlock(&id_priv->handler_mutex);
 		rdma_destroy_id(&id_priv->id);
@@ -3709,7 +3726,7 @@ static int cma_sidr_rep_handler(struct ib_cm_id *cm_id,
 		goto out;
 	}
 
-	ret = id_priv->id.event_handler(&id_priv->id, &event);
+	ret = cma_cm_event_handler(id_priv, &event);
 
 	rdma_destroy_ah_attr(&event.param.ud.ah_attr);
 	if (ret) {
@@ -3773,6 +3790,7 @@ static int cma_resolve_ib_udp(struct rdma_id_private *id_priv,
 	req.timeout_ms = 1 << (CMA_CM_RESPONSE_TIMEOUT - 8);
 	req.max_cm_retries = CMA_MAX_CM_RETRIES;
 
+	trace_cm_send_sidr_req(id_priv);
 	ret = ib_send_cm_sidr_req(id_priv->cm_id.ib, &req);
 	if (ret) {
 		ib_destroy_cm_id(id_priv->cm_id.ib);
@@ -3846,6 +3864,7 @@ static int cma_connect_ib(struct rdma_id_private *id_priv,
 	req.max_cm_retries = CMA_MAX_CM_RETRIES;
 	req.srq = id_priv->srq ? 1 : 0;
 
+	trace_cm_send_req(id_priv);
 	ret = ib_send_cm_req(id_priv->cm_id.ib, &req);
 out:
 	if (ret && !IS_ERR(id)) {
@@ -3959,6 +3978,7 @@ static int cma_accept_ib(struct rdma_id_private *id_priv,
 	rep.rnr_retry_count = min_t(u8, 7, conn_param->rnr_retry_count);
 	rep.srq = id_priv->srq ? 1 : 0;
 
+	trace_cm_send_rep(id_priv);
 	ret = ib_send_cm_rep(id_priv->cm_id.ib, &rep);
 out:
 	return ret;
@@ -4008,6 +4028,7 @@ static int cma_send_sidr_rep(struct rdma_id_private *id_priv,
 	rep.private_data = private_data;
 	rep.private_data_len = private_data_len;
 
+	trace_cm_send_sidr_rep(id_priv);
 	return ib_send_cm_sidr_rep(id_priv->cm_id.ib, &rep);
 }
 
@@ -4093,13 +4114,15 @@ int rdma_reject(struct rdma_cm_id *id, const void *private_data,
 		return -EINVAL;
 
 	if (rdma_cap_ib_cm(id->device, id->port_num)) {
-		if (id->qp_type == IB_QPT_UD)
+		if (id->qp_type == IB_QPT_UD) {
 			ret = cma_send_sidr_rep(id_priv, IB_SIDR_REJECT, 0,
 						private_data, private_data_len);
-		else
+		} else {
+			trace_cm_send_rej(id_priv);
 			ret = ib_send_cm_rej(id_priv->cm_id.ib,
 					     IB_CM_REJ_CONSUMER_DEFINED, NULL,
 					     0, private_data, private_data_len);
+		}
 	} else if (rdma_cap_iw_cm(id->device, id->port_num)) {
 		ret = iw_cm_reject(id_priv->cm_id.iw,
 				   private_data, private_data_len);
@@ -4124,8 +4147,13 @@ int rdma_disconnect(struct rdma_cm_id *id)
 		if (ret)
 			goto out;
 		/* Initiate or respond to a disconnect. */
-		if (ib_send_cm_dreq(id_priv->cm_id.ib, NULL, 0))
-			ib_send_cm_drep(id_priv->cm_id.ib, NULL, 0);
+		trace_cm_disconnect(id_priv);
+		if (ib_send_cm_dreq(id_priv->cm_id.ib, NULL, 0)) {
+			if (!ib_send_cm_drep(id_priv->cm_id.ib, NULL, 0))
+				trace_cm_sent_drep(id_priv);
+		} else {
+			trace_cm_sent_dreq(id_priv);
+		}
 	} else if (rdma_cap_iw_cm(id->device, id->port_num)) {
 		ret = iw_cm_disconnect(id_priv->cm_id.iw, 0);
 	} else
@@ -4191,7 +4219,7 @@ static int cma_ib_mc_handler(int status, struct ib_sa_multicast *multicast)
 	} else
 		event.event = RDMA_CM_EVENT_MULTICAST_ERROR;
 
-	ret = id_priv->id.event_handler(&id_priv->id, &event);
+	ret = cma_cm_event_handler(id_priv, &event);
 
 	rdma_destroy_ah_attr(&event.param.ud.ah_attr);
 	if (ret) {
@@ -4626,7 +4654,7 @@ static int cma_remove_id_dev(struct rdma_id_private *id_priv)
 		goto out;
 
 	event.event = RDMA_CM_EVENT_DEVICE_REMOVAL;
-	ret = id_priv->id.event_handler(&id_priv->id, &event);
+	ret = cma_cm_event_handler(id_priv, &event);
 out:
 	mutex_unlock(&id_priv->handler_mutex);
 	return ret;
diff --git a/drivers/infiniband/core/cma_trace.c b/drivers/infiniband/core/cma_trace.c
new file mode 100644
index 000000000000..1093fa813bc1
--- /dev/null
+++ b/drivers/infiniband/core/cma_trace.c
@@ -0,0 +1,16 @@
+// SPDX-License-Identifier: GPL-2.0-only
+/*
+ * Trace points for the RDMA Connection Manager.
+ *
+ * Author: Chuck Lever <chuck.lever@oracle.com>
+ *
+ * Copyright (c) 2019, Oracle and/or its affiliates. All rights reserved.
+ */
+
+#define CREATE_TRACE_POINTS
+
+#include <rdma/rdma_cm.h>
+#include <rdma/ib_cm.h>
+#include "cma_priv.h"
+
+#include <trace/events/rdma_cma.h>
diff --git a/include/trace/events/rdma_cma.h b/include/trace/events/rdma_cma.h
new file mode 100644
index 000000000000..b6ccdade651c
--- /dev/null
+++ b/include/trace/events/rdma_cma.h
@@ -0,0 +1,218 @@
+/* SPDX-License-Identifier: GPL-2.0-only */
+/*
+ * Trace point definitions for the RDMA Connect Manager.
+ *
+ * Author: Chuck Lever <chuck.lever@oracle.com>
+ *
+ * Copyright (c) 2019, Oracle and/or its affiliates. All rights reserved.
+ */
+
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM rdma_cma
+
+#if !defined(_TRACE_RDMA_CMA_H) || defined(TRACE_HEADER_MULTI_READ)
+
+#define _TRACE_RDMA_CMA_H
+
+#include <linux/tracepoint.h>
+#include <rdma/rdma_cm.h>
+#include "cma_priv.h"
+
+#include <trace/events/rdma.h>
+
+/*
+ * enum ib_cm_event_type, from include/rdma/ib_cm.h
+ */
+#define IB_CM_EVENT_LIST			\
+	ib_cm_event(REQ_ERROR)			\
+	ib_cm_event(REQ_RECEIVED)		\
+	ib_cm_event(REP_ERROR)			\
+	ib_cm_event(REP_RECEIVED)		\
+	ib_cm_event(RTU_RECEIVED)		\
+	ib_cm_event(USER_ESTABLISHED)		\
+	ib_cm_event(DREQ_ERROR)			\
+	ib_cm_event(DREQ_RECEIVED)		\
+	ib_cm_event(DREP_RECEIVED)		\
+	ib_cm_event(TIMEWAIT_EXIT)		\
+	ib_cm_event(MRA_RECEIVED)		\
+	ib_cm_event(REJ_RECEIVED)		\
+	ib_cm_event(LAP_ERROR)			\
+	ib_cm_event(LAP_RECEIVED)		\
+	ib_cm_event(APR_RECEIVED)		\
+	ib_cm_event(SIDR_REQ_ERROR)		\
+	ib_cm_event(SIDR_REQ_RECEIVED)		\
+	ib_cm_event_end(SIDR_REP_RECEIVED)
+
+#undef ib_cm_event
+#undef ib_cm_event_end
+
+#define ib_cm_event(x)		TRACE_DEFINE_ENUM(IB_CM_##x);
+#define ib_cm_event_end(x)	TRACE_DEFINE_ENUM(IB_CM_##x);
+
+IB_CM_EVENT_LIST
+
+#undef ib_cm_event
+#undef ib_cm_event_end
+
+#define ib_cm_event(x)		{ IB_CM_##x, #x },
+#define ib_cm_event_end(x)	{ IB_CM_##x, #x }
+
+#define rdma_show_ib_cm_event(x) \
+		__print_symbolic(x, IB_CM_EVENT_LIST)
+
+
+DECLARE_EVENT_CLASS(cma_fsm_class,
+	TP_PROTO(
+		const struct rdma_id_private *id_priv
+	),
+
+	TP_ARGS(id_priv),
+
+	TP_STRUCT__entry(
+		__field(u32, id)
+		__field(u32, tos)
+		__array(unsigned char, srcaddr, sizeof(struct sockaddr_in6))
+		__array(unsigned char, dstaddr, sizeof(struct sockaddr_in6))
+	),
+
+	TP_fast_assign(
+		__entry->id = id_priv->res.id;
+		__entry->tos = id_priv->tos;
+		memcpy(__entry->srcaddr, &id_priv->id.route.addr.src_addr,
+		       sizeof(struct sockaddr_in6));
+		memcpy(__entry->dstaddr, &id_priv->id.route.addr.dst_addr,
+		       sizeof(struct sockaddr_in6));
+	),
+
+	TP_printk("cm_id.id=%u src: %pISpc dst: %pISpc tos=%u",
+		__entry->id, __entry->srcaddr, __entry->dstaddr, __entry->tos
+	)
+);
+
+#define DEFINE_CMA_FSM_EVENT(name)						\
+		DEFINE_EVENT(cma_fsm_class, cm_##name,				\
+				TP_PROTO(					\
+					const struct rdma_id_private *id_priv	\
+				),						\
+				TP_ARGS(id_priv))
+
+DEFINE_CMA_FSM_EVENT(send_rtu);
+DEFINE_CMA_FSM_EVENT(send_rej);
+DEFINE_CMA_FSM_EVENT(send_mra);
+DEFINE_CMA_FSM_EVENT(send_sidr_req);
+DEFINE_CMA_FSM_EVENT(send_sidr_rep);
+DEFINE_CMA_FSM_EVENT(disconnect);
+DEFINE_CMA_FSM_EVENT(sent_drep);
+DEFINE_CMA_FSM_EVENT(sent_dreq);
+
+DECLARE_EVENT_CLASS(cma_qp_class,
+	TP_PROTO(
+		const struct rdma_id_private *id_priv
+	),
+
+	TP_ARGS(id_priv),
+
+	TP_STRUCT__entry(
+		__field(u32, id)
+		__field(u32, tos)
+		__field(u32, qp_num)
+		__array(unsigned char, srcaddr, sizeof(struct sockaddr_in6))
+		__array(unsigned char, dstaddr, sizeof(struct sockaddr_in6))
+	),
+
+	TP_fast_assign(
+		__entry->id = id_priv->res.id;
+		__entry->tos = id_priv->tos;
+		__entry->qp_num = id_priv->qp_num;
+		memcpy(__entry->srcaddr, &id_priv->id.route.addr.src_addr,
+		       sizeof(struct sockaddr_in6));
+		memcpy(__entry->dstaddr, &id_priv->id.route.addr.dst_addr,
+		       sizeof(struct sockaddr_in6));
+	),
+
+	TP_printk("cm_id.id=%u src: %pISpc dst: %pISpc tos=%u qp_num=%u",
+		__entry->id, __entry->srcaddr, __entry->dstaddr, __entry->tos,
+		__entry->qp_num
+	)
+);
+
+#define DEFINE_CMA_QP_EVENT(name)						\
+		DEFINE_EVENT(cma_qp_class, cm_##name,				\
+				TP_PROTO(					\
+					const struct rdma_id_private *id_priv	\
+				),						\
+				TP_ARGS(id_priv))
+
+DEFINE_CMA_QP_EVENT(send_req);
+DEFINE_CMA_QP_EVENT(send_rep);
+
+TRACE_EVENT(cm_req_handler,
+	TP_PROTO(
+		const struct rdma_id_private *id_priv,
+		int event
+	),
+
+	TP_ARGS(id_priv, event),
+
+	TP_STRUCT__entry(
+		__field(u32, id)
+		__field(u32, tos)
+		__field(unsigned long, event)
+		__array(unsigned char, srcaddr, sizeof(struct sockaddr_in6))
+		__array(unsigned char, dstaddr, sizeof(struct sockaddr_in6))
+	),
+
+	TP_fast_assign(
+		__entry->id = id_priv->res.id;
+		__entry->tos = id_priv->tos;
+		__entry->event = event;
+		memcpy(__entry->srcaddr, &id_priv->id.route.addr.src_addr,
+		       sizeof(struct sockaddr_in6));
+		memcpy(__entry->dstaddr, &id_priv->id.route.addr.dst_addr,
+		       sizeof(struct sockaddr_in6));
+	),
+
+	TP_printk("cm_id.id=%u src: %pISpc dst: %pISpc tos=%u %s (%lu)",
+		__entry->id, __entry->srcaddr, __entry->dstaddr, __entry->tos,
+		rdma_show_ib_cm_event(__entry->event), __entry->event
+	)
+);
+
+TRACE_EVENT(cm_event_handler,
+	TP_PROTO(
+		const struct rdma_id_private *id_priv,
+		const struct rdma_cm_event *event
+	),
+
+	TP_ARGS(id_priv, event),
+
+	TP_STRUCT__entry(
+		__field(u32, id)
+		__field(u32, tos)
+		__field(unsigned long, event)
+		__field(int, status)
+		__array(unsigned char, srcaddr, sizeof(struct sockaddr_in6))
+		__array(unsigned char, dstaddr, sizeof(struct sockaddr_in6))
+	),
+
+	TP_fast_assign(
+		__entry->id = id_priv->res.id;
+		__entry->tos = id_priv->tos;
+		__entry->event = event->event;
+		__entry->status = event->status;
+		memcpy(__entry->srcaddr, &id_priv->id.route.addr.src_addr,
+		       sizeof(struct sockaddr_in6));
+		memcpy(__entry->dstaddr, &id_priv->id.route.addr.dst_addr,
+		       sizeof(struct sockaddr_in6));
+	),
+
+	TP_printk("cm_id.id=%u src: %pISpc dst: %pISpc tos=%u %s (%lu/%d)",
+		__entry->id, __entry->srcaddr, __entry->dstaddr, __entry->tos,
+		rdma_show_cm_event(__entry->event), __entry->event,
+		__entry->status
+	)
+);
+
+#endif /* _TRACE_RDMA_CMA_H */
+
+#include <trace/define_trace.h>

Re: [PATCH v6 2/2] RDMA/cma: Add trace points in RDMA Connection Manager

[Leon Romanovsky]

On Mon, Nov 18, 2019 at 04:49:15PM -0500, Chuck Lever wrote:
> Record state transitions as each connection is established. The IP
> address of both peers and the Type of Service is reported. These
> new trace points are not in performance hot paths.
>
> Also, record each cm_event_handler call to ULPs. This eliminates the
> need for each ULP to add its own similar trace point in its CM event
> handler function.
>
> These new trace points appear in a new trace subsystem called
> "rdma_cma".
>
> This patch is based on previous work by:
>
> Saeed Mahameed <saeedm@mellanox.com>
> Mukesh Kacker <mukesh.kacker@oracle.com>
> Ajaykumar Hotchandani <ajaykumar.hotchandani@oracle.com>
> Aron Silverton <aron.silverton@oracle.com>
> Avinash Repaka <avinash.repaka@oracle.com>
> Somasundaram Krishnasamy <somasundaram.krishnasamy@oracle.com>
>
> Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
> ---
>  drivers/infiniband/core/Makefile    |    2
>  drivers/infiniband/core/cma.c       |   60 +++++++---
>  drivers/infiniband/core/cma_trace.c |   16 +++
>  include/trace/events/rdma_cma.h     |  218 +++++++++++++++++++++++++++++++++++
>  4 files changed, 279 insertions(+), 17 deletions(-)
>  create mode 100644 drivers/infiniband/core/cma_trace.c
>  create mode 100644 include/trace/events/rdma_cma.h
>
> diff --git a/drivers/infiniband/core/Makefile b/drivers/infiniband/core/Makefile
> index 68d9e27c3c61..bab7b6f01982 100644
> --- a/drivers/infiniband/core/Makefile
> +++ b/drivers/infiniband/core/Makefile
> @@ -20,7 +20,7 @@ ib_cm-y :=			cm.o
>
>  iw_cm-y :=			iwcm.o iwpm_util.o iwpm_msg.o
>
> -rdma_cm-y :=			cma.o
> +rdma_cm-y :=			cma.o cma_trace.o
>
>  rdma_cm-$(CONFIG_INFINIBAND_ADDR_TRANS_CONFIGFS) += cma_configfs.o
>
> diff --git a/drivers/infiniband/core/cma.c b/drivers/infiniband/core/cma.c
> index d78f67623f24..5d5e63336954 100644
> --- a/drivers/infiniband/core/cma.c
> +++ b/drivers/infiniband/core/cma.c
> @@ -64,6 +64,8 @@
>  #include "core_priv.h"
>  #include "cma_priv.h"
>
> +#include <trace/events/rdma_cma.h>
> +
>  MODULE_AUTHOR("Sean Hefty");
>  MODULE_DESCRIPTION("Generic RDMA CM Agent");
>  MODULE_LICENSE("Dual BSD/GPL");
> @@ -1890,6 +1892,7 @@ static int cma_rep_recv(struct rdma_id_private *id_priv)
>  	if (ret)
>  		goto reject;
>
> +	trace_cm_send_rtu(id_priv);
>  	ret = ib_send_cm_rtu(id_priv->cm_id.ib, NULL, 0);
>  	if (ret)
>  		goto reject;
> @@ -1898,6 +1901,7 @@ static int cma_rep_recv(struct rdma_id_private *id_priv)
>  reject:
>  	pr_debug_ratelimited("RDMA CM: CONNECT_ERROR: failed to handle reply. status %d\n", ret);
>  	cma_modify_qp_err(id_priv);
> +	trace_cm_send_rej(id_priv);
>  	ib_send_cm_rej(id_priv->cm_id.ib, IB_CM_REJ_CONSUMER_DEFINED,
>  		       NULL, 0, NULL, 0);
>  	return ret;
> @@ -1917,6 +1921,13 @@ static void cma_set_rep_event_data(struct rdma_cm_event *event,
>  	event->param.conn.qp_num = rep_data->remote_qpn;
>  }
>
> +static int cma_cm_event_handler(struct rdma_id_private *id_priv,
> +				struct rdma_cm_event *event)
> +{
> +	trace_cm_event_handler(id_priv, event);
> +	return id_priv->id.event_handler(&id_priv->id, event);
> +}
> +
>  static int cma_ib_handler(struct ib_cm_id *cm_id,
>  			  const struct ib_cm_event *ib_event)
>  {
> @@ -1939,8 +1950,10 @@ static int cma_ib_handler(struct ib_cm_id *cm_id,
>  		break;
>  	case IB_CM_REP_RECEIVED:
>  		if (cma_comp(id_priv, RDMA_CM_CONNECT) &&
> -		    (id_priv->id.qp_type != IB_QPT_UD))
> +		    (id_priv->id.qp_type != IB_QPT_UD)) {
> +			trace_cm_send_mra(id_priv);
>  			ib_send_cm_mra(cm_id, CMA_CM_MRA_SETTING, NULL, 0);
> +		}
>  		if (id_priv->id.qp) {
>  			event.status = cma_rep_recv(id_priv);
>  			event.event = event.status ? RDMA_CM_EVENT_CONNECT_ERROR :
> @@ -1985,7 +1998,7 @@ static int cma_ib_handler(struct ib_cm_id *cm_id,
>  		goto out;
>  	}
>
> -	ret = id_priv->id.event_handler(&id_priv->id, &event);
> +	ret = cma_cm_event_handler(id_priv, &event);
>  	if (ret) {
>  		/* Destroy the CM ID by returning a non-zero value. */
>  		id_priv->cm_id.ib = NULL;
> @@ -2146,6 +2159,7 @@ static int cma_ib_req_handler(struct ib_cm_id *cm_id,
>  	if (IS_ERR(listen_id))
>  		return PTR_ERR(listen_id);
>
> +	trace_cm_req_handler(listen_id, ib_event->event);
>  	if (!cma_ib_check_req_qp_type(&listen_id->id, ib_event)) {
>  		ret = -EINVAL;
>  		goto net_dev_put;
> @@ -2188,7 +2202,7 @@ static int cma_ib_req_handler(struct ib_cm_id *cm_id,
>  	 * until we're done accessing it.
>  	 */
>  	atomic_inc(&conn_id->refcount);
> -	ret = conn_id->id.event_handler(&conn_id->id, &event);
> +	ret = cma_cm_event_handler(conn_id, &event);
>  	if (ret)
>  		goto err3;
>  	/*
> @@ -2197,8 +2211,10 @@ static int cma_ib_req_handler(struct ib_cm_id *cm_id,
>  	 */
>  	mutex_lock(&lock);
>  	if (cma_comp(conn_id, RDMA_CM_CONNECT) &&
> -	    (conn_id->id.qp_type != IB_QPT_UD))
> +	    (conn_id->id.qp_type != IB_QPT_UD)) {
> +		trace_cm_send_mra(cm_id->context);
>  		ib_send_cm_mra(cm_id, CMA_CM_MRA_SETTING, NULL, 0);
> +	}
>  	mutex_unlock(&lock);
>  	mutex_unlock(&conn_id->handler_mutex);
>  	mutex_unlock(&listen_id->handler_mutex);
> @@ -2313,7 +2329,7 @@ static int cma_iw_handler(struct iw_cm_id *iw_id, struct iw_cm_event *iw_event)
>  	event.status = iw_event->status;
>  	event.param.conn.private_data = iw_event->private_data;
>  	event.param.conn.private_data_len = iw_event->private_data_len;
> -	ret = id_priv->id.event_handler(&id_priv->id, &event);
> +	ret = cma_cm_event_handler(id_priv, &event);
>  	if (ret) {
>  		/* Destroy the CM ID by returning a non-zero value. */
>  		id_priv->cm_id.iw = NULL;
> @@ -2390,7 +2406,7 @@ static int iw_conn_req_handler(struct iw_cm_id *cm_id,
>  	 * until we're done accessing it.
>  	 */
>  	atomic_inc(&conn_id->refcount);
> -	ret = conn_id->id.event_handler(&conn_id->id, &event);
> +	ret = cma_cm_event_handler(conn_id, &event);
>  	if (ret) {
>  		/* User wants to destroy the CM ID */
>  		conn_id->cm_id.iw = NULL;
> @@ -2462,6 +2478,7 @@ static int cma_listen_handler(struct rdma_cm_id *id,
>
>  	id->context = id_priv->id.context;
>  	id->event_handler = id_priv->id.event_handler;
> +	trace_cm_event_handler(id_priv, event);
>  	return id_priv->id.event_handler(id, event);
>  }
>
> @@ -2636,7 +2653,7 @@ static void cma_work_handler(struct work_struct *_work)
>  	if (!cma_comp_exch(id_priv, work->old_state, work->new_state))
>  		goto out;
>
> -	if (id_priv->id.event_handler(&id_priv->id, &work->event)) {
> +	if (cma_cm_event_handler(id_priv, &work->event)) {
>  		cma_exch(id_priv, RDMA_CM_DESTROYING);
>  		destroy = 1;
>  	}
> @@ -2659,7 +2676,7 @@ static void cma_ndev_work_handler(struct work_struct *_work)
>  	    id_priv->state == RDMA_CM_DEVICE_REMOVAL)
>  		goto out;
>
> -	if (id_priv->id.event_handler(&id_priv->id, &work->event)) {
> +	if (cma_cm_event_handler(id_priv, &work->event)) {
>  		cma_exch(id_priv, RDMA_CM_DESTROYING);
>  		destroy = 1;
>  	}
> @@ -3062,7 +3079,7 @@ static void addr_handler(int status, struct sockaddr *src_addr,
>  	} else
>  		event.event = RDMA_CM_EVENT_ADDR_RESOLVED;
>
> -	if (id_priv->id.event_handler(&id_priv->id, &event)) {
> +	if (cma_cm_event_handler(id_priv, &event)) {
>  		cma_exch(id_priv, RDMA_CM_DESTROYING);
>  		mutex_unlock(&id_priv->handler_mutex);
>  		rdma_destroy_id(&id_priv->id);
> @@ -3709,7 +3726,7 @@ static int cma_sidr_rep_handler(struct ib_cm_id *cm_id,
>  		goto out;
>  	}
>
> -	ret = id_priv->id.event_handler(&id_priv->id, &event);
> +	ret = cma_cm_event_handler(id_priv, &event);
>
>  	rdma_destroy_ah_attr(&event.param.ud.ah_attr);
>  	if (ret) {
> @@ -3773,6 +3790,7 @@ static int cma_resolve_ib_udp(struct rdma_id_private *id_priv,
>  	req.timeout_ms = 1 << (CMA_CM_RESPONSE_TIMEOUT - 8);
>  	req.max_cm_retries = CMA_MAX_CM_RETRIES;
>
> +	trace_cm_send_sidr_req(id_priv);
>  	ret = ib_send_cm_sidr_req(id_priv->cm_id.ib, &req);
>  	if (ret) {
>  		ib_destroy_cm_id(id_priv->cm_id.ib);
> @@ -3846,6 +3864,7 @@ static int cma_connect_ib(struct rdma_id_private *id_priv,
>  	req.max_cm_retries = CMA_MAX_CM_RETRIES;
>  	req.srq = id_priv->srq ? 1 : 0;
>
> +	trace_cm_send_req(id_priv);
>  	ret = ib_send_cm_req(id_priv->cm_id.ib, &req);
>  out:
>  	if (ret && !IS_ERR(id)) {
> @@ -3959,6 +3978,7 @@ static int cma_accept_ib(struct rdma_id_private *id_priv,
>  	rep.rnr_retry_count = min_t(u8, 7, conn_param->rnr_retry_count);
>  	rep.srq = id_priv->srq ? 1 : 0;
>
> +	trace_cm_send_rep(id_priv);
>  	ret = ib_send_cm_rep(id_priv->cm_id.ib, &rep);
>  out:
>  	return ret;
> @@ -4008,6 +4028,7 @@ static int cma_send_sidr_rep(struct rdma_id_private *id_priv,
>  	rep.private_data = private_data;
>  	rep.private_data_len = private_data_len;
>
> +	trace_cm_send_sidr_rep(id_priv);
>  	return ib_send_cm_sidr_rep(id_priv->cm_id.ib, &rep);
>  }
>
> @@ -4093,13 +4114,15 @@ int rdma_reject(struct rdma_cm_id *id, const void *private_data,
>  		return -EINVAL;
>
>  	if (rdma_cap_ib_cm(id->device, id->port_num)) {
> -		if (id->qp_type == IB_QPT_UD)
> +		if (id->qp_type == IB_QPT_UD) {
>  			ret = cma_send_sidr_rep(id_priv, IB_SIDR_REJECT, 0,
>  						private_data, private_data_len);
> -		else
> +		} else {
> +			trace_cm_send_rej(id_priv);
>  			ret = ib_send_cm_rej(id_priv->cm_id.ib,
>  					     IB_CM_REJ_CONSUMER_DEFINED, NULL,
>  					     0, private_data, private_data_len);
> +		}
>  	} else if (rdma_cap_iw_cm(id->device, id->port_num)) {
>  		ret = iw_cm_reject(id_priv->cm_id.iw,
>  				   private_data, private_data_len);
> @@ -4124,8 +4147,13 @@ int rdma_disconnect(struct rdma_cm_id *id)
>  		if (ret)
>  			goto out;
>  		/* Initiate or respond to a disconnect. */
> -		if (ib_send_cm_dreq(id_priv->cm_id.ib, NULL, 0))
> -			ib_send_cm_drep(id_priv->cm_id.ib, NULL, 0);
> +		trace_cm_disconnect(id_priv);
> +		if (ib_send_cm_dreq(id_priv->cm_id.ib, NULL, 0)) {
> +			if (!ib_send_cm_drep(id_priv->cm_id.ib, NULL, 0))
> +				trace_cm_sent_drep(id_priv);
> +		} else {
> +			trace_cm_sent_dreq(id_priv);
> +		}
>  	} else if (rdma_cap_iw_cm(id->device, id->port_num)) {
>  		ret = iw_cm_disconnect(id_priv->cm_id.iw, 0);
>  	} else
> @@ -4191,7 +4219,7 @@ static int cma_ib_mc_handler(int status, struct ib_sa_multicast *multicast)
>  	} else
>  		event.event = RDMA_CM_EVENT_MULTICAST_ERROR;
>
> -	ret = id_priv->id.event_handler(&id_priv->id, &event);
> +	ret = cma_cm_event_handler(id_priv, &event);
>
>  	rdma_destroy_ah_attr(&event.param.ud.ah_attr);
>  	if (ret) {
> @@ -4626,7 +4654,7 @@ static int cma_remove_id_dev(struct rdma_id_private *id_priv)
>  		goto out;
>
>  	event.event = RDMA_CM_EVENT_DEVICE_REMOVAL;
> -	ret = id_priv->id.event_handler(&id_priv->id, &event);
> +	ret = cma_cm_event_handler(id_priv, &event);
>  out:
>  	mutex_unlock(&id_priv->handler_mutex);
>  	return ret;
> diff --git a/drivers/infiniband/core/cma_trace.c b/drivers/infiniband/core/cma_trace.c
> new file mode 100644
> index 000000000000..1093fa813bc1
> --- /dev/null
> +++ b/drivers/infiniband/core/cma_trace.c
> @@ -0,0 +1,16 @@
> +// SPDX-License-Identifier: GPL-2.0-only
> +/*
> + * Trace points for the RDMA Connection Manager.
> + *
> + * Author: Chuck Lever <chuck.lever@oracle.com>
> + *
> + * Copyright (c) 2019, Oracle and/or its affiliates. All rights reserved.
> + */
> +
> +#define CREATE_TRACE_POINTS
> +
> +#include <rdma/rdma_cm.h>
> +#include <rdma/ib_cm.h>
> +#include "cma_priv.h"
> +
> +#include <trace/events/rdma_cma.h>
> diff --git a/include/trace/events/rdma_cma.h b/include/trace/events/rdma_cma.h
> new file mode 100644
> index 000000000000..b6ccdade651c
> --- /dev/null
> +++ b/include/trace/events/rdma_cma.h
> @@ -0,0 +1,218 @@
> +/* SPDX-License-Identifier: GPL-2.0-only */
> +/*
> + * Trace point definitions for the RDMA Connect Manager.
> + *
> + * Author: Chuck Lever <chuck.lever@oracle.com>
> + *
> + * Copyright (c) 2019, Oracle and/or its affiliates. All rights reserved.
> + */
> +
> +#undef TRACE_SYSTEM
> +#define TRACE_SYSTEM rdma_cma
> +
> +#if !defined(_TRACE_RDMA_CMA_H) || defined(TRACE_HEADER_MULTI_READ)
> +
> +#define _TRACE_RDMA_CMA_H
> +
> +#include <linux/tracepoint.h>
> +#include <rdma/rdma_cm.h>
> +#include "cma_priv.h"

Did it compile?
cma_priv.h is located in drivers/infiniband/core/ and unlikely to be
accessible from "include/trace/events/rdma_cma.h" file.

BTW, can you please add example of trace output to your commit message?
It will help users to understand immediately what they are expected to
see after this series is applied.

Thanks

RE: [PATCH v6 2/2] RDMA/cma: Add trace points in RDMA Connection Manager

[Zengtao (B)]

> -----Original Message-----
> From: linux-rdma-owner@vger.kernel.org
> [mailto:linux-rdma-owner@vger.kernel.org] On Behalf Of Leon Romanovsky
> Sent: Tuesday, November 19, 2019 3:45 PM
> To: Chuck Lever
> Cc: linux-rdma@vger.kernel.org
> Subject: Re: [PATCH v6 2/2] RDMA/cma: Add trace points in RDMA Connection
> Manager
> 
> On Mon, Nov 18, 2019 at 04:49:15PM -0500, Chuck Lever wrote:
> > Record state transitions as each connection is established. The IP
> > address of both peers and the Type of Service is reported. These
> > new trace points are not in performance hot paths.
> >
> > Also, record each cm_event_handler call to ULPs. This eliminates the
> > need for each ULP to add its own similar trace point in its CM event
> > handler function.
> >
> > These new trace points appear in a new trace subsystem called
> > "rdma_cma".
> >
> > This patch is based on previous work by:
> >
> > Saeed Mahameed <saeedm@mellanox.com>
> > Mukesh Kacker <mukesh.kacker@oracle.com>
> > Ajaykumar Hotchandani <ajaykumar.hotchandani@oracle.com>
> > Aron Silverton <aron.silverton@oracle.com>
> > Avinash Repaka <avinash.repaka@oracle.com>
> > Somasundaram Krishnasamy <somasundaram.krishnasamy@oracle.com>
> >
> > Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
> > ---
> >  drivers/infiniband/core/Makefile    |    2
> >  drivers/infiniband/core/cma.c       |   60 +++++++---
> >  drivers/infiniband/core/cma_trace.c |   16 +++
> >  include/trace/events/rdma_cma.h     |  218
> +++++++++++++++++++++++++++++++++++
> >  4 files changed, 279 insertions(+), 17 deletions(-)
> >  create mode 100644 drivers/infiniband/core/cma_trace.c
> >  create mode 100644 include/trace/events/rdma_cma.h
> >
> > diff --git a/drivers/infiniband/core/Makefile
> b/drivers/infiniband/core/Makefile
> > index 68d9e27c3c61..bab7b6f01982 100644
> > --- a/drivers/infiniband/core/Makefile
> > +++ b/drivers/infiniband/core/Makefile
> > @@ -20,7 +20,7 @@ ib_cm-y :=			cm.o
> >
> >  iw_cm-y :=			iwcm.o iwpm_util.o iwpm_msg.o
> >
> > -rdma_cm-y :=			cma.o
> > +rdma_cm-y :=			cma.o cma_trace.o
> >
> >  rdma_cm-$(CONFIG_INFINIBAND_ADDR_TRANS_CONFIGFS) +=
> cma_configfs.o
> >
> > diff --git a/drivers/infiniband/core/cma.c b/drivers/infiniband/core/cma.c
> > index d78f67623f24..5d5e63336954 100644
> > --- a/drivers/infiniband/core/cma.c
> > +++ b/drivers/infiniband/core/cma.c
> > @@ -64,6 +64,8 @@
> >  #include "core_priv.h"
> >  #include "cma_priv.h"
> >
> > +#include <trace/events/rdma_cma.h>
> > +
> >  MODULE_AUTHOR("Sean Hefty");
> >  MODULE_DESCRIPTION("Generic RDMA CM Agent");
> >  MODULE_LICENSE("Dual BSD/GPL");
> > @@ -1890,6 +1892,7 @@ static int cma_rep_recv(struct rdma_id_private
> *id_priv)
> >  	if (ret)
> >  		goto reject;
> >
> > +	trace_cm_send_rtu(id_priv);
> >  	ret = ib_send_cm_rtu(id_priv->cm_id.ib, NULL, 0);
> >  	if (ret)
> >  		goto reject;
> > @@ -1898,6 +1901,7 @@ static int cma_rep_recv(struct rdma_id_private
> *id_priv)
> >  reject:
> >  	pr_debug_ratelimited("RDMA CM: CONNECT_ERROR: failed to handle
> reply. status %d\n", ret);
> >  	cma_modify_qp_err(id_priv);
> > +	trace_cm_send_rej(id_priv);
> >  	ib_send_cm_rej(id_priv->cm_id.ib, IB_CM_REJ_CONSUMER_DEFINED,
> >  		       NULL, 0, NULL, 0);
> >  	return ret;
> > @@ -1917,6 +1921,13 @@ static void cma_set_rep_event_data(struct
> rdma_cm_event *event,
> >  	event->param.conn.qp_num = rep_data->remote_qpn;
> >  }
> >
> > +static int cma_cm_event_handler(struct rdma_id_private *id_priv,
> > +				struct rdma_cm_event *event)
> > +{
> > +	trace_cm_event_handler(id_priv, event);
> > +	return id_priv->id.event_handler(&id_priv->id, event);
> > +}
> > +
> >  static int cma_ib_handler(struct ib_cm_id *cm_id,
> >  			  const struct ib_cm_event *ib_event)
> >  {
> > @@ -1939,8 +1950,10 @@ static int cma_ib_handler(struct ib_cm_id
> *cm_id,
> >  		break;
> >  	case IB_CM_REP_RECEIVED:
> >  		if (cma_comp(id_priv, RDMA_CM_CONNECT) &&
> > -		    (id_priv->id.qp_type != IB_QPT_UD))
> > +		    (id_priv->id.qp_type != IB_QPT_UD)) {
> > +			trace_cm_send_mra(id_priv);
> >  			ib_send_cm_mra(cm_id, CMA_CM_MRA_SETTING, NULL, 0);
> > +		}
> >  		if (id_priv->id.qp) {
> >  			event.status = cma_rep_recv(id_priv);
> >  			event.event = event.status ?
> RDMA_CM_EVENT_CONNECT_ERROR :
> > @@ -1985,7 +1998,7 @@ static int cma_ib_handler(struct ib_cm_id *cm_id,
> >  		goto out;
> >  	}
> >
> > -	ret = id_priv->id.event_handler(&id_priv->id, &event);
> > +	ret = cma_cm_event_handler(id_priv, &event);
> >  	if (ret) {
> >  		/* Destroy the CM ID by returning a non-zero value. */
> >  		id_priv->cm_id.ib = NULL;
> > @@ -2146,6 +2159,7 @@ static int cma_ib_req_handler(struct ib_cm_id
> *cm_id,
> >  	if (IS_ERR(listen_id))
> >  		return PTR_ERR(listen_id);
> >
> > +	trace_cm_req_handler(listen_id, ib_event->event);
> >  	if (!cma_ib_check_req_qp_type(&listen_id->id, ib_event)) {
> >  		ret = -EINVAL;
> >  		goto net_dev_put;
> > @@ -2188,7 +2202,7 @@ static int cma_ib_req_handler(struct ib_cm_id
> *cm_id,
> >  	 * until we're done accessing it.
> >  	 */
> >  	atomic_inc(&conn_id->refcount);
> > -	ret = conn_id->id.event_handler(&conn_id->id, &event);
> > +	ret = cma_cm_event_handler(conn_id, &event);
> >  	if (ret)
> >  		goto err3;
> >  	/*
> > @@ -2197,8 +2211,10 @@ static int cma_ib_req_handler(struct ib_cm_id
> *cm_id,
> >  	 */
> >  	mutex_lock(&lock);
> >  	if (cma_comp(conn_id, RDMA_CM_CONNECT) &&
> > -	    (conn_id->id.qp_type != IB_QPT_UD))
> > +	    (conn_id->id.qp_type != IB_QPT_UD)) {
> > +		trace_cm_send_mra(cm_id->context);
> >  		ib_send_cm_mra(cm_id, CMA_CM_MRA_SETTING, NULL, 0);
> > +	}
> >  	mutex_unlock(&lock);
> >  	mutex_unlock(&conn_id->handler_mutex);
> >  	mutex_unlock(&listen_id->handler_mutex);
> > @@ -2313,7 +2329,7 @@ static int cma_iw_handler(struct iw_cm_id *iw_id,
> struct iw_cm_event *iw_event)
> >  	event.status = iw_event->status;
> >  	event.param.conn.private_data = iw_event->private_data;
> >  	event.param.conn.private_data_len = iw_event->private_data_len;
> > -	ret = id_priv->id.event_handler(&id_priv->id, &event);
> > +	ret = cma_cm_event_handler(id_priv, &event);
> >  	if (ret) {
> >  		/* Destroy the CM ID by returning a non-zero value. */
> >  		id_priv->cm_id.iw = NULL;
> > @@ -2390,7 +2406,7 @@ static int iw_conn_req_handler(struct iw_cm_id
> *cm_id,
> >  	 * until we're done accessing it.
> >  	 */
> >  	atomic_inc(&conn_id->refcount);
> > -	ret = conn_id->id.event_handler(&conn_id->id, &event);
> > +	ret = cma_cm_event_handler(conn_id, &event);
> >  	if (ret) {
> >  		/* User wants to destroy the CM ID */
> >  		conn_id->cm_id.iw = NULL;
> > @@ -2462,6 +2478,7 @@ static int cma_listen_handler(struct rdma_cm_id
> *id,
> >
> >  	id->context = id_priv->id.context;
> >  	id->event_handler = id_priv->id.event_handler;
> > +	trace_cm_event_handler(id_priv, event);
> >  	return id_priv->id.event_handler(id, event);
> >  }
> >
> > @@ -2636,7 +2653,7 @@ static void cma_work_handler(struct work_struct
> *_work)
> >  	if (!cma_comp_exch(id_priv, work->old_state, work->new_state))
> >  		goto out;
> >
> > -	if (id_priv->id.event_handler(&id_priv->id, &work->event)) {
> > +	if (cma_cm_event_handler(id_priv, &work->event)) {
> >  		cma_exch(id_priv, RDMA_CM_DESTROYING);
> >  		destroy = 1;
> >  	}
> > @@ -2659,7 +2676,7 @@ static void cma_ndev_work_handler(struct
> work_struct *_work)
> >  	    id_priv->state == RDMA_CM_DEVICE_REMOVAL)
> >  		goto out;
> >
> > -	if (id_priv->id.event_handler(&id_priv->id, &work->event)) {
> > +	if (cma_cm_event_handler(id_priv, &work->event)) {
> >  		cma_exch(id_priv, RDMA_CM_DESTROYING);
> >  		destroy = 1;
> >  	}
> > @@ -3062,7 +3079,7 @@ static void addr_handler(int status, struct
> sockaddr *src_addr,
> >  	} else
> >  		event.event = RDMA_CM_EVENT_ADDR_RESOLVED;
> >
> > -	if (id_priv->id.event_handler(&id_priv->id, &event)) {
> > +	if (cma_cm_event_handler(id_priv, &event)) {
> >  		cma_exch(id_priv, RDMA_CM_DESTROYING);
> >  		mutex_unlock(&id_priv->handler_mutex);
> >  		rdma_destroy_id(&id_priv->id);
> > @@ -3709,7 +3726,7 @@ static int cma_sidr_rep_handler(struct ib_cm_id
> *cm_id,
> >  		goto out;
> >  	}
> >
> > -	ret = id_priv->id.event_handler(&id_priv->id, &event);
> > +	ret = cma_cm_event_handler(id_priv, &event);
> >
> >  	rdma_destroy_ah_attr(&event.param.ud.ah_attr);
> >  	if (ret) {
> > @@ -3773,6 +3790,7 @@ static int cma_resolve_ib_udp(struct
> rdma_id_private *id_priv,
> >  	req.timeout_ms = 1 << (CMA_CM_RESPONSE_TIMEOUT - 8);
> >  	req.max_cm_retries = CMA_MAX_CM_RETRIES;
> >
> > +	trace_cm_send_sidr_req(id_priv);
> >  	ret = ib_send_cm_sidr_req(id_priv->cm_id.ib, &req);
> >  	if (ret) {
> >  		ib_destroy_cm_id(id_priv->cm_id.ib);
> > @@ -3846,6 +3864,7 @@ static int cma_connect_ib(struct rdma_id_private
> *id_priv,
> >  	req.max_cm_retries = CMA_MAX_CM_RETRIES;
> >  	req.srq = id_priv->srq ? 1 : 0;
> >
> > +	trace_cm_send_req(id_priv);
> >  	ret = ib_send_cm_req(id_priv->cm_id.ib, &req);
> >  out:
> >  	if (ret && !IS_ERR(id)) {
> > @@ -3959,6 +3978,7 @@ static int cma_accept_ib(struct rdma_id_private
> *id_priv,
> >  	rep.rnr_retry_count = min_t(u8, 7, conn_param->rnr_retry_count);
> >  	rep.srq = id_priv->srq ? 1 : 0;
> >
> > +	trace_cm_send_rep(id_priv);
> >  	ret = ib_send_cm_rep(id_priv->cm_id.ib, &rep);
> >  out:
> >  	return ret;
> > @@ -4008,6 +4028,7 @@ static int cma_send_sidr_rep(struct
> rdma_id_private *id_priv,
> >  	rep.private_data = private_data;
> >  	rep.private_data_len = private_data_len;
> >
> > +	trace_cm_send_sidr_rep(id_priv);
> >  	return ib_send_cm_sidr_rep(id_priv->cm_id.ib, &rep);
> >  }
> >
> > @@ -4093,13 +4114,15 @@ int rdma_reject(struct rdma_cm_id *id, const
> void *private_data,
> >  		return -EINVAL;
> >
> >  	if (rdma_cap_ib_cm(id->device, id->port_num)) {
> > -		if (id->qp_type == IB_QPT_UD)
> > +		if (id->qp_type == IB_QPT_UD) {
> >  			ret = cma_send_sidr_rep(id_priv, IB_SIDR_REJECT, 0,
> >  						private_data, private_data_len);
> > -		else
> > +		} else {
> > +			trace_cm_send_rej(id_priv);
> >  			ret = ib_send_cm_rej(id_priv->cm_id.ib,
> >  					     IB_CM_REJ_CONSUMER_DEFINED, NULL,
> >  					     0, private_data, private_data_len);
> > +		}
> >  	} else if (rdma_cap_iw_cm(id->device, id->port_num)) {
> >  		ret = iw_cm_reject(id_priv->cm_id.iw,
> >  				   private_data, private_data_len);
> > @@ -4124,8 +4147,13 @@ int rdma_disconnect(struct rdma_cm_id *id)
> >  		if (ret)
> >  			goto out;
> >  		/* Initiate or respond to a disconnect. */
> > -		if (ib_send_cm_dreq(id_priv->cm_id.ib, NULL, 0))
> > -			ib_send_cm_drep(id_priv->cm_id.ib, NULL, 0);
> > +		trace_cm_disconnect(id_priv);
> > +		if (ib_send_cm_dreq(id_priv->cm_id.ib, NULL, 0)) {
> > +			if (!ib_send_cm_drep(id_priv->cm_id.ib, NULL, 0))
> > +				trace_cm_sent_drep(id_priv);
> > +		} else {
> > +			trace_cm_sent_dreq(id_priv);
> > +		}
> >  	} else if (rdma_cap_iw_cm(id->device, id->port_num)) {
> >  		ret = iw_cm_disconnect(id_priv->cm_id.iw, 0);
> >  	} else
> > @@ -4191,7 +4219,7 @@ static int cma_ib_mc_handler(int status, struct
> ib_sa_multicast *multicast)
> >  	} else
> >  		event.event = RDMA_CM_EVENT_MULTICAST_ERROR;
> >
> > -	ret = id_priv->id.event_handler(&id_priv->id, &event);
> > +	ret = cma_cm_event_handler(id_priv, &event);
> >
> >  	rdma_destroy_ah_attr(&event.param.ud.ah_attr);
> >  	if (ret) {
> > @@ -4626,7 +4654,7 @@ static int cma_remove_id_dev(struct
> rdma_id_private *id_priv)
> >  		goto out;
> >
> >  	event.event = RDMA_CM_EVENT_DEVICE_REMOVAL;
> > -	ret = id_priv->id.event_handler(&id_priv->id, &event);
> > +	ret = cma_cm_event_handler(id_priv, &event);
> >  out:
> >  	mutex_unlock(&id_priv->handler_mutex);
> >  	return ret;
> > diff --git a/drivers/infiniband/core/cma_trace.c
> b/drivers/infiniband/core/cma_trace.c
> > new file mode 100644
> > index 000000000000..1093fa813bc1
> > --- /dev/null
> > +++ b/drivers/infiniband/core/cma_trace.c
> > @@ -0,0 +1,16 @@
> > +// SPDX-License-Identifier: GPL-2.0-only
> > +/*
> > + * Trace points for the RDMA Connection Manager.
> > + *
> > + * Author: Chuck Lever <chuck.lever@oracle.com>
> > + *
> > + * Copyright (c) 2019, Oracle and/or its affiliates. All rights reserved.
> > + */
> > +
> > +#define CREATE_TRACE_POINTS
> > +
> > +#include <rdma/rdma_cm.h>
> > +#include <rdma/ib_cm.h>
> > +#include "cma_priv.h"
> > +
> > +#include <trace/events/rdma_cma.h>
> > diff --git a/include/trace/events/rdma_cma.h
> b/include/trace/events/rdma_cma.h
> > new file mode 100644
> > index 000000000000..b6ccdade651c
> > --- /dev/null
> > +++ b/include/trace/events/rdma_cma.h
> > @@ -0,0 +1,218 @@
> > +/* SPDX-License-Identifier: GPL-2.0-only */
> > +/*
> > + * Trace point definitions for the RDMA Connect Manager.
> > + *
> > + * Author: Chuck Lever <chuck.lever@oracle.com>
> > + *
> > + * Copyright (c) 2019, Oracle and/or its affiliates. All rights reserved.
> > + */
> > +
> > +#undef TRACE_SYSTEM
> > +#define TRACE_SYSTEM rdma_cma
> > +
> > +#if !defined(_TRACE_RDMA_CMA_H) ||
> defined(TRACE_HEADER_MULTI_READ)
> > +
> > +#define _TRACE_RDMA_CMA_H
> > +
> > +#include <linux/tracepoint.h>
> > +#include <rdma/rdma_cm.h>
> > +#include "cma_priv.h"
> 
> Did it compile?
> cma_priv.h is located in drivers/infiniband/core/ and unlikely to be
> accessible from "include/trace/events/rdma_cma.h" file.
> 
Exactly , I have applied this patch and compile failed, and it seems
that just simply remove "#cma_priv.h" works.

> BTW, can you please add example of trace output to your commit message?
> It will help users to understand immediately what they are expected to
> see after this series is applied.
> 
> Thanks

Re: [PATCH v6 2/2] RDMA/cma: Add trace points in RDMA Connection Manager

[Chuck Lever]

> On Nov 19, 2019, at 2:45 AM, Leon Romanovsky <leon@kernel.org> wrote:
> 
> On Mon, Nov 18, 2019 at 04:49:15PM -0500, Chuck Lever wrote:
>> Record state transitions as each connection is established. The IP
>> address of both peers and the Type of Service is reported. These
>> new trace points are not in performance hot paths.
>> 
>> Also, record each cm_event_handler call to ULPs. This eliminates the
>> need for each ULP to add its own similar trace point in its CM event
>> handler function.
>> 
>> These new trace points appear in a new trace subsystem called
>> "rdma_cma".
>> 
>> This patch is based on previous work by:
>> 
>> Saeed Mahameed <saeedm@mellanox.com>
>> Mukesh Kacker <mukesh.kacker@oracle.com>
>> Ajaykumar Hotchandani <ajaykumar.hotchandani@oracle.com>
>> Aron Silverton <aron.silverton@oracle.com>
>> Avinash Repaka <avinash.repaka@oracle.com>
>> Somasundaram Krishnasamy <somasundaram.krishnasamy@oracle.com>
>> 
>> Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
>> ---
>> drivers/infiniband/core/Makefile    |    2
>> drivers/infiniband/core/cma.c       |   60 +++++++---
>> drivers/infiniband/core/cma_trace.c |   16 +++
>> include/trace/events/rdma_cma.h     |  218 +++++++++++++++++++++++++++++++++++
>> 4 files changed, 279 insertions(+), 17 deletions(-)
>> create mode 100644 drivers/infiniband/core/cma_trace.c
>> create mode 100644 include/trace/events/rdma_cma.h
>> 
>> diff --git a/drivers/infiniband/core/Makefile b/drivers/infiniband/core/Makefile
>> index 68d9e27c3c61..bab7b6f01982 100644
>> --- a/drivers/infiniband/core/Makefile
>> +++ b/drivers/infiniband/core/Makefile
>> @@ -20,7 +20,7 @@ ib_cm-y :=            cm.o
>> 
>> iw_cm-y :=            iwcm.o iwpm_util.o iwpm_msg.o
>> 
>> -rdma_cm-y :=            cma.o
>> +rdma_cm-y :=            cma.o cma_trace.o
>> 
>> rdma_cm-$(CONFIG_INFINIBAND_ADDR_TRANS_CONFIGFS) += cma_configfs.o
>> 
>> diff --git a/drivers/infiniband/core/cma.c b/drivers/infiniband/core/cma.c
>> index d78f67623f24..5d5e63336954 100644
>> --- a/drivers/infiniband/core/cma.c
>> +++ b/drivers/infiniband/core/cma.c
>> @@ -64,6 +64,8 @@
>> #include "core_priv.h"
>> #include "cma_priv.h"
>> 
>> +#include <trace/events/rdma_cma.h>
>> +
>> MODULE_AUTHOR("Sean Hefty");
>> MODULE_DESCRIPTION("Generic RDMA CM Agent");
>> MODULE_LICENSE("Dual BSD/GPL");
>> @@ -1890,6 +1892,7 @@ static int cma_rep_recv(struct rdma_id_private *id_priv)
>>    if (ret)
>>        goto reject;
>> 
>> +    trace_cm_send_rtu(id_priv);
>>    ret = ib_send_cm_rtu(id_priv->cm_id.ib, NULL, 0);
>>    if (ret)
>>        goto reject;
>> @@ -1898,6 +1901,7 @@ static int cma_rep_recv(struct rdma_id_private *id_priv)
>> reject:
>>    pr_debug_ratelimited("RDMA CM: CONNECT_ERROR: failed to handle reply. status %d\n", ret);
>>    cma_modify_qp_err(id_priv);
>> +    trace_cm_send_rej(id_priv);
>>    ib_send_cm_rej(id_priv->cm_id.ib, IB_CM_REJ_CONSUMER_DEFINED,
>>               NULL, 0, NULL, 0);
>>    return ret;
>> @@ -1917,6 +1921,13 @@ static void cma_set_rep_event_data(struct rdma_cm_event *event,
>>    event->param.conn.qp_num = rep_data->remote_qpn;
>> }
>> 
>> +static int cma_cm_event_handler(struct rdma_id_private *id_priv,
>> +                struct rdma_cm_event *event)
>> +{
>> +    trace_cm_event_handler(id_priv, event);
>> +    return id_priv->id.event_handler(&id_priv->id, event);
>> +}
>> +
>> static int cma_ib_handler(struct ib_cm_id *cm_id,
>>              const struct ib_cm_event *ib_event)
>> {
>> @@ -1939,8 +1950,10 @@ static int cma_ib_handler(struct ib_cm_id *cm_id,
>>        break;
>>    case IB_CM_REP_RECEIVED:
>>        if (cma_comp(id_priv, RDMA_CM_CONNECT) &&
>> -            (id_priv->id.qp_type != IB_QPT_UD))
>> +            (id_priv->id.qp_type != IB_QPT_UD)) {
>> +            trace_cm_send_mra(id_priv);
>>            ib_send_cm_mra(cm_id, CMA_CM_MRA_SETTING, NULL, 0);
>> +        }
>>        if (id_priv->id.qp) {
>>            event.status = cma_rep_recv(id_priv);
>>            event.event = event.status ? RDMA_CM_EVENT_CONNECT_ERROR :
>> @@ -1985,7 +1998,7 @@ static int cma_ib_handler(struct ib_cm_id *cm_id,
>>        goto out;
>>    }
>> 
>> -    ret = id_priv->id.event_handler(&id_priv->id, &event);
>> +    ret = cma_cm_event_handler(id_priv, &event);
>>    if (ret) {
>>        /* Destroy the CM ID by returning a non-zero value. */
>>        id_priv->cm_id.ib = NULL;
>> @@ -2146,6 +2159,7 @@ static int cma_ib_req_handler(struct ib_cm_id *cm_id,
>>    if (IS_ERR(listen_id))
>>        return PTR_ERR(listen_id);
>> 
>> +    trace_cm_req_handler(listen_id, ib_event->event);
>>    if (!cma_ib_check_req_qp_type(&listen_id->id, ib_event)) {
>>        ret = -EINVAL;
>>        goto net_dev_put;
>> @@ -2188,7 +2202,7 @@ static int cma_ib_req_handler(struct ib_cm_id *cm_id,
>>     * until we're done accessing it.
>>     */
>>    atomic_inc(&conn_id->refcount);
>> -    ret = conn_id->id.event_handler(&conn_id->id, &event);
>> +    ret = cma_cm_event_handler(conn_id, &event);
>>    if (ret)
>>        goto err3;
>>    /*
>> @@ -2197,8 +2211,10 @@ static int cma_ib_req_handler(struct ib_cm_id *cm_id,
>>     */
>>    mutex_lock(&lock);
>>    if (cma_comp(conn_id, RDMA_CM_CONNECT) &&
>> -        (conn_id->id.qp_type != IB_QPT_UD))
>> +        (conn_id->id.qp_type != IB_QPT_UD)) {
>> +        trace_cm_send_mra(cm_id->context);
>>        ib_send_cm_mra(cm_id, CMA_CM_MRA_SETTING, NULL, 0);
>> +    }
>>    mutex_unlock(&lock);
>>    mutex_unlock(&conn_id->handler_mutex);
>>    mutex_unlock(&listen_id->handler_mutex);
>> @@ -2313,7 +2329,7 @@ static int cma_iw_handler(struct iw_cm_id *iw_id, struct iw_cm_event *iw_event)
>>    event.status = iw_event->status;
>>    event.param.conn.private_data = iw_event->private_data;
>>    event.param.conn.private_data_len = iw_event->private_data_len;
>> -    ret = id_priv->id.event_handler(&id_priv->id, &event);
>> +    ret = cma_cm_event_handler(id_priv, &event);
>>    if (ret) {
>>        /* Destroy the CM ID by returning a non-zero value. */
>>        id_priv->cm_id.iw = NULL;
>> @@ -2390,7 +2406,7 @@ static int iw_conn_req_handler(struct iw_cm_id *cm_id,
>>     * until we're done accessing it.
>>     */
>>    atomic_inc(&conn_id->refcount);
>> -    ret = conn_id->id.event_handler(&conn_id->id, &event);
>> +    ret = cma_cm_event_handler(conn_id, &event);
>>    if (ret) {
>>        /* User wants to destroy the CM ID */
>>        conn_id->cm_id.iw = NULL;
>> @@ -2462,6 +2478,7 @@ static int cma_listen_handler(struct rdma_cm_id *id,
>> 
>>    id->context = id_priv->id.context;
>>    id->event_handler = id_priv->id.event_handler;
>> +    trace_cm_event_handler(id_priv, event);
>>    return id_priv->id.event_handler(id, event);
>> }
>> 
>> @@ -2636,7 +2653,7 @@ static void cma_work_handler(struct work_struct *_work)
>>    if (!cma_comp_exch(id_priv, work->old_state, work->new_state))
>>        goto out;
>> 
>> -    if (id_priv->id.event_handler(&id_priv->id, &work->event)) {
>> +    if (cma_cm_event_handler(id_priv, &work->event)) {
>>        cma_exch(id_priv, RDMA_CM_DESTROYING);
>>        destroy = 1;
>>    }
>> @@ -2659,7 +2676,7 @@ static void cma_ndev_work_handler(struct work_struct *_work)
>>        id_priv->state == RDMA_CM_DEVICE_REMOVAL)
>>        goto out;
>> 
>> -    if (id_priv->id.event_handler(&id_priv->id, &work->event)) {
>> +    if (cma_cm_event_handler(id_priv, &work->event)) {
>>        cma_exch(id_priv, RDMA_CM_DESTROYING);
>>        destroy = 1;
>>    }
>> @@ -3062,7 +3079,7 @@ static void addr_handler(int status, struct sockaddr *src_addr,
>>    } else
>>        event.event = RDMA_CM_EVENT_ADDR_RESOLVED;
>> 
>> -    if (id_priv->id.event_handler(&id_priv->id, &event)) {
>> +    if (cma_cm_event_handler(id_priv, &event)) {
>>        cma_exch(id_priv, RDMA_CM_DESTROYING);
>>        mutex_unlock(&id_priv->handler_mutex);
>>        rdma_destroy_id(&id_priv->id);
>> @@ -3709,7 +3726,7 @@ static int cma_sidr_rep_handler(struct ib_cm_id *cm_id,
>>        goto out;
>>    }
>> 
>> -    ret = id_priv->id.event_handler(&id_priv->id, &event);
>> +    ret = cma_cm_event_handler(id_priv, &event);
>> 
>>    rdma_destroy_ah_attr(&event.param.ud.ah_attr);
>>    if (ret) {
>> @@ -3773,6 +3790,7 @@ static int cma_resolve_ib_udp(struct rdma_id_private *id_priv,
>>    req.timeout_ms = 1 << (CMA_CM_RESPONSE_TIMEOUT - 8);
>>    req.max_cm_retries = CMA_MAX_CM_RETRIES;
>> 
>> +    trace_cm_send_sidr_req(id_priv);
>>    ret = ib_send_cm_sidr_req(id_priv->cm_id.ib, &req);
>>    if (ret) {
>>        ib_destroy_cm_id(id_priv->cm_id.ib);
>> @@ -3846,6 +3864,7 @@ static int cma_connect_ib(struct rdma_id_private *id_priv,
>>    req.max_cm_retries = CMA_MAX_CM_RETRIES;
>>    req.srq = id_priv->srq ? 1 : 0;
>> 
>> +    trace_cm_send_req(id_priv);
>>    ret = ib_send_cm_req(id_priv->cm_id.ib, &req);
>> out:
>>    if (ret && !IS_ERR(id)) {
>> @@ -3959,6 +3978,7 @@ static int cma_accept_ib(struct rdma_id_private *id_priv,
>>    rep.rnr_retry_count = min_t(u8, 7, conn_param->rnr_retry_count);
>>    rep.srq = id_priv->srq ? 1 : 0;
>> 
>> +    trace_cm_send_rep(id_priv);
>>    ret = ib_send_cm_rep(id_priv->cm_id.ib, &rep);
>> out:
>>    return ret;
>> @@ -4008,6 +4028,7 @@ static int cma_send_sidr_rep(struct rdma_id_private *id_priv,
>>    rep.private_data = private_data;
>>    rep.private_data_len = private_data_len;
>> 
>> +    trace_cm_send_sidr_rep(id_priv);
>>    return ib_send_cm_sidr_rep(id_priv->cm_id.ib, &rep);
>> }
>> 
>> @@ -4093,13 +4114,15 @@ int rdma_reject(struct rdma_cm_id *id, const void *private_data,
>>        return -EINVAL;
>> 
>>    if (rdma_cap_ib_cm(id->device, id->port_num)) {
>> -        if (id->qp_type == IB_QPT_UD)
>> +        if (id->qp_type == IB_QPT_UD) {
>>            ret = cma_send_sidr_rep(id_priv, IB_SIDR_REJECT, 0,
>>                        private_data, private_data_len);
>> -        else
>> +        } else {
>> +            trace_cm_send_rej(id_priv);
>>            ret = ib_send_cm_rej(id_priv->cm_id.ib,
>>                         IB_CM_REJ_CONSUMER_DEFINED, NULL,
>>                         0, private_data, private_data_len);
>> +        }
>>    } else if (rdma_cap_iw_cm(id->device, id->port_num)) {
>>        ret = iw_cm_reject(id_priv->cm_id.iw,
>>                   private_data, private_data_len);
>> @@ -4124,8 +4147,13 @@ int rdma_disconnect(struct rdma_cm_id *id)
>>        if (ret)
>>            goto out;
>>        /* Initiate or respond to a disconnect. */
>> -        if (ib_send_cm_dreq(id_priv->cm_id.ib, NULL, 0))
>> -            ib_send_cm_drep(id_priv->cm_id.ib, NULL, 0);
>> +        trace_cm_disconnect(id_priv);
>> +        if (ib_send_cm_dreq(id_priv->cm_id.ib, NULL, 0)) {
>> +            if (!ib_send_cm_drep(id_priv->cm_id.ib, NULL, 0))
>> +                trace_cm_sent_drep(id_priv);
>> +        } else {
>> +            trace_cm_sent_dreq(id_priv);
>> +        }
>>    } else if (rdma_cap_iw_cm(id->device, id->port_num)) {
>>        ret = iw_cm_disconnect(id_priv->cm_id.iw, 0);
>>    } else
>> @@ -4191,7 +4219,7 @@ static int cma_ib_mc_handler(int status, struct ib_sa_multicast *multicast)
>>    } else
>>        event.event = RDMA_CM_EVENT_MULTICAST_ERROR;
>> 
>> -    ret = id_priv->id.event_handler(&id_priv->id, &event);
>> +    ret = cma_cm_event_handler(id_priv, &event);
>> 
>>    rdma_destroy_ah_attr(&event.param.ud.ah_attr);
>>    if (ret) {
>> @@ -4626,7 +4654,7 @@ static int cma_remove_id_dev(struct rdma_id_private *id_priv)
>>        goto out;
>> 
>>    event.event = RDMA_CM_EVENT_DEVICE_REMOVAL;
>> -    ret = id_priv->id.event_handler(&id_priv->id, &event);
>> +    ret = cma_cm_event_handler(id_priv, &event);
>> out:
>>    mutex_unlock(&id_priv->handler_mutex);
>>    return ret;
>> diff --git a/drivers/infiniband/core/cma_trace.c b/drivers/infiniband/core/cma_trace.c
>> new file mode 100644
>> index 000000000000..1093fa813bc1
>> --- /dev/null
>> +++ b/drivers/infiniband/core/cma_trace.c
>> @@ -0,0 +1,16 @@
>> +// SPDX-License-Identifier: GPL-2.0-only
>> +/*
>> + * Trace points for the RDMA Connection Manager.
>> + *
>> + * Author: Chuck Lever <chuck.lever@oracle.com>
>> + *
>> + * Copyright (c) 2019, Oracle and/or its affiliates. All rights reserved.
>> + */
>> +
>> +#define CREATE_TRACE_POINTS
>> +
>> +#include <rdma/rdma_cm.h>
>> +#include <rdma/ib_cm.h>
>> +#include "cma_priv.h"
>> +
>> +#include <trace/events/rdma_cma.h>
>> diff --git a/include/trace/events/rdma_cma.h b/include/trace/events/rdma_cma.h
>> new file mode 100644
>> index 000000000000..b6ccdade651c
>> --- /dev/null
>> +++ b/include/trace/events/rdma_cma.h
>> @@ -0,0 +1,218 @@
>> +/* SPDX-License-Identifier: GPL-2.0-only */
>> +/*
>> + * Trace point definitions for the RDMA Connect Manager.
>> + *
>> + * Author: Chuck Lever <chuck.lever@oracle.com>
>> + *
>> + * Copyright (c) 2019, Oracle and/or its affiliates. All rights reserved.
>> + */
>> +
>> +#undef TRACE_SYSTEM
>> +#define TRACE_SYSTEM rdma_cma
>> +
>> +#if !defined(_TRACE_RDMA_CMA_H) || defined(TRACE_HEADER_MULTI_READ)
>> +
>> +#define _TRACE_RDMA_CMA_H
>> +
>> +#include <linux/tracepoint.h>
>> +#include <rdma/rdma_cm.h>
>> +#include "cma_priv.h"
> 
> Did it compile?

Yes, it compiles for me, and passes lkp as well.

 I admit though that it seems like a brittle arrangement. Might be better off moving rdma_cma.h to drivers/infiniband/core/ .


> cma_priv.h is located in drivers/infiniband/core/ and unlikely to be
> accessible from "include/trace/events/rdma_cma.h" file.
> 
> BTW, can you please add example of trace output to your commit message?

Will do.

> It will help users to understand immediately what they are expected to
> see after this series is applied.
> 
> Thanks

Re: [PATCH v6 2/2] RDMA/cma: Add trace points in RDMA Connection Manager

[Jason Gunthorpe]

On Tue, Nov 19, 2019 at 07:10:03AM -0500, Chuck Lever wrote:
> >> diff --git a/include/trace/events/rdma_cma.h b/include/trace/events/rdma_cma.h
> >> new file mode 100644
> >> index 000000000000..b6ccdade651c
> >> +++ b/include/trace/events/rdma_cma.h
> >> @@ -0,0 +1,218 @@
> >> +/* SPDX-License-Identifier: GPL-2.0-only */
> >> +/*
> >> + * Trace point definitions for the RDMA Connect Manager.
> >> + *
> >> + * Author: Chuck Lever <chuck.lever@oracle.com>
> >> + *
> >> + * Copyright (c) 2019, Oracle and/or its affiliates. All rights reserved.
> >> + */
> >> +
> >> +#undef TRACE_SYSTEM
> >> +#define TRACE_SYSTEM rdma_cma
> >> +
> >> +#if !defined(_TRACE_RDMA_CMA_H) || defined(TRACE_HEADER_MULTI_READ)
> >> +
> >> +#define _TRACE_RDMA_CMA_H
> >> +
> >> +#include <linux/tracepoint.h>
> >> +#include <rdma/rdma_cm.h>
> >> +#include "cma_priv.h"
> > 
> > Did it compile?
> 
> Yes, it compiles for me, and passes lkp as well.
> 
>  I admit though that it seems like a brittle arrangement. Might be
>  better off moving rdma_cma.h to drivers/infiniband/core/ .

The more headers that can move out of include the better, IMHO

Jason

Re: [PATCH v6 1/2] RDMA/core: Trace points for diagnosing completion queue issues

[Jason Gunthorpe]

On Mon, Nov 18, 2019 at 04:49:09PM -0500, Chuck Lever wrote:
> @@ -65,11 +68,35 @@ static void rdma_dim_init(struct ib_cq *cq)
>  	INIT_WORK(&dim->work, ib_cq_rdma_dim_work);
>  }
>  
> +/**
> + * ib_poll_cq - poll a CQ for completion(s)
> + * @cq: the CQ being polled
> + * @num_entries: maximum number of completions to return
> + * @wc: array of at least @num_entries &struct ib_wc where completions
> + *      will be returned
> + *
> + * Poll a CQ for (possibly multiple) completions.  If the return value
> + * is < 0, an error occurred.  If the return value is >= 0, it is the
> + * number of completions returned.  If the return value is
> + * non-negative and < num_entries, then the CQ was emptied.
> + */
> +int ib_poll_cq(struct ib_cq *cq, int num_entries, struct ib_wc *wc)
> +{
> +	int rc;
> +
> +	rc = cq->device->ops.poll_cq(cq, num_entries, wc);
> +	trace_cq_poll(cq, num_entries, rc);
> +	return rc;
> +}
> +EXPORT_SYMBOL(ib_poll_cq);

Back to the non-inlined function?

Jason

Re: [PATCH v6 1/2] RDMA/core: Trace points for diagnosing completion queue issues

[Chuck Lever]

> On Nov 19, 2019, at 12:01 PM, Jason Gunthorpe <jgg@ziepe.ca> wrote:
> 
> On Mon, Nov 18, 2019 at 04:49:09PM -0500, Chuck Lever wrote:
>> @@ -65,11 +68,35 @@ static void rdma_dim_init(struct ib_cq *cq)
>> 	INIT_WORK(&dim->work, ib_cq_rdma_dim_work);
>> }
>> 
>> +/**
>> + * ib_poll_cq - poll a CQ for completion(s)
>> + * @cq: the CQ being polled
>> + * @num_entries: maximum number of completions to return
>> + * @wc: array of at least @num_entries &struct ib_wc where completions
>> + *      will be returned
>> + *
>> + * Poll a CQ for (possibly multiple) completions.  If the return value
>> + * is < 0, an error occurred.  If the return value is >= 0, it is the
>> + * number of completions returned.  If the return value is
>> + * non-negative and < num_entries, then the CQ was emptied.
>> + */
>> +int ib_poll_cq(struct ib_cq *cq, int num_entries, struct ib_wc *wc)
>> +{
>> +	int rc;
>> +
>> +	rc = cq->device->ops.poll_cq(cq, num_entries, wc);
>> +	trace_cq_poll(cq, num_entries, rc);
>> +	return rc;
>> +}
>> +EXPORT_SYMBOL(ib_poll_cq);
> 
> Back to the non-inlined function?

I never got a clear answer about your preference either way.

IMO making this into a non-inline function is necessary to support
either a static trace point here, or to have a place to put a
convenient dynamic trace point via eBPF. I don't believe it will
add noticeable overhead -- in particular, under heavy load, poll_cq
is invoked once every 16 completions.

On the other hand, it's not clear to me that the latency calculation
will work correctly with callers outside of cq.c ...

--
Chuck Lever