xprtrdma: Add trace points for connect events

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 d296d5b084c290d3feafcdf2481ed7a0ec737c97..023443d5a0bfb6b95661675fb92fbce42fd1520d 100644 (file)
--- a/include/trace/events/rpcrdma.h
+++ b/include/trace/events/rpcrdma.h
@@ -267,6 +267,81 @@ DECLARE_EVENT_CLASS(xprtrdma_mr,
                                ), \
                                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 ddf0d87812efcdd77a90a04903946e8c5e4bd980..25d1160dc0850558e26f42838c4ac08dadbf05b7 100644 (file)
--- a/net/sunrpc/xprtrdma/transport.c
+++ b/net/sunrpc/xprtrdma/transport.c
@@ -259,13 +259,10 @@ xprt_rdma_connect_worker(struct work_struct *work)
 
        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 @@ xprt_rdma_inject_disconnect(struct rpc_xprt *xprt)
        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 @@ xprt_rdma_destroy(struct rpc_xprt *xprt)
 {
        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 @@ xprt_rdma_destroy(struct rpc_xprt *xprt)
        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 @@ xprt_setup_rdma(struct xprt_create *args)
        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 @@ out3:
 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 1addcc9477baab581427d9cd78cfbf1c01a76f4d..7f9e9025c42f2fbeffb736ffa0e3e34eb9e0c67c 100644 (file)
--- a/net/sunrpc/xprtrdma/verbs.c
+++ b/net/sunrpc/xprtrdma/verbs.c
@@ -220,6 +220,7 @@ rpcrdma_conn_upcall(struct rdma_cm_id *id, struct rdma_cm_event *event)
        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 @@ rpcrdma_conn_upcall(struct rdma_cm_id *id, struct rdma_cm_event *event)
                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 @@ 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);
 
@@ -322,8 +321,7 @@ rpcrdma_create_id(struct rpcrdma_xprt *xprt, struct rpcrdma_ia *ia)
        }
        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 @@ rpcrdma_create_id(struct rpcrdma_xprt *xprt, struct rpcrdma_ia *ia)
        }
        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 @@ rpcrdma_ia_remove(struct rpcrdma_ia *ia)
 
        /* Allow waiters to continue */
        complete(&ia->ri_remove_done);
+
+       trace_xprtrdma_remove(r_xprt);
 }
 
 /**
@@ -471,7 +470,6 @@ rpcrdma_ia_remove(struct rpcrdma_ia *ia)
 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 @@ out1:
 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 @@ rpcrdma_ep_recreate_xprt(struct rpcrdma_xprt *r_xprt,
 {
        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 @@ rpcrdma_ep_reconnect(struct rpcrdma_xprt *r_xprt, struct rpcrdma_ep *ep,
        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 @@ rpcrdma_ep_disconnect(struct rpcrdma_ep *ep, struct rpcrdma_ia *ia)
        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);
 }