xprtrdma: Report the computed connect delay

For debugging, the op_connect trace point should report the computed
connect delay. We can then ensure that the delay is computed at the
proper times, for example.

As a further clean-up, remove a few low-value "heartbeat" trace
points in the connect path.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
Signed-off-by: Anna Schumaker <Anna.Schumaker@Netapp.com>

diff --git a/include/trace/events/rpcrdma.h b/include/trace/events/rpcrdma.h
index 213c72585a5fcb84ddc788382681696090f7c571..99e3c61609b2441c96c5392ce313cc3ebedc7dbb 100644 (file)
--- a/include/trace/events/rpcrdma.h
+++ b/include/trace/events/rpcrdma.h
@@ -85,6 +85,44 @@ DECLARE_EVENT_CLASS(xprtrdma_rxprt,
                                ),                                      \
                                TP_ARGS(r_xprt))
 
+DECLARE_EVENT_CLASS(xprtrdma_connect_class,
+       TP_PROTO(
+               const struct rpcrdma_xprt *r_xprt,
+               int rc
+       ),
+
+       TP_ARGS(r_xprt, rc),
+
+       TP_STRUCT__entry(
+               __field(const void *, r_xprt)
+               __field(int, rc)
+               __field(int, connect_status)
+               __string(addr, rpcrdma_addrstr(r_xprt))
+               __string(port, rpcrdma_portstr(r_xprt))
+       ),
+
+       TP_fast_assign(
+               __entry->r_xprt = r_xprt;
+               __entry->rc = rc;
+               __entry->connect_status = 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: rc=%d connect status=%d",
+               __get_str(addr), __get_str(port), __entry->r_xprt,
+               __entry->rc, __entry->connect_status
+       )
+);
+
+#define DEFINE_CONN_EVENT(name)                                                \
+               DEFINE_EVENT(xprtrdma_connect_class, xprtrdma_##name,   \
+                               TP_PROTO(                               \
+                                       const struct rpcrdma_xprt *r_xprt, \
+                                       int rc                          \
+                               ),                                      \
+                               TP_ARGS(r_xprt, rc))
+
 DECLARE_EVENT_CLASS(xprtrdma_rdch_event,
        TP_PROTO(
                const struct rpc_task *task,
@@ -333,47 +371,44 @@ TRACE_EVENT(xprtrdma_cm_event,
        )
 );
 
-TRACE_EVENT(xprtrdma_disconnect,
+DEFINE_CONN_EVENT(connect);
+DEFINE_CONN_EVENT(disconnect);
+
+DEFINE_RXPRT_EVENT(xprtrdma_create);
+DEFINE_RXPRT_EVENT(xprtrdma_op_destroy);
+DEFINE_RXPRT_EVENT(xprtrdma_remove);
+DEFINE_RXPRT_EVENT(xprtrdma_reinsert);
+DEFINE_RXPRT_EVENT(xprtrdma_op_inject_dsc);
+DEFINE_RXPRT_EVENT(xprtrdma_op_close);
+
+TRACE_EVENT(xprtrdma_op_connect,
        TP_PROTO(
                const struct rpcrdma_xprt *r_xprt,
-               int status
+               unsigned long delay
        ),
 
-       TP_ARGS(r_xprt, status),
+       TP_ARGS(r_xprt, delay),
 
        TP_STRUCT__entry(
                __field(const void *, r_xprt)
-               __field(int, status)
-               __field(int, connected)
+               __field(unsigned long, delay)
                __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;
+               __entry->delay = delay;
                __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"
+       TP_printk("peer=[%s]:%s r_xprt=%p delay=%lu",
+               __get_str(addr), __get_str(port), __entry->r_xprt,
+               __entry->delay
        )
 );
 
-DEFINE_RXPRT_EVENT(xprtrdma_conn_start);
-DEFINE_RXPRT_EVENT(xprtrdma_conn_tout);
-DEFINE_RXPRT_EVENT(xprtrdma_create);
-DEFINE_RXPRT_EVENT(xprtrdma_op_destroy);
-DEFINE_RXPRT_EVENT(xprtrdma_remove);
-DEFINE_RXPRT_EVENT(xprtrdma_reinsert);
-DEFINE_RXPRT_EVENT(xprtrdma_reconnect);
-DEFINE_RXPRT_EVENT(xprtrdma_op_inject_dsc);
-DEFINE_RXPRT_EVENT(xprtrdma_op_close);
-DEFINE_RXPRT_EVENT(xprtrdma_op_connect);
 
 TRACE_EVENT(xprtrdma_op_set_cto,
        TP_PROTO(

diff --git a/net/sunrpc/xprtrdma/transport.c b/net/sunrpc/xprtrdma/transport.c
index 361e59146807f2d8fdf69fba05757726c03c27c9..ce263e6f779c4f2ee236f7a46cb7e59e4a74c85e 100644 (file)
--- a/net/sunrpc/xprtrdma/transport.c
+++ b/net/sunrpc/xprtrdma/transport.c
@@ -527,13 +527,12 @@ xprt_rdma_connect(struct rpc_xprt *xprt, struct rpc_task *task)
        struct rpcrdma_xprt *r_xprt = rpcx_to_rdmax(xprt);
        unsigned long delay;
 
-       trace_xprtrdma_op_connect(r_xprt);
-
        delay = 0;
        if (r_xprt->rx_ep.rep_connected != 0) {
                delay = xprt_reconnect_delay(xprt);
                xprt_reconnect_backoff(xprt, RPCRDMA_INIT_REEST_TO);
        }
+       trace_xprtrdma_op_connect(r_xprt, delay);
        queue_delayed_work(xprtiod_workqueue, &r_xprt->rx_connect_worker,
                           delay);
 }

diff --git a/net/sunrpc/xprtrdma/verbs.c b/net/sunrpc/xprtrdma/verbs.c
index a514e2c89ac342053fae2181a4481bdade0132d6..92bdf053716aae74a34b2bc0079cb70ae47b1197 100644 (file)
--- a/net/sunrpc/xprtrdma/verbs.c
+++ b/net/sunrpc/xprtrdma/verbs.c
@@ -297,8 +297,6 @@ rpcrdma_create_id(struct rpcrdma_xprt *xprt, struct rpcrdma_ia *ia)
        struct rdma_cm_id *id;
        int rc;
 
-       trace_xprtrdma_conn_start(xprt);
-
        init_completion(&ia->ri_done);
        init_completion(&ia->ri_remove_done);
 
@@ -314,10 +312,8 @@ rpcrdma_create_id(struct rpcrdma_xprt *xprt, struct rpcrdma_ia *ia)
        if (rc)
                goto out;
        rc = wait_for_completion_interruptible_timeout(&ia->ri_done, wtimeout);
-       if (rc < 0) {
-               trace_xprtrdma_conn_tout(xprt);
+       if (rc < 0)
                goto out;
-       }
 
        rc = ia->ri_async_rc;
        if (rc)
@@ -328,10 +324,8 @@ rpcrdma_create_id(struct rpcrdma_xprt *xprt, struct rpcrdma_ia *ia)
        if (rc)
                goto out;
        rc = wait_for_completion_interruptible_timeout(&ia->ri_done, wtimeout);
-       if (rc < 0) {
-               trace_xprtrdma_conn_tout(xprt);
+       if (rc < 0)
                goto out;
-       }
        rc = ia->ri_async_rc;
        if (rc)
                goto out;
@@ -644,8 +638,6 @@ static int rpcrdma_ep_reconnect(struct rpcrdma_xprt *r_xprt,
        struct rdma_cm_id *id, *old;
        int err, rc;
 
-       trace_xprtrdma_reconnect(r_xprt);
-
        rpcrdma_ep_disconnect(&r_xprt->rx_ep, ia);
 
        rc = -EHOSTUNREACH;
@@ -744,6 +736,7 @@ out:
                ep->rep_connected = rc;
 
 out_noupdate:
+       trace_xprtrdma_connect(r_xprt, rc);
        return rc;
 }