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@xxxxxxxxxx>
---
include/trace/events/rpcrdma.h | 77 ++++++++++++++++++++++++++++-----------
net/sunrpc/xprtrdma/transport.c | 3 +-
net/sunrpc/xprtrdma/verbs.c | 13 ++-----
3 files changed, 60 insertions(+), 33 deletions(-)
diff --git a/include/trace/events/rpcrdma.h b/include/trace/events/rpcrdma.h
index 336a65d..201623c 100644
--- a/include/trace/events/rpcrdma.h
+++ b/include/trace/events/rpcrdma.h
@@ -85,6 +85,44 @@
), \
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_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 361e591..ce263e6 100644
--- a/net/sunrpc/xprtrdma/transport.c
+++ b/net/sunrpc/xprtrdma/transport.c
@@ -527,13 +527,12 @@ static void xprt_rdma_set_connect_timeout(struct rpc_xprt *xprt,
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 a514e2c..92bdf05 100644
--- a/net/sunrpc/xprtrdma/verbs.c
+++ b/net/sunrpc/xprtrdma/verbs.c
@@ -297,8 +297,6 @@ static void rpcrdma_xprt_drain(struct rpcrdma_xprt *r_xprt)
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 @@ static void rpcrdma_xprt_drain(struct rpcrdma_xprt *r_xprt)
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 @@ static void rpcrdma_xprt_drain(struct rpcrdma_xprt *r_xprt)
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 @@ static int rpcrdma_ep_reconnect(struct rpcrdma_xprt *r_xprt,
ep->rep_connected = rc;
out_noupdate:
+ trace_xprtrdma_connect(r_xprt, rc);
return rc;
}
