From 53bc19f17f21738735706fabcae3070f16c833db Mon Sep 17 00:00:00 2001 From: Chuck Lever Date: Tue, 12 May 2020 17:13:01 -0400 Subject: SUNRPC: receive buffer size estimation values almost never change Avoid unnecessary cache sloshing by placing the buffer size estimation update logic behind an atomic bit flag. The size of GSS information included in each wrapped Reply does not change during the lifetime of a GSS context. Therefore, the au_rslack and au_ralign fields need to be updated only once after establishing a fresh GSS credential. Thus a slack size update must occur after a cred is created, duplicated, renewed, or expires. I'm not sure I have this exactly right. A trace point is introduced to track updates to these variables to enable troubleshooting the problem if I missed a spot. Signed-off-by: Chuck Lever Signed-off-by: Anna Schumaker --- include/trace/events/rpcgss.h | 34 ++++++++++++++++++++++++++++++++++ 1 file changed, 34 insertions(+) (limited to 'include/trace') diff --git a/include/trace/events/rpcgss.h b/include/trace/events/rpcgss.h index 32d88c4fb063..421b14db87ae 100644 --- a/include/trace/events/rpcgss.h +++ b/include/trace/events/rpcgss.h @@ -291,6 +291,40 @@ TRACE_EVENT(rpcgss_need_reencode, __entry->ret ? "" : "un") ); +TRACE_EVENT(rpcgss_update_slack, + TP_PROTO( + const struct rpc_task *task, + const struct rpc_auth *auth + ), + + TP_ARGS(task, auth), + + TP_STRUCT__entry( + __field(unsigned int, task_id) + __field(unsigned int, client_id) + __field(u32, xid) + __field(const void *, auth) + __field(unsigned int, rslack) + __field(unsigned int, ralign) + __field(unsigned int, verfsize) + ), + + TP_fast_assign( + __entry->task_id = task->tk_pid; + __entry->client_id = task->tk_client->cl_clid; + __entry->xid = be32_to_cpu(task->tk_rqstp->rq_xid); + __entry->auth = auth; + __entry->rslack = auth->au_rslack; + __entry->ralign = auth->au_ralign; + __entry->verfsize = auth->au_verfsize; + ), + + TP_printk("task:%u@%u xid=0x%08x auth=%p rslack=%u ralign=%u verfsize=%u\n", + __entry->task_id, __entry->client_id, __entry->xid, + __entry->auth, __entry->rslack, __entry->ralign, + __entry->verfsize) +); + DECLARE_EVENT_CLASS(rpcgss_svc_seqno_class, TP_PROTO( __be32 xid, -- cgit v1.2.3-59-g8ed1b From 74fb8fecee99f61415dcb6e22dbc24f42988a1d3 Mon Sep 17 00:00:00 2001 From: Chuck Lever Date: Tue, 12 May 2020 17:13:07 -0400 Subject: SUNRPC: Trace GSS context lifetimes Signed-off-by: Chuck Lever Signed-off-by: Anna Schumaker --- include/trace/events/rpcgss.h | 55 +++++++++++++++++++++++++++++++++++++++--- net/sunrpc/auth_gss/auth_gss.c | 10 +++++--- net/sunrpc/auth_gss/trace.c | 1 + 3 files changed, 58 insertions(+), 8 deletions(-) (limited to 'include/trace') diff --git a/include/trace/events/rpcgss.h b/include/trace/events/rpcgss.h index 421b14db87ae..b9b51a4b1db1 100644 --- a/include/trace/events/rpcgss.h +++ b/include/trace/events/rpcgss.h @@ -17,6 +17,16 @@ ** GSS-API related trace events **/ +TRACE_DEFINE_ENUM(RPC_GSS_SVC_NONE); +TRACE_DEFINE_ENUM(RPC_GSS_SVC_INTEGRITY); +TRACE_DEFINE_ENUM(RPC_GSS_SVC_PRIVACY); + +#define show_gss_service(x) \ + __print_symbolic(x, \ + { RPC_GSS_SVC_NONE, "none" }, \ + { RPC_GSS_SVC_INTEGRITY, "integrity" }, \ + { RPC_GSS_SVC_PRIVACY, "privacy" }) + TRACE_DEFINE_ENUM(GSS_S_BAD_MECH); TRACE_DEFINE_ENUM(GSS_S_BAD_NAME); TRACE_DEFINE_ENUM(GSS_S_BAD_NAMETYPE); @@ -126,6 +136,40 @@ DEFINE_GSSAPI_EVENT(verify_mic); DEFINE_GSSAPI_EVENT(wrap); DEFINE_GSSAPI_EVENT(unwrap); +DECLARE_EVENT_CLASS(rpcgss_ctx_class, + TP_PROTO( + const struct gss_cred *gc + ), + + TP_ARGS(gc), + + TP_STRUCT__entry( + __field(const void *, cred) + __field(unsigned long, service) + __string(principal, gc->gc_principal) + ), + + TP_fast_assign( + __entry->cred = gc; + __entry->service = gc->gc_service; + __assign_str(principal, gc->gc_principal) + ), + + TP_printk("cred=%p service=%s principal='%s'", + __entry->cred, show_gss_service(__entry->service), + __get_str(principal)) +); + +#define DEFINE_CTX_EVENT(name) \ + DEFINE_EVENT(rpcgss_ctx_class, rpcgss_ctx_##name, \ + TP_PROTO( \ + const struct gss_cred *gc \ + ), \ + TP_ARGS(gc)) + +DEFINE_CTX_EVENT(init); +DEFINE_CTX_EVENT(destroy); + TRACE_EVENT(rpcgss_svc_accept_upcall, TP_PROTO( __be32 xid, @@ -405,6 +449,7 @@ TRACE_EVENT(rpcgss_upcall_result, TRACE_EVENT(rpcgss_context, TP_PROTO( + u32 window_size, unsigned long expiry, unsigned long now, unsigned int timeout, @@ -412,12 +457,13 @@ TRACE_EVENT(rpcgss_context, const u8 *data ), - TP_ARGS(expiry, now, timeout, len, data), + TP_ARGS(window_size, expiry, now, timeout, len, data), TP_STRUCT__entry( __field(unsigned long, expiry) __field(unsigned long, now) __field(unsigned int, timeout) + __field(u32, window_size) __field(int, len) __string(acceptor, data) ), @@ -426,13 +472,14 @@ TRACE_EVENT(rpcgss_context, __entry->expiry = expiry; __entry->now = now; __entry->timeout = timeout; + __entry->window_size = window_size; __entry->len = len; strncpy(__get_str(acceptor), data, len); ), - TP_printk("gc_expiry=%lu now=%lu timeout=%u acceptor=%.*s", - __entry->expiry, __entry->now, __entry->timeout, - __entry->len, __get_str(acceptor)) + TP_printk("win_size=%u expiry=%lu now=%lu timeout=%u acceptor=%.*s", + __entry->window_size, __entry->expiry, __entry->now, + __entry->timeout, __entry->len, __get_str(acceptor)) ); diff --git a/net/sunrpc/auth_gss/auth_gss.c b/net/sunrpc/auth_gss/auth_gss.c index 5f097c8cacd1..429f17459ae3 100644 --- a/net/sunrpc/auth_gss/auth_gss.c +++ b/net/sunrpc/auth_gss/auth_gss.c @@ -254,7 +254,7 @@ gss_fill_context(const void *p, const void *end, struct gss_cl_ctx *ctx, struct if (IS_ERR(p)) goto err; done: - trace_rpcgss_context(ctx->gc_expiry, now, timeout, + trace_rpcgss_context(window_size, ctx->gc_expiry, now, timeout, ctx->gc_acceptor.len, ctx->gc_acceptor.data); err: return p; @@ -697,10 +697,12 @@ retry: } schedule(); } - if (gss_msg->ctx) + if (gss_msg->ctx) { + trace_rpcgss_ctx_init(gss_cred); gss_cred_set_ctx(cred, gss_msg->ctx); - else + } else { err = gss_msg->msg.errno; + } spin_unlock(&pipe->lock); out_intr: finish_wait(&gss_msg->waitqueue, &wait); @@ -1284,6 +1286,7 @@ gss_send_destroy_context(struct rpc_cred *cred) if (new) { ctx->gc_proc = RPC_GSS_PROC_DESTROY; + trace_rpcgss_ctx_destroy(gss_cred); task = rpc_call_null(gss_auth->client, &new->gc_base, RPC_TASK_ASYNC|RPC_TASK_SOFT); if (!IS_ERR(task)) @@ -1349,7 +1352,6 @@ gss_destroy_nullcred(struct rpc_cred *cred) static void gss_destroy_cred(struct rpc_cred *cred) { - if (test_and_clear_bit(RPCAUTH_CRED_UPTODATE, &cred->cr_flags) != 0) gss_send_destroy_context(cred); gss_destroy_nullcred(cred); diff --git a/net/sunrpc/auth_gss/trace.c b/net/sunrpc/auth_gss/trace.c index 5576f1e66de9..49fa583d7f91 100644 --- a/net/sunrpc/auth_gss/trace.c +++ b/net/sunrpc/auth_gss/trace.c @@ -6,6 +6,7 @@ #include #include #include +#include #define CREATE_TRACE_POINTS #include -- cgit v1.2.3-59-g8ed1b From 7a34c8e0c38b5fd21a764031b1f8664c28b595af Mon Sep 17 00:00:00 2001 From: Chuck Lever Date: Tue, 12 May 2020 17:13:12 -0400 Subject: SUNRPC: Update the rpc_show_task_flags() macro Recent additions to the RPC_TASK flags neglected to update the tracepoint ENUM definitions. Signed-off-by: Chuck Lever Signed-off-by: Anna Schumaker --- include/trace/events/sunrpc.h | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) (limited to 'include/trace') diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h index ffd2215950dc..7d64aea7489e 100644 --- a/include/trace/events/sunrpc.h +++ b/include/trace/events/sunrpc.h @@ -142,29 +142,35 @@ TRACE_EVENT(rpc_request, TRACE_DEFINE_ENUM(RPC_TASK_ASYNC); TRACE_DEFINE_ENUM(RPC_TASK_SWAPPER); +TRACE_DEFINE_ENUM(RPC_TASK_NULLCREDS); TRACE_DEFINE_ENUM(RPC_CALL_MAJORSEEN); TRACE_DEFINE_ENUM(RPC_TASK_ROOTCREDS); TRACE_DEFINE_ENUM(RPC_TASK_DYNAMIC); +TRACE_DEFINE_ENUM(RPC_TASK_NO_ROUND_ROBIN); TRACE_DEFINE_ENUM(RPC_TASK_SOFT); TRACE_DEFINE_ENUM(RPC_TASK_SOFTCONN); TRACE_DEFINE_ENUM(RPC_TASK_SENT); TRACE_DEFINE_ENUM(RPC_TASK_TIMEOUT); TRACE_DEFINE_ENUM(RPC_TASK_NOCONNECT); TRACE_DEFINE_ENUM(RPC_TASK_NO_RETRANS_TIMEOUT); +TRACE_DEFINE_ENUM(RPC_TASK_CRED_NOREF); #define rpc_show_task_flags(flags) \ __print_flags(flags, "|", \ { RPC_TASK_ASYNC, "ASYNC" }, \ { RPC_TASK_SWAPPER, "SWAPPER" }, \ + { RPC_TASK_NULLCREDS, "NULLCREDS" }, \ { RPC_CALL_MAJORSEEN, "MAJORSEEN" }, \ { RPC_TASK_ROOTCREDS, "ROOTCREDS" }, \ { RPC_TASK_DYNAMIC, "DYNAMIC" }, \ + { RPC_TASK_NO_ROUND_ROBIN, "NO_ROUND_ROBIN" }, \ { RPC_TASK_SOFT, "SOFT" }, \ { RPC_TASK_SOFTCONN, "SOFTCONN" }, \ { RPC_TASK_SENT, "SENT" }, \ { RPC_TASK_TIMEOUT, "TIMEOUT" }, \ { RPC_TASK_NOCONNECT, "NOCONNECT" }, \ - { RPC_TASK_NO_RETRANS_TIMEOUT, "NORTO" }) + { RPC_TASK_NO_RETRANS_TIMEOUT, "NORTO" }, \ + { RPC_TASK_CRED_NOREF, "CRED_NOREF" }) TRACE_DEFINE_ENUM(RPC_TASK_RUNNING); TRACE_DEFINE_ENUM(RPC_TASK_QUEUED); -- cgit v1.2.3-59-g8ed1b From 82909dc546461c6ea060879e9b6fbe5eeac37cea Mon Sep 17 00:00:00 2001 From: Chuck Lever Date: Tue, 12 May 2020 17:13:18 -0400 Subject: SUNRPC: Update the RPC_SHOW_SOCKET() macro Clean up: remove unnecessary commas, and fix a white-space nit. Signed-off-by: Chuck Lever Signed-off-by: Anna Schumaker --- include/trace/events/sunrpc.h | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) (limited to 'include/trace') diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h index 7d64aea7489e..f6896bcfd97f 100644 --- a/include/trace/events/sunrpc.h +++ b/include/trace/events/sunrpc.h @@ -581,9 +581,9 @@ TRACE_EVENT(rpc_reply_pages, #define RPC_SHOW_SOCKET \ EM( SS_FREE, "FREE" ) \ EM( SS_UNCONNECTED, "UNCONNECTED" ) \ - EM( SS_CONNECTING, "CONNECTING," ) \ - EM( SS_CONNECTED, "CONNECTED," ) \ - EMe(SS_DISCONNECTING, "DISCONNECTING" ) + EM( SS_CONNECTING, "CONNECTING" ) \ + EM( SS_CONNECTED, "CONNECTED" ) \ + EMe( SS_DISCONNECTING, "DISCONNECTING" ) #define rpc_show_socket_state(state) \ __print_symbolic(state, RPC_SHOW_SOCKET) -- cgit v1.2.3-59-g8ed1b From 0125ecbb526745930c63585314fa4e1c45432979 Mon Sep 17 00:00:00 2001 From: Chuck Lever Date: Tue, 12 May 2020 17:13:23 -0400 Subject: SUNRPC: Add tracepoint to rpc_call_rpcerror() Add a tracepoint in another common exit point for failing RPCs. Signed-off-by: Chuck Lever Signed-off-by: Anna Schumaker --- include/trace/events/sunrpc.h | 28 ++++++++++++++++++++++++++++ net/sunrpc/clnt.c | 1 + 2 files changed, 29 insertions(+) (limited to 'include/trace') diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h index f6896bcfd97f..f1fd3fae5b0f 100644 --- a/include/trace/events/sunrpc.h +++ b/include/trace/events/sunrpc.h @@ -365,6 +365,34 @@ DEFINE_RPC_REPLY_EVENT(stale_creds); DEFINE_RPC_REPLY_EVENT(bad_creds); DEFINE_RPC_REPLY_EVENT(auth_tooweak); +TRACE_EVENT(rpc_call_rpcerror, + TP_PROTO( + const struct rpc_task *task, + int tk_status, + int rpc_status + ), + + TP_ARGS(task, tk_status, rpc_status), + + TP_STRUCT__entry( + __field(unsigned int, task_id) + __field(unsigned int, client_id) + __field(int, tk_status) + __field(int, rpc_status) + ), + + TP_fast_assign( + __entry->client_id = task->tk_client->cl_clid; + __entry->task_id = task->tk_pid; + __entry->tk_status = tk_status; + __entry->rpc_status = rpc_status; + ), + + TP_printk("task:%u@%u tk_status=%d rpc_status=%d", + __entry->task_id, __entry->client_id, + __entry->tk_status, __entry->rpc_status) +); + TRACE_EVENT(rpc_stats_latency, TP_PROTO( diff --git a/net/sunrpc/clnt.c b/net/sunrpc/clnt.c index 61b21dafd7c0..2621258bd8fc 100644 --- a/net/sunrpc/clnt.c +++ b/net/sunrpc/clnt.c @@ -1624,6 +1624,7 @@ const char static void __rpc_call_rpcerror(struct rpc_task *task, int tk_status, int rpc_status) { + trace_rpc_call_rpcerror(task, tk_status, rpc_status); task->tk_rpc_status = rpc_status; rpc_exit(task, tk_status); } -- cgit v1.2.3-59-g8ed1b From c509f15a5801605652126831d965751e8d602471 Mon Sep 17 00:00:00 2001 From: Chuck Lever Date: Tue, 12 May 2020 17:13:28 -0400 Subject: SUNRPC: Split the xdr_buf event class To help tie the recorded xdr_buf to a particular RPC transaction, the client side version of this class should display task ID information and the server side one should show the request's XID. Signed-off-by: Chuck Lever Signed-off-by: Anna Schumaker --- include/trace/events/sunrpc.h | 113 ++++++++++++++++++++++++------------------ net/sunrpc/clnt.c | 4 +- net/sunrpc/svc_xprt.c | 4 +- net/sunrpc/xprt.c | 2 +- 4 files changed, 71 insertions(+), 52 deletions(-) (limited to 'include/trace') diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h index f1fd3fae5b0f..4747803b370e 100644 --- a/include/trace/events/sunrpc.h +++ b/include/trace/events/sunrpc.h @@ -14,14 +14,17 @@ #include #include -DECLARE_EVENT_CLASS(xdr_buf_class, +DECLARE_EVENT_CLASS(rpc_xdr_buf_class, TP_PROTO( + const struct rpc_task *task, const struct xdr_buf *xdr ), - TP_ARGS(xdr), + TP_ARGS(task, xdr), TP_STRUCT__entry( + __field(unsigned int, task_id) + __field(unsigned int, client_id) __field(const void *, head_base) __field(size_t, head_len) __field(const void *, tail_base) @@ -31,6 +34,8 @@ DECLARE_EVENT_CLASS(xdr_buf_class, ), TP_fast_assign( + __entry->task_id = task->tk_pid; + __entry->client_id = task->tk_client->cl_clid; __entry->head_base = xdr->head[0].iov_base; __entry->head_len = xdr->head[0].iov_len; __entry->tail_base = xdr->tail[0].iov_base; @@ -39,23 +44,26 @@ DECLARE_EVENT_CLASS(xdr_buf_class, __entry->msg_len = xdr->len; ), - TP_printk("head=[%p,%zu] page=%u tail=[%p,%zu] len=%u", + TP_printk("task:%u@%u head=[%p,%zu] page=%u tail=[%p,%zu] len=%u", + __entry->task_id, __entry->client_id, __entry->head_base, __entry->head_len, __entry->page_len, __entry->tail_base, __entry->tail_len, __entry->msg_len ) ); -#define DEFINE_XDRBUF_EVENT(name) \ - DEFINE_EVENT(xdr_buf_class, name, \ +#define DEFINE_RPCXDRBUF_EVENT(name) \ + DEFINE_EVENT(rpc_xdr_buf_class, \ + rpc_xdr_##name, \ TP_PROTO( \ + const struct rpc_task *task, \ const struct xdr_buf *xdr \ ), \ - TP_ARGS(xdr)) + TP_ARGS(task, xdr)) + +DEFINE_RPCXDRBUF_EVENT(sendto); +DEFINE_RPCXDRBUF_EVENT(recvfrom); +DEFINE_RPCXDRBUF_EVENT(reply_pages); -DEFINE_XDRBUF_EVENT(xprt_sendto); -DEFINE_XDRBUF_EVENT(xprt_recvfrom); -DEFINE_XDRBUF_EVENT(svc_recvfrom); -DEFINE_XDRBUF_EVENT(svc_sendto); TRACE_DEFINE_ENUM(RPC_AUTH_OK); TRACE_DEFINE_ENUM(RPC_AUTH_BADCRED); @@ -560,43 +568,6 @@ TRACE_EVENT(rpc_xdr_alignment, ) ); -TRACE_EVENT(rpc_reply_pages, - TP_PROTO( - const struct rpc_rqst *req - ), - - TP_ARGS(req), - - TP_STRUCT__entry( - __field(unsigned int, task_id) - __field(unsigned int, client_id) - __field(const void *, head_base) - __field(size_t, head_len) - __field(const void *, tail_base) - __field(size_t, tail_len) - __field(unsigned int, page_len) - ), - - TP_fast_assign( - __entry->task_id = req->rq_task->tk_pid; - __entry->client_id = req->rq_task->tk_client->cl_clid; - - __entry->head_base = req->rq_rcv_buf.head[0].iov_base; - __entry->head_len = req->rq_rcv_buf.head[0].iov_len; - __entry->page_len = req->rq_rcv_buf.page_len; - __entry->tail_base = req->rq_rcv_buf.tail[0].iov_base; - __entry->tail_len = req->rq_rcv_buf.tail[0].iov_len; - ), - - TP_printk( - "task:%u@%u xdr=[%p,%zu]/%u/[%p,%zu]\n", - __entry->task_id, __entry->client_id, - __entry->head_base, __entry->head_len, - __entry->page_len, - __entry->tail_base, __entry->tail_len - ) -); - /* * First define the enums in the below macros to be exported to userspace * via TRACE_DEFINE_ENUM(). @@ -1024,6 +995,54 @@ TRACE_EVENT(xs_stream_read_request, __entry->copied, __entry->reclen, __entry->offset) ); + +DECLARE_EVENT_CLASS(svc_xdr_buf_class, + TP_PROTO( + const struct svc_rqst *rqst, + const struct xdr_buf *xdr + ), + + TP_ARGS(rqst, xdr), + + TP_STRUCT__entry( + __field(u32, xid) + __field(const void *, head_base) + __field(size_t, head_len) + __field(const void *, tail_base) + __field(size_t, tail_len) + __field(unsigned int, page_len) + __field(unsigned int, msg_len) + ), + + TP_fast_assign( + __entry->xid = be32_to_cpu(rqst->rq_xid); + __entry->head_base = xdr->head[0].iov_base; + __entry->head_len = xdr->head[0].iov_len; + __entry->tail_base = xdr->tail[0].iov_base; + __entry->tail_len = xdr->tail[0].iov_len; + __entry->page_len = xdr->page_len; + __entry->msg_len = xdr->len; + ), + + TP_printk("xid=0x%08x head=[%p,%zu] page=%u tail=[%p,%zu] len=%u", + __entry->xid, + __entry->head_base, __entry->head_len, __entry->page_len, + __entry->tail_base, __entry->tail_len, __entry->msg_len + ) +); + +#define DEFINE_SVCXDRBUF_EVENT(name) \ + DEFINE_EVENT(svc_xdr_buf_class, \ + svc_xdr_##name, \ + TP_PROTO( \ + const struct svc_rqst *rqst, \ + const struct xdr_buf *xdr \ + ), \ + TP_ARGS(rqst, xdr)) + +DEFINE_SVCXDRBUF_EVENT(recvfrom); +DEFINE_SVCXDRBUF_EVENT(sendto); + #define show_rqstp_flags(flags) \ __print_flags(flags, "|", \ { (1UL << RQ_SECURE), "RQ_SECURE"}, \ diff --git a/net/sunrpc/clnt.c b/net/sunrpc/clnt.c index 2621258bd8fc..0e684d93c9b1 100644 --- a/net/sunrpc/clnt.c +++ b/net/sunrpc/clnt.c @@ -1270,7 +1270,7 @@ void rpc_prepare_reply_pages(struct rpc_rqst *req, struct page **pages, hdrsize += RPC_REPHDRSIZE + req->rq_cred->cr_auth->au_ralign - 1; xdr_inline_pages(&req->rq_rcv_buf, hdrsize << 2, pages, base, len); - trace_rpc_reply_pages(req); + trace_rpc_xdr_reply_pages(req->rq_task, &req->rq_rcv_buf); } EXPORT_SYMBOL_GPL(rpc_prepare_reply_pages); @@ -2532,7 +2532,7 @@ call_decode(struct rpc_task *task) goto out; req->rq_rcv_buf.len = req->rq_private_buf.len; - trace_xprt_recvfrom(&req->rq_rcv_buf); + trace_rpc_xdr_recvfrom(task, &req->rq_rcv_buf); /* Check that the softirq receive buffer is valid */ WARN_ON(memcmp(&req->rq_rcv_buf, &req->rq_private_buf, diff --git a/net/sunrpc/svc_xprt.c b/net/sunrpc/svc_xprt.c index 2284ff038dad..8ef44275c255 100644 --- a/net/sunrpc/svc_xprt.c +++ b/net/sunrpc/svc_xprt.c @@ -812,7 +812,7 @@ static int svc_handle_xprt(struct svc_rqst *rqstp, struct svc_xprt *xprt) else len = xprt->xpt_ops->xpo_recvfrom(rqstp); if (len > 0) - trace_svc_recvfrom(&rqstp->rq_arg); + trace_svc_xdr_recvfrom(rqstp, &rqstp->rq_arg); rqstp->rq_stime = ktime_get(); rqstp->rq_reserved = serv->sv_max_mesg; atomic_add(rqstp->rq_reserved, &xprt->xpt_reserved); @@ -913,7 +913,7 @@ int svc_send(struct svc_rqst *rqstp) xb->len = xb->head[0].iov_len + xb->page_len + xb->tail[0].iov_len; - trace_svc_sendto(xb); + trace_svc_xdr_sendto(rqstp, xb); /* Grab mutex to serialize outgoing data. */ mutex_lock(&xprt->xpt_mutex); diff --git a/net/sunrpc/xprt.c b/net/sunrpc/xprt.c index 493a30a296fc..053de053a024 100644 --- a/net/sunrpc/xprt.c +++ b/net/sunrpc/xprt.c @@ -1460,7 +1460,7 @@ xprt_request_transmit(struct rpc_rqst *req, struct rpc_task *snd_task) */ req->rq_ntrans++; - trace_xprt_sendto(&req->rq_snd_buf); + trace_rpc_xdr_sendto(task, &req->rq_snd_buf); connect_cookie = xprt->connect_cookie; status = xprt->ops->send_request(req); if (status != 0) { -- cgit v1.2.3-59-g8ed1b From 911813d7a15221362d1655d246f3502c0f898c14 Mon Sep 17 00:00:00 2001 From: Chuck Lever Date: Tue, 12 May 2020 17:13:34 -0400 Subject: SUNRPC: Trace transport lifetime events Refactor: Hoist create/destroy/disconnect tracepoints out of xprtrdma and into the generic RPC client. Some benefits include: - Enable tracing of xprt lifetime events for the socket transport types - Expose the different types of disconnect to help run down issues with lingering connections Signed-off-by: Chuck Lever Signed-off-by: Anna Schumaker --- include/trace/events/rpcrdma.h | 4 ---- include/trace/events/sunrpc.h | 35 +++++++++++++++++++++++++++++++++++ net/sunrpc/xprt.c | 21 +++++++++++---------- net/sunrpc/xprtrdma/transport.c | 8 -------- net/sunrpc/xprtrdma/verbs.c | 1 - 5 files changed, 46 insertions(+), 23 deletions(-) (limited to 'include/trace') diff --git a/include/trace/events/rpcrdma.h b/include/trace/events/rpcrdma.h index 132c3c778a43..edb55eab4762 100644 --- a/include/trace/events/rpcrdma.h +++ b/include/trace/events/rpcrdma.h @@ -380,12 +380,8 @@ TRACE_EVENT(xprtrdma_inline_thresh, DEFINE_CONN_EVENT(connect); DEFINE_CONN_EVENT(disconnect); -DEFINE_CONN_EVENT(flush_dct); -DEFINE_RXPRT_EVENT(xprtrdma_create); -DEFINE_RXPRT_EVENT(xprtrdma_op_destroy); DEFINE_RXPRT_EVENT(xprtrdma_op_inject_dsc); -DEFINE_RXPRT_EVENT(xprtrdma_op_close); DEFINE_RXPRT_EVENT(xprtrdma_op_setport); TRACE_EVENT(xprtrdma_op_connect, diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h index 4747803b370e..fc8a969ba306 100644 --- a/include/trace/events/sunrpc.h +++ b/include/trace/events/sunrpc.h @@ -724,6 +724,41 @@ DEFINE_RPC_SOCKET_EVENT_DONE(rpc_socket_reset_connection); DEFINE_RPC_SOCKET_EVENT(rpc_socket_close); DEFINE_RPC_SOCKET_EVENT(rpc_socket_shutdown); +DECLARE_EVENT_CLASS(rpc_xprt_lifetime_class, + TP_PROTO( + const struct rpc_xprt *xprt + ), + + TP_ARGS(xprt), + + TP_STRUCT__entry( + __string(addr, xprt->address_strings[RPC_DISPLAY_ADDR]) + __string(port, xprt->address_strings[RPC_DISPLAY_PORT]) + ), + + TP_fast_assign( + __assign_str(addr, xprt->address_strings[RPC_DISPLAY_ADDR]); + __assign_str(port, xprt->address_strings[RPC_DISPLAY_PORT]); + ), + + TP_printk("peer=[%s]:%s", __get_str(addr), __get_str(port)) +); + +#define DEFINE_RPC_XPRT_LIFETIME_EVENT(name) \ + DEFINE_EVENT(rpc_xprt_lifetime_class, \ + xprt_##name, \ + TP_PROTO( \ + const struct rpc_xprt *xprt \ + ), \ + TP_ARGS(xprt)) + +DEFINE_RPC_XPRT_LIFETIME_EVENT(create); +DEFINE_RPC_XPRT_LIFETIME_EVENT(disconnect_auto); +DEFINE_RPC_XPRT_LIFETIME_EVENT(disconnect_done); +DEFINE_RPC_XPRT_LIFETIME_EVENT(disconnect_force); +DEFINE_RPC_XPRT_LIFETIME_EVENT(disconnect_cleanup); +DEFINE_RPC_XPRT_LIFETIME_EVENT(destroy); + DECLARE_EVENT_CLASS(rpc_xprt_event, TP_PROTO( const struct rpc_xprt *xprt, diff --git a/net/sunrpc/xprt.c b/net/sunrpc/xprt.c index 053de053a024..d5cc5db9dbf3 100644 --- a/net/sunrpc/xprt.c +++ b/net/sunrpc/xprt.c @@ -663,6 +663,7 @@ static void xprt_autoclose(struct work_struct *work) container_of(work, struct rpc_xprt, task_cleanup); unsigned int pflags = memalloc_nofs_save(); + trace_xprt_disconnect_auto(xprt); clear_bit(XPRT_CLOSE_WAIT, &xprt->state); xprt->ops->close(xprt); xprt_release_write(xprt, NULL); @@ -677,7 +678,7 @@ static void xprt_autoclose(struct work_struct *work) */ void xprt_disconnect_done(struct rpc_xprt *xprt) { - dprintk("RPC: disconnected transport %p\n", xprt); + trace_xprt_disconnect_done(xprt); spin_lock(&xprt->transport_lock); xprt_clear_connected(xprt); xprt_clear_write_space_locked(xprt); @@ -694,6 +695,8 @@ EXPORT_SYMBOL_GPL(xprt_disconnect_done); */ void xprt_force_disconnect(struct rpc_xprt *xprt) { + trace_xprt_disconnect_force(xprt); + /* Don't race with the test_bit() in xprt_clear_locked() */ spin_lock(&xprt->transport_lock); set_bit(XPRT_CLOSE_WAIT, &xprt->state); @@ -832,8 +835,10 @@ void xprt_connect(struct rpc_task *task) if (!xprt_lock_write(xprt, task)) return; - if (test_and_clear_bit(XPRT_CLOSE_WAIT, &xprt->state)) + if (test_and_clear_bit(XPRT_CLOSE_WAIT, &xprt->state)) { + trace_xprt_disconnect_cleanup(xprt); xprt->ops->close(xprt); + } if (!xprt_connected(xprt)) { task->tk_rqstp->rq_connect_cookie = xprt->connect_cookie; @@ -1903,11 +1908,8 @@ struct rpc_xprt *xprt_create_transport(struct xprt_create *args) found: xprt = t->setup(args); - if (IS_ERR(xprt)) { - dprintk("RPC: xprt_create_transport: failed, %ld\n", - -PTR_ERR(xprt)); + if (IS_ERR(xprt)) goto out; - } if (args->flags & XPRT_CREATE_NO_IDLE_TIMEOUT) xprt->idle_timeout = 0; INIT_WORK(&xprt->task_cleanup, xprt_autoclose); @@ -1928,8 +1930,7 @@ found: rpc_xprt_debugfs_register(xprt); - dprintk("RPC: created transport %p with %u slots\n", xprt, - xprt->max_reqs); + trace_xprt_create(xprt); out: return xprt; } @@ -1939,6 +1940,8 @@ static void xprt_destroy_cb(struct work_struct *work) struct rpc_xprt *xprt = container_of(work, struct rpc_xprt, task_cleanup); + trace_xprt_destroy(xprt); + rpc_xprt_debugfs_unregister(xprt); rpc_destroy_wait_queue(&xprt->binding); rpc_destroy_wait_queue(&xprt->pending); @@ -1963,8 +1966,6 @@ static void xprt_destroy_cb(struct work_struct *work) */ static void xprt_destroy(struct rpc_xprt *xprt) { - dprintk("RPC: destroying transport %p\n", xprt); - /* * Exclude transport connect/disconnect handlers and autoclose */ diff --git a/net/sunrpc/xprtrdma/transport.c b/net/sunrpc/xprtrdma/transport.c index 659da37020a4..048c2fd85728 100644 --- a/net/sunrpc/xprtrdma/transport.c +++ b/net/sunrpc/xprtrdma/transport.c @@ -281,8 +281,6 @@ xprt_rdma_destroy(struct rpc_xprt *xprt) { struct rpcrdma_xprt *r_xprt = rpcx_to_rdmax(xprt); - trace_xprtrdma_op_destroy(r_xprt); - cancel_delayed_work_sync(&r_xprt->rx_connect_worker); rpcrdma_xprt_disconnect(r_xprt); @@ -365,10 +363,6 @@ xprt_setup_rdma(struct xprt_create *args) xprt->max_payload = RPCRDMA_MAX_DATA_SEGS << PAGE_SHIFT; - 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; } @@ -385,8 +379,6 @@ void xprt_rdma_close(struct rpc_xprt *xprt) { struct rpcrdma_xprt *r_xprt = rpcx_to_rdmax(xprt); - trace_xprtrdma_op_close(r_xprt); - rpcrdma_xprt_disconnect(r_xprt); xprt->reestablish_timeout = 0; diff --git a/net/sunrpc/xprtrdma/verbs.c b/net/sunrpc/xprtrdma/verbs.c index 05c4d3a9cda2..2ae348377806 100644 --- a/net/sunrpc/xprtrdma/verbs.c +++ b/net/sunrpc/xprtrdma/verbs.c @@ -141,7 +141,6 @@ void rpcrdma_flush_disconnect(struct ib_cq *cq, struct ib_wc *wc) if (wc->status != IB_WC_SUCCESS && r_xprt->rx_ep->re_connect_status == 1) { r_xprt->rx_ep->re_connect_status = -ECONNABORTED; - trace_xprtrdma_flush_dct(r_xprt, wc->status); xprt_force_disconnect(xprt); } } -- cgit v1.2.3-59-g8ed1b From 42aad0d7f9486b72155892c689bea2ff9793d8a8 Mon Sep 17 00:00:00 2001 From: Chuck Lever Date: Tue, 12 May 2020 17:13:39 -0400 Subject: SUNRPC: trace RPC client lifetime events The "create" tracepoint records parts of the rpc_create arguments, and the shutdown tracepoint records when the rpc_clnt is about to signal pending tasks and destroy auths. Signed-off-by: Chuck Lever Signed-off-by: Anna Schumaker --- include/trace/events/sunrpc.h | 111 ++++++++++++++++++++++++++++++++++++++++++ net/sunrpc/clnt.c | 39 ++++++--------- 2 files changed, 126 insertions(+), 24 deletions(-) (limited to 'include/trace') diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h index fc8a969ba306..098c84750fb7 100644 --- a/include/trace/events/sunrpc.h +++ b/include/trace/events/sunrpc.h @@ -65,6 +65,117 @@ DEFINE_RPCXDRBUF_EVENT(recvfrom); DEFINE_RPCXDRBUF_EVENT(reply_pages); +DECLARE_EVENT_CLASS(rpc_clnt_class, + TP_PROTO( + const struct rpc_clnt *clnt + ), + + TP_ARGS(clnt), + + TP_STRUCT__entry( + __field(unsigned int, client_id) + ), + + TP_fast_assign( + __entry->client_id = clnt->cl_clid; + ), + + TP_printk("clid=%u", __entry->client_id) +); + +#define DEFINE_RPC_CLNT_EVENT(name) \ + DEFINE_EVENT(rpc_clnt_class, \ + rpc_clnt_##name, \ + TP_PROTO( \ + const struct rpc_clnt *clnt \ + ), \ + TP_ARGS(clnt)) + +DEFINE_RPC_CLNT_EVENT(free); +DEFINE_RPC_CLNT_EVENT(killall); +DEFINE_RPC_CLNT_EVENT(shutdown); +DEFINE_RPC_CLNT_EVENT(release); +DEFINE_RPC_CLNT_EVENT(replace_xprt); +DEFINE_RPC_CLNT_EVENT(replace_xprt_err); + +TRACE_EVENT(rpc_clnt_new, + TP_PROTO( + const struct rpc_clnt *clnt, + const struct rpc_xprt *xprt, + const char *program, + const char *server + ), + + TP_ARGS(clnt, xprt, program, server), + + TP_STRUCT__entry( + __field(unsigned int, client_id) + __string(addr, xprt->address_strings[RPC_DISPLAY_ADDR]) + __string(port, xprt->address_strings[RPC_DISPLAY_PORT]) + __string(program, program) + __string(server, server) + ), + + TP_fast_assign( + __entry->client_id = clnt->cl_clid; + __assign_str(addr, xprt->address_strings[RPC_DISPLAY_ADDR]); + __assign_str(port, xprt->address_strings[RPC_DISPLAY_PORT]); + __assign_str(program, program) + __assign_str(server, server) + ), + + TP_printk("client=%u peer=[%s]:%s program=%s server=%s", + __entry->client_id, __get_str(addr), __get_str(port), + __get_str(program), __get_str(server)) +); + +TRACE_EVENT(rpc_clnt_new_err, + TP_PROTO( + const char *program, + const char *server, + int error + ), + + TP_ARGS(program, server, error), + + TP_STRUCT__entry( + __field(int, error) + __string(program, program) + __string(server, server) + ), + + TP_fast_assign( + __entry->error = error; + __assign_str(program, program) + __assign_str(server, server) + ), + + TP_printk("program=%s server=%s error=%d", + __get_str(program), __get_str(server), __entry->error) +); + +TRACE_EVENT(rpc_clnt_clone_err, + TP_PROTO( + const struct rpc_clnt *clnt, + int error + ), + + TP_ARGS(clnt, error), + + TP_STRUCT__entry( + __field(unsigned int, client_id) + __field(int, error) + ), + + TP_fast_assign( + __entry->client_id = clnt->cl_clid; + __entry->error = error; + ), + + TP_printk("client=%u error=%d", __entry->client_id, __entry->error) +); + + TRACE_DEFINE_ENUM(RPC_AUTH_OK); TRACE_DEFINE_ENUM(RPC_AUTH_BADCRED); TRACE_DEFINE_ENUM(RPC_AUTH_REJECTEDCRED); diff --git a/net/sunrpc/clnt.c b/net/sunrpc/clnt.c index 0e684d93c9b1..4614a6eebfe1 100644 --- a/net/sunrpc/clnt.c +++ b/net/sunrpc/clnt.c @@ -370,10 +370,6 @@ static struct rpc_clnt * rpc_new_client(const struct rpc_create_args *args, const char *nodename = args->nodename; int err; - /* sanity check the name before trying to print it */ - dprintk("RPC: creating %s client for %s (xprt %p)\n", - program->name, args->servername, xprt); - err = rpciod_up(); if (err) goto out_no_rpciod; @@ -436,6 +432,8 @@ static struct rpc_clnt * rpc_new_client(const struct rpc_create_args *args, goto out_no_path; if (parent) atomic_inc(&parent->cl_count); + + trace_rpc_clnt_new(clnt, xprt, program->name, args->servername); return clnt; out_no_path: @@ -450,6 +448,7 @@ out_err: out_no_rpciod: xprt_switch_put(xps); xprt_put(xprt); + trace_rpc_clnt_new_err(program->name, args->servername, err); return ERR_PTR(err); } @@ -634,10 +633,8 @@ static struct rpc_clnt *__rpc_clone_client(struct rpc_create_args *args, args->nodename = clnt->cl_nodename; new = rpc_new_client(args, xps, xprt, clnt); - if (IS_ERR(new)) { - err = PTR_ERR(new); - goto out_err; - } + if (IS_ERR(new)) + return new; /* Turn off autobind on clones */ new->cl_autobind = 0; @@ -650,7 +647,7 @@ static struct rpc_clnt *__rpc_clone_client(struct rpc_create_args *args, return new; out_err: - dprintk("RPC: %s: returned error %d\n", __func__, err); + trace_rpc_clnt_clone_err(clnt, err); return ERR_PTR(err); } @@ -723,11 +720,8 @@ int rpc_switch_client_transport(struct rpc_clnt *clnt, int err; xprt = xprt_create_transport(args); - if (IS_ERR(xprt)) { - dprintk("RPC: failed to create new xprt for clnt %p\n", - clnt); + if (IS_ERR(xprt)) return PTR_ERR(xprt); - } xps = xprt_switch_alloc(xprt, GFP_KERNEL); if (xps == NULL) { @@ -767,7 +761,7 @@ int rpc_switch_client_transport(struct rpc_clnt *clnt, rpc_release_client(parent); xprt_switch_put(oldxps); xprt_put(old); - dprintk("RPC: replaced xprt for clnt %p\n", clnt); + trace_rpc_clnt_replace_xprt(clnt); return 0; out_revert: @@ -777,7 +771,7 @@ out_revert: rpc_client_register(clnt, pseudoflavor, NULL); xprt_switch_put(xps); xprt_put(xprt); - dprintk("RPC: failed to switch xprt for clnt %p\n", clnt); + trace_rpc_clnt_replace_xprt_err(clnt); return err; } EXPORT_SYMBOL_GPL(rpc_switch_client_transport); @@ -844,10 +838,11 @@ void rpc_killall_tasks(struct rpc_clnt *clnt) if (list_empty(&clnt->cl_tasks)) return; - dprintk("RPC: killing all tasks for client %p\n", clnt); + /* * Spin lock all_tasks to prevent changes... */ + trace_rpc_clnt_killall(clnt); spin_lock(&clnt->cl_lock); list_for_each_entry(rovr, &clnt->cl_tasks, tk_task) rpc_signal_task(rovr); @@ -863,9 +858,7 @@ void rpc_shutdown_client(struct rpc_clnt *clnt) { might_sleep(); - dprintk_rcu("RPC: shutting down %s client for %s\n", - clnt->cl_program->name, - rcu_dereference(clnt->cl_xprt)->servername); + trace_rpc_clnt_shutdown(clnt); while (!list_empty(&clnt->cl_tasks)) { rpc_killall_tasks(clnt); @@ -884,6 +877,8 @@ static void rpc_free_client_work(struct work_struct *work) { struct rpc_clnt *clnt = container_of(work, struct rpc_clnt, cl_work); + trace_rpc_clnt_free(clnt); + /* These might block on processes that might allocate memory, * so they cannot be called in rpciod, so they are handled separately * here. @@ -901,9 +896,7 @@ rpc_free_client(struct rpc_clnt *clnt) { struct rpc_clnt *parent = NULL; - dprintk_rcu("RPC: destroying %s client for %s\n", - clnt->cl_program->name, - rcu_dereference(clnt->cl_xprt)->servername); + trace_rpc_clnt_release(clnt); if (clnt->cl_parent != clnt) parent = clnt->cl_parent; rpc_unregister_client(clnt); @@ -945,8 +938,6 @@ rpc_free_auth(struct rpc_clnt *clnt) void rpc_release_client(struct rpc_clnt *clnt) { - dprintk("RPC: rpc_release_client(%p)\n", clnt); - do { if (list_empty(&clnt->cl_tasks)) wake_up(&destroy_wait); -- cgit v1.2.3-59-g8ed1b From 94afd9c489fe6720ea3f49084125344e22610880 Mon Sep 17 00:00:00 2001 From: Chuck Lever Date: Mon, 18 May 2020 10:13:02 -0400 Subject: SUNRPC: rpc_xprt lifetime events should record xprt->state Help troubleshoot the logic that uses these flags. Signed-off-by: Chuck Lever Signed-off-by: Anna Schumaker --- include/trace/events/sunrpc.h | 30 +++++++++++++++++++++++++++++- 1 file changed, 29 insertions(+), 1 deletion(-) (limited to 'include/trace') diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h index 098c84750fb7..73193c79fcaa 100644 --- a/include/trace/events/sunrpc.h +++ b/include/trace/events/sunrpc.h @@ -835,6 +835,30 @@ DEFINE_RPC_SOCKET_EVENT_DONE(rpc_socket_reset_connection); DEFINE_RPC_SOCKET_EVENT(rpc_socket_close); DEFINE_RPC_SOCKET_EVENT(rpc_socket_shutdown); +TRACE_DEFINE_ENUM(XPRT_LOCKED); +TRACE_DEFINE_ENUM(XPRT_CONNECTED); +TRACE_DEFINE_ENUM(XPRT_CONNECTING); +TRACE_DEFINE_ENUM(XPRT_CLOSE_WAIT); +TRACE_DEFINE_ENUM(XPRT_BOUND); +TRACE_DEFINE_ENUM(XPRT_BINDING); +TRACE_DEFINE_ENUM(XPRT_CLOSING); +TRACE_DEFINE_ENUM(XPRT_CONGESTED); +TRACE_DEFINE_ENUM(XPRT_CWND_WAIT); +TRACE_DEFINE_ENUM(XPRT_WRITE_SPACE); + +#define rpc_show_xprt_state(x) \ + __print_flags(x, "|", \ + { (1UL << XPRT_LOCKED), "LOCKED"}, \ + { (1UL << XPRT_CONNECTED), "CONNECTED"}, \ + { (1UL << XPRT_CONNECTING), "CONNECTING"}, \ + { (1UL << XPRT_CLOSE_WAIT), "CLOSE_WAIT"}, \ + { (1UL << XPRT_BOUND), "BOUND"}, \ + { (1UL << XPRT_BINDING), "BINDING"}, \ + { (1UL << XPRT_CLOSING), "CLOSING"}, \ + { (1UL << XPRT_CONGESTED), "CONGESTED"}, \ + { (1UL << XPRT_CWND_WAIT), "CWND_WAIT"}, \ + { (1UL << XPRT_WRITE_SPACE), "WRITE_SPACE"}) + DECLARE_EVENT_CLASS(rpc_xprt_lifetime_class, TP_PROTO( const struct rpc_xprt *xprt @@ -843,16 +867,20 @@ DECLARE_EVENT_CLASS(rpc_xprt_lifetime_class, TP_ARGS(xprt), TP_STRUCT__entry( + __field(unsigned long, state) __string(addr, xprt->address_strings[RPC_DISPLAY_ADDR]) __string(port, xprt->address_strings[RPC_DISPLAY_PORT]) ), TP_fast_assign( + __entry->state = xprt->state; __assign_str(addr, xprt->address_strings[RPC_DISPLAY_ADDR]); __assign_str(port, xprt->address_strings[RPC_DISPLAY_PORT]); ), - TP_printk("peer=[%s]:%s", __get_str(addr), __get_str(port)) + TP_printk("peer=[%s]:%s state=%s", + __get_str(addr), __get_str(port), + rpc_show_xprt_state(__entry->state)) ); #define DEFINE_RPC_XPRT_LIFETIME_EVENT(name) \ -- cgit v1.2.3-59-g8ed1b