From 6ceea36890a01aa626ce08487eecc5fb43e749b1 Mon Sep 17 00:00:00 2001 From: Chuck Lever Date: Wed, 19 Dec 2018 10:58:24 -0500 Subject: xprtrdma: Refactor Receive accounting Clean up: Divide the work cleanly: - rpcrdma_wc_receive is responsible only for RDMA Receives - rpcrdma_reply_handler is responsible only for RPC Replies - the posted send and receive counts both belong in rpcrdma_ep Signed-off-by: Chuck Lever Signed-off-by: Anna Schumaker --- include/trace/events/rpcrdma.h | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) (limited to 'include/trace') diff --git a/include/trace/events/rpcrdma.h b/include/trace/events/rpcrdma.h index b093058f78aa..2efe2d7d6683 100644 --- a/include/trace/events/rpcrdma.h +++ b/include/trace/events/rpcrdma.h @@ -570,7 +570,7 @@ TRACE_EVENT(xprtrdma_post_recvs, __entry->r_xprt = r_xprt; __entry->count = count; __entry->status = status; - __entry->posted = r_xprt->rx_buf.rb_posted_receives; + __entry->posted = r_xprt->rx_ep.rep_receive_count; __assign_str(addr, rpcrdma_addrstr(r_xprt)); __assign_str(port, rpcrdma_portstr(r_xprt)); ), -- cgit v1.2.3-59-g8ed1b From aba11831794356ff58da69de46a125e6335eb9ca Mon Sep 17 00:00:00 2001 From: Chuck Lever Date: Wed, 19 Dec 2018 10:59:49 -0500 Subject: xprtrdma: Clean up of xprtrdma chunk trace points The chunk-related trace points capture nearly the same information as the MR-related trace points. Also, rename them so globbing can be used to enable or disable these trace points more easily. Signed-off-by: Chuck Lever Signed-off-by: Anna Schumaker --- include/trace/events/rpcrdma.h | 42 ++++++++++++++++++++++++++---------------- net/sunrpc/xprtrdma/rpc_rdma.c | 6 +++--- 2 files changed, 29 insertions(+), 19 deletions(-) (limited to 'include/trace') diff --git a/include/trace/events/rpcrdma.h b/include/trace/events/rpcrdma.h index 2efe2d7d6683..e9fbf7dbc16f 100644 --- a/include/trace/events/rpcrdma.h +++ b/include/trace/events/rpcrdma.h @@ -97,7 +97,6 @@ DECLARE_EVENT_CLASS(xprtrdma_rdch_event, TP_STRUCT__entry( __field(unsigned int, task_id) __field(unsigned int, client_id) - __field(const void *, mr) __field(unsigned int, pos) __field(int, nents) __field(u32, handle) @@ -109,7 +108,6 @@ DECLARE_EVENT_CLASS(xprtrdma_rdch_event, TP_fast_assign( __entry->task_id = task->tk_pid; __entry->client_id = task->tk_client->cl_clid; - __entry->mr = mr; __entry->pos = pos; __entry->nents = mr->mr_nents; __entry->handle = mr->mr_handle; @@ -118,8 +116,8 @@ DECLARE_EVENT_CLASS(xprtrdma_rdch_event, __entry->nsegs = nsegs; ), - TP_printk("task:%u@%u mr=%p pos=%u %u@0x%016llx:0x%08x (%s)", - __entry->task_id, __entry->client_id, __entry->mr, + TP_printk("task:%u@%u pos=%u %u@0x%016llx:0x%08x (%s)", + __entry->task_id, __entry->client_id, __entry->pos, __entry->length, (unsigned long long)__entry->offset, __entry->handle, __entry->nents < __entry->nsegs ? "more" : "last" @@ -127,7 +125,7 @@ DECLARE_EVENT_CLASS(xprtrdma_rdch_event, ); #define DEFINE_RDCH_EVENT(name) \ - DEFINE_EVENT(xprtrdma_rdch_event, name, \ + DEFINE_EVENT(xprtrdma_rdch_event, xprtrdma_chunk_##name,\ TP_PROTO( \ const struct rpc_task *task, \ unsigned int pos, \ @@ -148,7 +146,6 @@ DECLARE_EVENT_CLASS(xprtrdma_wrch_event, TP_STRUCT__entry( __field(unsigned int, task_id) __field(unsigned int, client_id) - __field(const void *, mr) __field(int, nents) __field(u32, handle) __field(u32, length) @@ -159,7 +156,6 @@ DECLARE_EVENT_CLASS(xprtrdma_wrch_event, TP_fast_assign( __entry->task_id = task->tk_pid; __entry->client_id = task->tk_client->cl_clid; - __entry->mr = mr; __entry->nents = mr->mr_nents; __entry->handle = mr->mr_handle; __entry->length = mr->mr_length; @@ -167,8 +163,8 @@ DECLARE_EVENT_CLASS(xprtrdma_wrch_event, __entry->nsegs = nsegs; ), - TP_printk("task:%u@%u mr=%p %u@0x%016llx:0x%08x (%s)", - __entry->task_id, __entry->client_id, __entry->mr, + TP_printk("task:%u@%u %u@0x%016llx:0x%08x (%s)", + __entry->task_id, __entry->client_id, __entry->length, (unsigned long long)__entry->offset, __entry->handle, __entry->nents < __entry->nsegs ? "more" : "last" @@ -176,7 +172,7 @@ DECLARE_EVENT_CLASS(xprtrdma_wrch_event, ); #define DEFINE_WRCH_EVENT(name) \ - DEFINE_EVENT(xprtrdma_wrch_event, name, \ + DEFINE_EVENT(xprtrdma_wrch_event, xprtrdma_chunk_##name,\ TP_PROTO( \ const struct rpc_task *task, \ struct rpcrdma_mr *mr, \ @@ -234,6 +230,18 @@ DECLARE_EVENT_CLASS(xprtrdma_frwr_done, ), \ TP_ARGS(wc, frwr)) +TRACE_DEFINE_ENUM(DMA_BIDIRECTIONAL); +TRACE_DEFINE_ENUM(DMA_TO_DEVICE); +TRACE_DEFINE_ENUM(DMA_FROM_DEVICE); +TRACE_DEFINE_ENUM(DMA_NONE); + +#define xprtrdma_show_direction(x) \ + __print_symbolic(x, \ + { DMA_BIDIRECTIONAL, "BIDIR" }, \ + { DMA_TO_DEVICE, "TO_DEVICE" }, \ + { DMA_FROM_DEVICE, "FROM_DEVICE" }, \ + { DMA_NONE, "NONE" }) + DECLARE_EVENT_CLASS(xprtrdma_mr, TP_PROTO( const struct rpcrdma_mr *mr @@ -246,6 +254,7 @@ DECLARE_EVENT_CLASS(xprtrdma_mr, __field(u32, handle) __field(u32, length) __field(u64, offset) + __field(u32, dir) ), TP_fast_assign( @@ -253,12 +262,13 @@ DECLARE_EVENT_CLASS(xprtrdma_mr, __entry->handle = mr->mr_handle; __entry->length = mr->mr_length; __entry->offset = mr->mr_offset; + __entry->dir = mr->mr_dir; ), - TP_printk("mr=%p %u@0x%016llx:0x%08x", + TP_printk("mr=%p %u@0x%016llx:0x%08x (%s)", __entry->mr, __entry->length, - (unsigned long long)__entry->offset, - __entry->handle + (unsigned long long)__entry->offset, __entry->handle, + xprtrdma_show_direction(__entry->dir) ) ); @@ -437,9 +447,9 @@ TRACE_EVENT(xprtrdma_createmrs, DEFINE_RXPRT_EVENT(xprtrdma_nomrs); -DEFINE_RDCH_EVENT(xprtrdma_read_chunk); -DEFINE_WRCH_EVENT(xprtrdma_write_chunk); -DEFINE_WRCH_EVENT(xprtrdma_reply_chunk); +DEFINE_RDCH_EVENT(read); +DEFINE_WRCH_EVENT(write); +DEFINE_WRCH_EVENT(reply); TRACE_DEFINE_ENUM(rpcrdma_noch); TRACE_DEFINE_ENUM(rpcrdma_readch); diff --git a/net/sunrpc/xprtrdma/rpc_rdma.c b/net/sunrpc/xprtrdma/rpc_rdma.c index 5a587698c885..54fbd70c661c 100644 --- a/net/sunrpc/xprtrdma/rpc_rdma.c +++ b/net/sunrpc/xprtrdma/rpc_rdma.c @@ -365,7 +365,7 @@ rpcrdma_encode_read_list(struct rpcrdma_xprt *r_xprt, struct rpcrdma_req *req, if (encode_read_segment(xdr, mr, pos) < 0) return -EMSGSIZE; - trace_xprtrdma_read_chunk(rqst->rq_task, pos, mr, nsegs); + trace_xprtrdma_chunk_read(rqst->rq_task, pos, mr, nsegs); r_xprt->rx_stats.read_chunk_count++; nsegs -= mr->mr_nents; } while (nsegs); @@ -422,7 +422,7 @@ rpcrdma_encode_write_list(struct rpcrdma_xprt *r_xprt, struct rpcrdma_req *req, if (encode_rdma_segment(xdr, mr) < 0) return -EMSGSIZE; - trace_xprtrdma_write_chunk(rqst->rq_task, mr, nsegs); + trace_xprtrdma_chunk_write(rqst->rq_task, mr, nsegs); r_xprt->rx_stats.write_chunk_count++; r_xprt->rx_stats.total_rdma_request += mr->mr_length; nchunks++; @@ -479,7 +479,7 @@ rpcrdma_encode_reply_chunk(struct rpcrdma_xprt *r_xprt, struct rpcrdma_req *req, if (encode_rdma_segment(xdr, mr) < 0) return -EMSGSIZE; - trace_xprtrdma_reply_chunk(rqst->rq_task, mr, nsegs); + trace_xprtrdma_chunk_reply(rqst->rq_task, mr, nsegs); r_xprt->rx_stats.reply_chunk_count++; r_xprt->rx_stats.total_rdma_request += mr->mr_length; nchunks++; -- cgit v1.2.3-59-g8ed1b From 395069fc37e7a76280b176c0327d1ead6ca29838 Mon Sep 17 00:00:00 2001 From: Chuck Lever Date: Wed, 19 Dec 2018 11:00:00 -0500 Subject: xprtrdma: Add trace points for calls to transport switch methods Name them "trace_xprtrdma_op_*" so they can be easily enabled as a group. No trace point is added where the generic layer already has observability. Signed-off-by: Chuck Lever Signed-off-by: Anna Schumaker --- include/trace/events/rpcrdma.h | 10 ++++++---- net/sunrpc/xprtrdma/transport.c | 18 +++++++++++------- 2 files changed, 17 insertions(+), 11 deletions(-) (limited to 'include/trace') diff --git a/include/trace/events/rpcrdma.h b/include/trace/events/rpcrdma.h index e9fbf7dbc16f..3d068bba4532 100644 --- a/include/trace/events/rpcrdma.h +++ b/include/trace/events/rpcrdma.h @@ -381,11 +381,13 @@ TRACE_EVENT(xprtrdma_disconnect, 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_op_destroy); DEFINE_RXPRT_EVENT(xprtrdma_remove); DEFINE_RXPRT_EVENT(xprtrdma_reinsert); DEFINE_RXPRT_EVENT(xprtrdma_reconnect); -DEFINE_RXPRT_EVENT(xprtrdma_inject_dsc); +DEFINE_RXPRT_EVENT(xprtrdma_op_inject_dsc); +DEFINE_RXPRT_EVENT(xprtrdma_op_close); +DEFINE_RXPRT_EVENT(xprtrdma_op_connect); TRACE_EVENT(xprtrdma_qp_event, TP_PROTO( @@ -834,7 +836,7 @@ TRACE_EVENT(xprtrdma_decode_seg, ** Allocation/release of rpcrdma_reqs and rpcrdma_reps **/ -TRACE_EVENT(xprtrdma_allocate, +TRACE_EVENT(xprtrdma_op_allocate, TP_PROTO( const struct rpc_task *task, const struct rpcrdma_req *req @@ -864,7 +866,7 @@ TRACE_EVENT(xprtrdma_allocate, ) ); -TRACE_EVENT(xprtrdma_rpc_done, +TRACE_EVENT(xprtrdma_op_free, TP_PROTO( const struct rpc_task *task, const struct rpcrdma_req *req diff --git a/net/sunrpc/xprtrdma/transport.c b/net/sunrpc/xprtrdma/transport.c index 6a57033a5846..d94da3c57593 100644 --- a/net/sunrpc/xprtrdma/transport.c +++ b/net/sunrpc/xprtrdma/transport.c @@ -268,7 +268,7 @@ xprt_rdma_inject_disconnect(struct rpc_xprt *xprt) { struct rpcrdma_xprt *r_xprt = rpcx_to_rdmax(xprt); - trace_xprtrdma_inject_dsc(r_xprt); + trace_xprtrdma_op_inject_dsc(r_xprt); rdma_disconnect(r_xprt->rx_ia.ri_id); } @@ -284,7 +284,7 @@ xprt_rdma_destroy(struct rpc_xprt *xprt) { struct rpcrdma_xprt *r_xprt = rpcx_to_rdmax(xprt); - trace_xprtrdma_destroy(r_xprt); + trace_xprtrdma_op_destroy(r_xprt); cancel_delayed_work_sync(&r_xprt->rx_connect_worker); @@ -418,7 +418,7 @@ out3: out2: rpcrdma_ia_close(&new_xprt->rx_ia); out1: - trace_xprtrdma_destroy(new_xprt); + trace_xprtrdma_op_destroy(new_xprt); xprt_rdma_free_addresses(xprt); xprt_free(xprt); return ERR_PTR(rc); @@ -428,7 +428,8 @@ out1: * xprt_rdma_close - close a transport connection * @xprt: transport context * - * Called during transport shutdown, reconnect, or device removal. + * Called during autoclose or device removal. + * * Caller holds @xprt's send lock to prevent activity on this * transport while the connection is torn down. */ @@ -440,6 +441,8 @@ void xprt_rdma_close(struct rpc_xprt *xprt) might_sleep(); + trace_xprtrdma_op_close(r_xprt); + /* Prevent marshaling and sending of new requests */ xprt_clear_connected(xprt); @@ -525,6 +528,7 @@ xprt_rdma_connect(struct rpc_xprt *xprt, struct rpc_task *task) { struct rpcrdma_xprt *r_xprt = rpcx_to_rdmax(xprt); + trace_xprtrdma_op_connect(r_xprt); if (r_xprt->rx_ep.rep_connected != 0) { /* Reconnect */ schedule_delayed_work(&r_xprt->rx_connect_worker, @@ -659,11 +663,11 @@ xprt_rdma_allocate(struct rpc_task *task) rqst->rq_buffer = req->rl_sendbuf->rg_base; rqst->rq_rbuffer = req->rl_recvbuf->rg_base; - trace_xprtrdma_allocate(task, req); + trace_xprtrdma_op_allocate(task, req); return 0; out_fail: - trace_xprtrdma_allocate(task, NULL); + trace_xprtrdma_op_allocate(task, NULL); return -ENOMEM; } @@ -682,7 +686,7 @@ xprt_rdma_free(struct rpc_task *task) if (test_bit(RPCRDMA_REQ_F_PENDING, &req->rl_flags)) rpcrdma_release_rqst(r_xprt, req); - trace_xprtrdma_rpc_done(task, req); + trace_xprtrdma_op_free(task, req); } /** -- cgit v1.2.3-59-g8ed1b From 53b2c1cb9b3cd901a200ddbbf08c77eabf1ab3e9 Mon Sep 17 00:00:00 2001 From: Chuck Lever Date: Wed, 19 Dec 2018 11:00:06 -0500 Subject: xprtrdma: Trace mapping, alloc, and dereg failures These are rare, but can be helpful at tracking down DMAR and other problems. Signed-off-by: Chuck Lever Signed-off-by: Anna Schumaker --- include/trace/events/rpcrdma.h | 136 +++++++++++++++++++++++++++++++++++++++++ net/sunrpc/xprtrdma/frwr_ops.c | 12 ++-- net/sunrpc/xprtrdma/rpc_rdma.c | 2 +- net/sunrpc/xprtrdma/verbs.c | 4 +- 4 files changed, 144 insertions(+), 10 deletions(-) (limited to 'include/trace') diff --git a/include/trace/events/rpcrdma.h b/include/trace/events/rpcrdma.h index 3d068bba4532..ce528d5942c5 100644 --- a/include/trace/events/rpcrdma.h +++ b/include/trace/events/rpcrdma.h @@ -10,6 +10,7 @@ #if !defined(_TRACE_RPCRDMA_H) || defined(TRACE_HEADER_MULTI_READ) #define _TRACE_RPCRDMA_H +#include #include #include @@ -663,12 +664,147 @@ DEFINE_FRWR_DONE_EVENT(xprtrdma_wc_fastreg); DEFINE_FRWR_DONE_EVENT(xprtrdma_wc_li); DEFINE_FRWR_DONE_EVENT(xprtrdma_wc_li_wake); +TRACE_EVENT(xprtrdma_frwr_alloc, + TP_PROTO( + const struct rpcrdma_mr *mr, + int rc + ), + + TP_ARGS(mr, rc), + + TP_STRUCT__entry( + __field(const void *, mr) + __field(int, rc) + ), + + TP_fast_assign( + __entry->mr = mr; + __entry->rc = rc; + ), + + TP_printk("mr=%p: rc=%d", + __entry->mr, __entry->rc + ) +); + +TRACE_EVENT(xprtrdma_frwr_dereg, + TP_PROTO( + const struct rpcrdma_mr *mr, + int rc + ), + + TP_ARGS(mr, rc), + + TP_STRUCT__entry( + __field(const void *, mr) + __field(u32, handle) + __field(u32, length) + __field(u64, offset) + __field(u32, dir) + __field(int, rc) + ), + + TP_fast_assign( + __entry->mr = mr; + __entry->handle = mr->mr_handle; + __entry->length = mr->mr_length; + __entry->offset = mr->mr_offset; + __entry->dir = mr->mr_dir; + __entry->rc = rc; + ), + + TP_printk("mr=%p %u@0x%016llx:0x%08x (%s): rc=%d", + __entry->mr, __entry->length, + (unsigned long long)__entry->offset, __entry->handle, + xprtrdma_show_direction(__entry->dir), + __entry->rc + ) +); + +TRACE_EVENT(xprtrdma_frwr_sgerr, + TP_PROTO( + const struct rpcrdma_mr *mr, + int sg_nents + ), + + TP_ARGS(mr, sg_nents), + + TP_STRUCT__entry( + __field(const void *, mr) + __field(u64, addr) + __field(u32, dir) + __field(int, nents) + ), + + TP_fast_assign( + __entry->mr = mr; + __entry->addr = mr->mr_sg->dma_address; + __entry->dir = mr->mr_dir; + __entry->nents = sg_nents; + ), + + TP_printk("mr=%p dma addr=0x%llx (%s) sg_nents=%d", + __entry->mr, __entry->addr, + xprtrdma_show_direction(__entry->dir), + __entry->nents + ) +); + +TRACE_EVENT(xprtrdma_frwr_maperr, + TP_PROTO( + const struct rpcrdma_mr *mr, + int num_mapped + ), + + TP_ARGS(mr, num_mapped), + + TP_STRUCT__entry( + __field(const void *, mr) + __field(u64, addr) + __field(u32, dir) + __field(int, num_mapped) + __field(int, nents) + ), + + TP_fast_assign( + __entry->mr = mr; + __entry->addr = mr->mr_sg->dma_address; + __entry->dir = mr->mr_dir; + __entry->num_mapped = num_mapped; + __entry->nents = mr->mr_nents; + ), + + TP_printk("mr=%p dma addr=0x%llx (%s) nents=%d of %d", + __entry->mr, __entry->addr, + xprtrdma_show_direction(__entry->dir), + __entry->num_mapped, __entry->nents + ) +); + DEFINE_MR_EVENT(localinv); DEFINE_MR_EVENT(map); DEFINE_MR_EVENT(unmap); DEFINE_MR_EVENT(remoteinv); DEFINE_MR_EVENT(recycle); +TRACE_EVENT(xprtrdma_dma_maperr, + TP_PROTO( + u64 addr + ), + + TP_ARGS(addr), + + TP_STRUCT__entry( + __field(u64, addr) + ), + + TP_fast_assign( + __entry->addr = addr; + ), + + TP_printk("dma addr=0x%llx\n", __entry->addr) +); + /** ** Reply events **/ diff --git a/net/sunrpc/xprtrdma/frwr_ops.c b/net/sunrpc/xprtrdma/frwr_ops.c index 1f508f4742f9..8a0f1a6e6927 100644 --- a/net/sunrpc/xprtrdma/frwr_ops.c +++ b/net/sunrpc/xprtrdma/frwr_ops.c @@ -113,8 +113,7 @@ void frwr_release_mr(struct rpcrdma_mr *mr) rc = ib_dereg_mr(mr->frwr.fr_mr); if (rc) - pr_err("rpcrdma: final ib_dereg_mr for %p returned %i\n", - mr, rc); + trace_xprtrdma_frwr_dereg(mr, rc); kfree(mr->mr_sg); kfree(mr); } @@ -177,8 +176,7 @@ int frwr_init_mr(struct rpcrdma_ia *ia, struct rpcrdma_mr *mr) out_mr_err: rc = PTR_ERR(frwr->fr_mr); - dprintk("RPC: %s: ib_alloc_mr status %i\n", - __func__, rc); + trace_xprtrdma_frwr_alloc(mr, rc); return rc; out_list_err: @@ -465,15 +463,13 @@ struct rpcrdma_mr_seg *frwr_map(struct rpcrdma_xprt *r_xprt, return seg; out_dmamap_err: - pr_err("rpcrdma: failed to DMA map sg %p sg_nents %d\n", - mr->mr_sg, i); frwr->fr_state = FRWR_IS_INVALID; + trace_xprtrdma_frwr_sgerr(mr, i); rpcrdma_mr_put(mr); return ERR_PTR(-EIO); out_mapmr_err: - pr_err("rpcrdma: failed to map mr %p (%d/%d)\n", - frwr->fr_mr, n, mr->mr_nents); + trace_xprtrdma_frwr_maperr(mr, n); rpcrdma_mr_recycle(mr); return ERR_PTR(-EIO); } diff --git a/net/sunrpc/xprtrdma/rpc_rdma.c b/net/sunrpc/xprtrdma/rpc_rdma.c index 54fbd70c661c..062aee97b070 100644 --- a/net/sunrpc/xprtrdma/rpc_rdma.c +++ b/net/sunrpc/xprtrdma/rpc_rdma.c @@ -665,7 +665,7 @@ out_mapping_overflow: out_mapping_err: rpcrdma_unmap_sendctx(sc); - pr_err("rpcrdma: Send mapping error\n"); + trace_xprtrdma_dma_maperr(sge[sge_no].addr); return false; } diff --git a/net/sunrpc/xprtrdma/verbs.c b/net/sunrpc/xprtrdma/verbs.c index 85c51b8c438d..719b69c8bb81 100644 --- a/net/sunrpc/xprtrdma/verbs.c +++ b/net/sunrpc/xprtrdma/verbs.c @@ -1392,8 +1392,10 @@ __rpcrdma_dma_map_regbuf(struct rpcrdma_ia *ia, struct rpcrdma_regbuf *rb) (void *)rb->rg_base, rdmab_length(rb), rb->rg_direction); - if (ib_dma_mapping_error(device, rdmab_addr(rb))) + if (ib_dma_mapping_error(device, rdmab_addr(rb))) { + trace_xprtrdma_dma_maperr(rdmab_addr(rb)); return false; + } rb->rg_device = device; rb->rg_iov.lkey = ia->ri_pd->local_dma_lkey; -- cgit v1.2.3-59-g8ed1b From dc5820bd21d84ee34770b0a1e2fca9378f8f7456 Mon Sep 17 00:00:00 2001 From: Chuck Lever Date: Wed, 19 Dec 2018 11:00:16 -0500 Subject: SUNRPC: Simplify defining common RPC trace events Clean up, no functional change is expected. Signed-off-by: Chuck Lever Signed-off-by: Anna Schumaker --- include/trace/events/sunrpc.h | 172 +++++++++++++++++------------------------- 1 file changed, 69 insertions(+), 103 deletions(-) (limited to 'include/trace') diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h index 28e384186c35..88bda93e8f90 100644 --- a/include/trace/events/sunrpc.h +++ b/include/trace/events/sunrpc.h @@ -16,40 +16,6 @@ DECLARE_EVENT_CLASS(rpc_task_status, - TP_PROTO(struct rpc_task *task), - - TP_ARGS(task), - - TP_STRUCT__entry( - __field(unsigned int, task_id) - __field(unsigned int, client_id) - __field(int, status) - ), - - TP_fast_assign( - __entry->task_id = task->tk_pid; - __entry->client_id = task->tk_client->cl_clid; - __entry->status = task->tk_status; - ), - - TP_printk("task:%u@%u status=%d", - __entry->task_id, __entry->client_id, - __entry->status) -); - -DEFINE_EVENT(rpc_task_status, rpc_call_status, - TP_PROTO(struct rpc_task *task), - - TP_ARGS(task) -); - -DEFINE_EVENT(rpc_task_status, rpc_bind_status, - TP_PROTO(struct rpc_task *task), - - TP_ARGS(task) -); - -TRACE_EVENT(rpc_connect_status, TP_PROTO(const struct rpc_task *task), TP_ARGS(task), @@ -70,6 +36,16 @@ TRACE_EVENT(rpc_connect_status, __entry->task_id, __entry->client_id, __entry->status) ); +#define DEFINE_RPC_STATUS_EVENT(name) \ + DEFINE_EVENT(rpc_task_status, rpc_##name##_status, \ + TP_PROTO( \ + const struct rpc_task *task \ + ), \ + TP_ARGS(task)) + +DEFINE_RPC_STATUS_EVENT(call); +DEFINE_RPC_STATUS_EVENT(bind); +DEFINE_RPC_STATUS_EVENT(connect); TRACE_EVENT(rpc_request, TP_PROTO(const struct rpc_task *task), @@ -134,30 +110,17 @@ DECLARE_EVENT_CLASS(rpc_task_running, __entry->action ) ); +#define DEFINE_RPC_RUNNING_EVENT(name) \ + DEFINE_EVENT(rpc_task_running, rpc_task_##name, \ + TP_PROTO( \ + const struct rpc_task *task, \ + const void *action \ + ), \ + TP_ARGS(task, action)) -DEFINE_EVENT(rpc_task_running, rpc_task_begin, - - TP_PROTO(const struct rpc_task *task, const void *action), - - TP_ARGS(task, action) - -); - -DEFINE_EVENT(rpc_task_running, rpc_task_run_action, - - TP_PROTO(const struct rpc_task *task, const void *action), - - TP_ARGS(task, action) - -); - -DEFINE_EVENT(rpc_task_running, rpc_task_complete, - - TP_PROTO(const struct rpc_task *task, const void *action), - - TP_ARGS(task, action) - -); +DEFINE_RPC_RUNNING_EVENT(begin); +DEFINE_RPC_RUNNING_EVENT(run_action); +DEFINE_RPC_RUNNING_EVENT(complete); DECLARE_EVENT_CLASS(rpc_task_queued, @@ -195,22 +158,16 @@ DECLARE_EVENT_CLASS(rpc_task_queued, __get_str(q_name) ) ); +#define DEFINE_RPC_QUEUED_EVENT(name) \ + DEFINE_EVENT(rpc_task_queued, rpc_task_##name, \ + TP_PROTO( \ + const struct rpc_task *task, \ + const struct rpc_wait_queue *q \ + ), \ + TP_ARGS(task, q)) -DEFINE_EVENT(rpc_task_queued, rpc_task_sleep, - - TP_PROTO(const struct rpc_task *task, const struct rpc_wait_queue *q), - - TP_ARGS(task, q) - -); - -DEFINE_EVENT(rpc_task_queued, rpc_task_wakeup, - - TP_PROTO(const struct rpc_task *task, const struct rpc_wait_queue *q), - - TP_ARGS(task, q) - -); +DEFINE_RPC_QUEUED_EVENT(sleep); +DEFINE_RPC_QUEUED_EVENT(wakeup); TRACE_EVENT(rpc_stats_latency, @@ -410,7 +367,11 @@ DEFINE_RPC_SOCKET_EVENT(rpc_socket_close); DEFINE_RPC_SOCKET_EVENT(rpc_socket_shutdown); DECLARE_EVENT_CLASS(rpc_xprt_event, - TP_PROTO(struct rpc_xprt *xprt, __be32 xid, int status), + TP_PROTO( + const struct rpc_xprt *xprt, + __be32 xid, + int status + ), TP_ARGS(xprt, xid, status), @@ -432,22 +393,19 @@ DECLARE_EVENT_CLASS(rpc_xprt_event, __get_str(port), __entry->xid, __entry->status) ); +#define DEFINE_RPC_XPRT_EVENT(name) \ + DEFINE_EVENT(rpc_xprt_event, xprt_##name, \ + TP_PROTO( \ + const struct rpc_xprt *xprt, \ + __be32 xid, \ + int status \ + ), \ + TP_ARGS(xprt, xid, status)) -DEFINE_EVENT(rpc_xprt_event, xprt_timer, - TP_PROTO(struct rpc_xprt *xprt, __be32 xid, int status), - TP_ARGS(xprt, xid, status)); - -DEFINE_EVENT(rpc_xprt_event, xprt_lookup_rqst, - TP_PROTO(struct rpc_xprt *xprt, __be32 xid, int status), - TP_ARGS(xprt, xid, status)); - -DEFINE_EVENT(rpc_xprt_event, xprt_transmit, - TP_PROTO(struct rpc_xprt *xprt, __be32 xid, int status), - TP_ARGS(xprt, xid, status)); - -DEFINE_EVENT(rpc_xprt_event, xprt_complete_rqst, - TP_PROTO(struct rpc_xprt *xprt, __be32 xid, int status), - TP_ARGS(xprt, xid, status)); +DEFINE_RPC_XPRT_EVENT(timer); +DEFINE_RPC_XPRT_EVENT(lookup_rqst); +DEFINE_RPC_XPRT_EVENT(transmit); +DEFINE_RPC_XPRT_EVENT(complete_rqst); TRACE_EVENT(xprt_ping, TP_PROTO(const struct rpc_xprt *xprt, int status), @@ -587,7 +545,9 @@ TRACE_EVENT(svc_process, DECLARE_EVENT_CLASS(svc_rqst_event, - TP_PROTO(struct svc_rqst *rqst), + TP_PROTO( + const struct svc_rqst *rqst + ), TP_ARGS(rqst), @@ -607,14 +567,15 @@ DECLARE_EVENT_CLASS(svc_rqst_event, __get_str(addr), __entry->xid, show_rqstp_flags(__entry->flags)) ); +#define DEFINE_SVC_RQST_EVENT(name) \ + DEFINE_EVENT(svc_rqst_event, svc_##name, \ + TP_PROTO( \ + const struct svc_rqst *rqst \ + ), \ + TP_ARGS(rqst)) -DEFINE_EVENT(svc_rqst_event, svc_defer, - TP_PROTO(struct svc_rqst *rqst), - TP_ARGS(rqst)); - -DEFINE_EVENT(svc_rqst_event, svc_drop, - TP_PROTO(struct svc_rqst *rqst), - TP_ARGS(rqst)); +DEFINE_SVC_RQST_EVENT(defer); +DEFINE_SVC_RQST_EVENT(drop); DECLARE_EVENT_CLASS(svc_rqst_status, @@ -801,7 +762,9 @@ TRACE_EVENT(svc_stats_latency, ); DECLARE_EVENT_CLASS(svc_deferred_event, - TP_PROTO(struct svc_deferred_req *dr), + TP_PROTO( + const struct svc_deferred_req *dr + ), TP_ARGS(dr), @@ -818,13 +781,16 @@ DECLARE_EVENT_CLASS(svc_deferred_event, TP_printk("addr=%s xid=0x%08x", __get_str(addr), __entry->xid) ); +#define DEFINE_SVC_DEFERRED_EVENT(name) \ + DEFINE_EVENT(svc_deferred_event, svc_##name##_deferred, \ + TP_PROTO( \ + const struct svc_deferred_req *dr \ + ), \ + TP_ARGS(dr)) + +DEFINE_SVC_DEFERRED_EVENT(drop); +DEFINE_SVC_DEFERRED_EVENT(revisit); -DEFINE_EVENT(svc_deferred_event, svc_drop_deferred, - TP_PROTO(struct svc_deferred_req *dr), - TP_ARGS(dr)); -DEFINE_EVENT(svc_deferred_event, svc_revisit_deferred, - TP_PROTO(struct svc_deferred_req *dr), - TP_ARGS(dr)); #endif /* _TRACE_SUNRPC_H */ #include -- cgit v1.2.3-59-g8ed1b From 07e10308ee5da8e6132e0b737ece1c99dd651fb6 Mon Sep 17 00:00:00 2001 From: Chuck Lever Date: Fri, 7 Dec 2018 11:11:44 -0500 Subject: xprtrdma: Prevent leak of rpcrdma_rep objects If a reply has been processed but the RPC is later retransmitted anyway, the req->rl_reply field still contains the only pointer to the old rpcrdma rep. When the next reply comes in, the reply handler will stomp on the rl_reply field, leaking the old rep. A trace event is added to capture such leaks. This problem seems to be worsened by the restructuring of the RPC Call path in v4.20. Fully addressing this issue will require at least a re-architecture of the disconnect logic, which is not appropriate during -rc. Signed-off-by: Chuck Lever Signed-off-by: Anna Schumaker --- include/trace/events/rpcrdma.h | 28 ++++++++++++++++++++++++++++ net/sunrpc/xprtrdma/rpc_rdma.c | 4 ++++ 2 files changed, 32 insertions(+) (limited to 'include/trace') diff --git a/include/trace/events/rpcrdma.h b/include/trace/events/rpcrdma.h index ce528d5942c5..399b1aedc927 100644 --- a/include/trace/events/rpcrdma.h +++ b/include/trace/events/rpcrdma.h @@ -1065,6 +1065,34 @@ TRACE_EVENT(xprtrdma_cb_setup, DEFINE_CB_EVENT(xprtrdma_cb_call); DEFINE_CB_EVENT(xprtrdma_cb_reply); +TRACE_EVENT(xprtrdma_leaked_rep, + TP_PROTO( + const struct rpc_rqst *rqst, + const struct rpcrdma_rep *rep + ), + + TP_ARGS(rqst, rep), + + TP_STRUCT__entry( + __field(unsigned int, task_id) + __field(unsigned int, client_id) + __field(u32, xid) + __field(const void *, rep) + ), + + TP_fast_assign( + __entry->task_id = rqst->rq_task->tk_pid; + __entry->client_id = rqst->rq_task->tk_client->cl_clid; + __entry->xid = be32_to_cpu(rqst->rq_xid); + __entry->rep = rep; + ), + + TP_printk("task:%u@%u xid=0x%08x rep=%p", + __entry->task_id, __entry->client_id, __entry->xid, + __entry->rep + ) +); + /** ** Server-side RPC/RDMA events **/ diff --git a/net/sunrpc/xprtrdma/rpc_rdma.c b/net/sunrpc/xprtrdma/rpc_rdma.c index 062aee97b070..d18614e02b4e 100644 --- a/net/sunrpc/xprtrdma/rpc_rdma.c +++ b/net/sunrpc/xprtrdma/rpc_rdma.c @@ -1350,6 +1350,10 @@ void rpcrdma_reply_handler(struct rpcrdma_rep *rep) } req = rpcr_to_rdmar(rqst); + if (req->rl_reply) { + trace_xprtrdma_leaked_rep(rqst, req->rl_reply); + rpcrdma_recv_buffer_put(req->rl_reply); + } req->rl_reply = rep; rep->rr_rqst = rqst; clear_bit(RPCRDMA_REQ_F_PENDING, &req->rl_flags); -- cgit v1.2.3-59-g8ed1b