* [PATCH 1/2] SUNRPC: Eliminate log noise in call_reserveresult
2019-10-09 16:58 [PATCH 0/2] Two quick clean-ups Chuck Lever
@ 2019-10-09 16:58 ` Chuck Lever
2019-10-09 16:58 ` [PATCH 2/2] SUNRPC: Add trace points to observe transport congestion control Chuck Lever
1 sibling, 0 replies; 3+ messages in thread
From: Chuck Lever @ 2019-10-09 16:58 UTC (permalink / raw)
To: anna.schumaker, trondmy; +Cc: linux-nfs
Sep 11 16:35:20 manet kernel:
call_reserveresult: unrecognized error -512, exiting
Diagnostic error messages such as this likely have no value for NFS
client administrators.
Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
net/sunrpc/clnt.c | 14 ++------------
1 file changed, 2 insertions(+), 12 deletions(-)
diff --git a/net/sunrpc/clnt.c b/net/sunrpc/clnt.c
index f7f7856..a728297 100644
--- a/net/sunrpc/clnt.c
+++ b/net/sunrpc/clnt.c
@@ -1676,8 +1676,6 @@ void rpc_force_rebind(struct rpc_clnt *clnt)
return;
}
- printk(KERN_ERR "%s: status=%d, but no request slot, exiting\n",
- __func__, status);
rpc_call_rpcerror(task, -EIO);
return;
}
@@ -1686,11 +1684,8 @@ void rpc_force_rebind(struct rpc_clnt *clnt)
* Even though there was an error, we may have acquired
* a request slot somehow. Make sure not to leak it.
*/
- if (task->tk_rqstp) {
- printk(KERN_ERR "%s: status=%d, request allocated anyway\n",
- __func__, status);
+ if (task->tk_rqstp)
xprt_release(task);
- }
switch (status) {
case -ENOMEM:
@@ -1699,14 +1694,9 @@ void rpc_force_rebind(struct rpc_clnt *clnt)
case -EAGAIN: /* woken up; retry */
task->tk_action = call_retry_reserve;
return;
- case -EIO: /* probably a shutdown */
- break;
default:
- printk(KERN_ERR "%s: unrecognized error %d, exiting\n",
- __func__, status);
- break;
+ rpc_call_rpcerror(task, status);
}
- rpc_call_rpcerror(task, status);
}
/*
^ permalink raw reply related [flat|nested] 3+ messages in thread* [PATCH 2/2] SUNRPC: Add trace points to observe transport congestion control
2019-10-09 16:58 [PATCH 0/2] Two quick clean-ups Chuck Lever
2019-10-09 16:58 ` [PATCH 1/2] SUNRPC: Eliminate log noise in call_reserveresult Chuck Lever
@ 2019-10-09 16:58 ` Chuck Lever
1 sibling, 0 replies; 3+ messages in thread
From: Chuck Lever @ 2019-10-09 16:58 UTC (permalink / raw)
To: anna.schumaker, trondmy; +Cc: linux-nfs
To help debug problems with RPC/RDMA credit management, replace
dprintk() call sites in the transport send lock paths with trace
events.
Similar trace points are defined for the non-congestion paths.
Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
include/trace/events/sunrpc.h | 93 +++++++++++++++++++++++++++++++++++++++++
net/sunrpc/xprt.c | 22 ++++++----
2 files changed, 106 insertions(+), 9 deletions(-)
diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
index ffa3c51..378233f 100644
--- a/include/trace/events/sunrpc.h
+++ b/include/trace/events/sunrpc.h
@@ -777,6 +777,99 @@
__get_str(addr), __get_str(port), __entry->status)
);
+DECLARE_EVENT_CLASS(xprt_writelock_event,
+ TP_PROTO(
+ const struct rpc_xprt *xprt, const struct rpc_task *task
+ ),
+
+ TP_ARGS(xprt, task),
+
+ TP_STRUCT__entry(
+ __field(unsigned int, task_id)
+ __field(unsigned int, client_id)
+ __field(unsigned int, snd_task_id)
+ ),
+
+ TP_fast_assign(
+ if (task) {
+ __entry->task_id = task->tk_pid;
+ __entry->client_id = task->tk_client ?
+ task->tk_client->cl_clid : -1;
+ } else {
+ __entry->task_id = -1;
+ __entry->client_id = -1;
+ }
+ __entry->snd_task_id = xprt->snd_task ?
+ xprt->snd_task->tk_pid : -1;
+ ),
+
+ TP_printk("task:%u@%u snd_task:%u",
+ __entry->task_id, __entry->client_id,
+ __entry->snd_task_id)
+);
+
+#define DEFINE_WRITELOCK_EVENT(name) \
+ DEFINE_EVENT(xprt_writelock_event, xprt_##name, \
+ TP_PROTO( \
+ const struct rpc_xprt *xprt, \
+ const struct rpc_task *task \
+ ), \
+ TP_ARGS(xprt, task))
+
+DEFINE_WRITELOCK_EVENT(reserve_xprt);
+DEFINE_WRITELOCK_EVENT(release_xprt);
+
+DECLARE_EVENT_CLASS(xprt_cong_event,
+ TP_PROTO(
+ const struct rpc_xprt *xprt, const struct rpc_task *task
+ ),
+
+ TP_ARGS(xprt, task),
+
+ TP_STRUCT__entry(
+ __field(unsigned int, task_id)
+ __field(unsigned int, client_id)
+ __field(unsigned int, snd_task_id)
+ __field(unsigned long, cong)
+ __field(unsigned long, cwnd)
+ __field(bool, wait)
+ ),
+
+ TP_fast_assign(
+ if (task) {
+ __entry->task_id = task->tk_pid;
+ __entry->client_id = task->tk_client ?
+ task->tk_client->cl_clid : -1;
+ } else {
+ __entry->task_id = -1;
+ __entry->client_id = -1;
+ }
+ __entry->snd_task_id = xprt->snd_task ?
+ xprt->snd_task->tk_pid : -1;
+ __entry->cong = xprt->cong;
+ __entry->cwnd = xprt->cwnd;
+ __entry->wait = test_bit(XPRT_CWND_WAIT, &xprt->state);
+ ),
+
+ TP_printk("task:%u@%u snd_task:%u cong=%lu cwnd=%lu%s",
+ __entry->task_id, __entry->client_id,
+ __entry->snd_task_id, __entry->cong, __entry->cwnd,
+ __entry->wait ? " (wait)" : "")
+);
+
+#define DEFINE_CONG_EVENT(name) \
+ DEFINE_EVENT(xprt_cong_event, xprt_##name, \
+ TP_PROTO( \
+ const struct rpc_xprt *xprt, \
+ const struct rpc_task *task \
+ ), \
+ TP_ARGS(xprt, task))
+
+DEFINE_CONG_EVENT(reserve_cong);
+DEFINE_CONG_EVENT(release_cong);
+DEFINE_CONG_EVENT(get_cong);
+DEFINE_CONG_EVENT(put_cong);
+
TRACE_EVENT(xs_stream_read_data,
TP_PROTO(struct rpc_xprt *xprt, ssize_t err, size_t total),
diff --git a/net/sunrpc/xprt.c b/net/sunrpc/xprt.c
index 8a45b3c..fcbeb56 100644
--- a/net/sunrpc/xprt.c
+++ b/net/sunrpc/xprt.c
@@ -205,20 +205,20 @@ int xprt_reserve_xprt(struct rpc_xprt *xprt, struct rpc_task *task)
if (test_and_set_bit(XPRT_LOCKED, &xprt->state)) {
if (task == xprt->snd_task)
- return 1;
+ goto out_locked;
goto out_sleep;
}
if (test_bit(XPRT_WRITE_SPACE, &xprt->state))
goto out_unlock;
xprt->snd_task = task;
+out_locked:
+ trace_xprt_reserve_xprt(xprt, task);
return 1;
out_unlock:
xprt_clear_locked(xprt);
out_sleep:
- dprintk("RPC: %5u failed to lock transport %p\n",
- task->tk_pid, xprt);
task->tk_status = -EAGAIN;
if (RPC_IS_SOFT(task))
rpc_sleep_on_timeout(&xprt->sending, task, NULL,
@@ -269,23 +269,22 @@ int xprt_reserve_xprt_cong(struct rpc_xprt *xprt, struct rpc_task *task)
if (test_and_set_bit(XPRT_LOCKED, &xprt->state)) {
if (task == xprt->snd_task)
- return 1;
+ goto out_locked;
goto out_sleep;
}
if (req == NULL) {
xprt->snd_task = task;
- return 1;
+ goto out_locked;
}
if (test_bit(XPRT_WRITE_SPACE, &xprt->state))
goto out_unlock;
if (!xprt_need_congestion_window_wait(xprt)) {
xprt->snd_task = task;
- return 1;
+ goto out_locked;
}
out_unlock:
xprt_clear_locked(xprt);
out_sleep:
- dprintk("RPC: %5u failed to lock transport %p\n", task->tk_pid, xprt);
task->tk_status = -EAGAIN;
if (RPC_IS_SOFT(task))
rpc_sleep_on_timeout(&xprt->sending, task, NULL,
@@ -293,6 +292,9 @@ int xprt_reserve_xprt_cong(struct rpc_xprt *xprt, struct rpc_task *task)
else
rpc_sleep_on(&xprt->sending, task, NULL);
return 0;
+out_locked:
+ trace_xprt_reserve_cong(xprt, task);
+ return 1;
}
EXPORT_SYMBOL_GPL(xprt_reserve_xprt_cong);
@@ -357,6 +359,7 @@ void xprt_release_xprt(struct rpc_xprt *xprt, struct rpc_task *task)
xprt_clear_locked(xprt);
__xprt_lock_write_next(xprt);
}
+ trace_xprt_release_xprt(xprt, task);
}
EXPORT_SYMBOL_GPL(xprt_release_xprt);
@@ -374,6 +377,7 @@ void xprt_release_xprt_cong(struct rpc_xprt *xprt, struct rpc_task *task)
xprt_clear_locked(xprt);
__xprt_lock_write_next_cong(xprt);
}
+ trace_xprt_release_cong(xprt, task);
}
EXPORT_SYMBOL_GPL(xprt_release_xprt_cong);
@@ -395,8 +399,7 @@ static inline void xprt_release_write(struct rpc_xprt *xprt, struct rpc_task *ta
{
if (req->rq_cong)
return 1;
- dprintk("RPC: %5u xprt_cwnd_limited cong = %lu cwnd = %lu\n",
- req->rq_task->tk_pid, xprt->cong, xprt->cwnd);
+ trace_xprt_get_cong(xprt, req->rq_task);
if (RPCXPRT_CONGESTED(xprt)) {
xprt_set_congestion_window_wait(xprt);
return 0;
@@ -418,6 +421,7 @@ static inline void xprt_release_write(struct rpc_xprt *xprt, struct rpc_task *ta
req->rq_cong = 0;
xprt->cong -= RPC_CWNDSCALE;
xprt_test_and_clear_congestion_window_wait(xprt);
+ trace_xprt_put_cong(xprt, req->rq_task);
__xprt_lock_write_next_cong(xprt);
}
^ permalink raw reply related [flat|nested] 3+ messages in thread