diff options
author | Chuck Lever <chuck.lever@oracle.com> | 2019-12-18 15:18:15 -0500 |
---|---|---|
committer | Jason Gunthorpe <jgg@mellanox.com> | 2020-01-07 16:10:53 -0400 |
commit | 3e5901cbfcc15da54f6ad148add754e7a2b2a558 (patch) | |
tree | ab59d8ab2fc14697c490c01e219466f5a8ba4227 /include/trace/events/rdma_core.h | |
parent | ed999f820a6c579298b53270656a0a26c8a6cb87 (diff) | |
download | linux-stable-3e5901cbfcc15da54f6ad148add754e7a2b2a558.tar.gz linux-stable-3e5901cbfcc15da54f6ad148add754e7a2b2a558.tar.bz2 linux-stable-3e5901cbfcc15da54f6ad148add754e7a2b2a558.zip |
RDMA/core: Trace points for diagnosing completion queue issues
Sample trace events:
kworker/u29:0-300 [007] 120.042217: cq_alloc: cq.id=4 nr_cqe=161 comp_vector=2 poll_ctx=WORKQUEUE
<idle>-0 [002] 120.056292: cq_schedule: cq.id=4
kworker/2:1H-482 [002] 120.056402: cq_process: cq.id=4 wake-up took 109 [us] from interrupt
kworker/2:1H-482 [002] 120.056407: cq_poll: cq.id=4 requested 16, returned 1
<idle>-0 [002] 120.067503: cq_schedule: cq.id=4
kworker/2:1H-482 [002] 120.067537: cq_process: cq.id=4 wake-up took 34 [us] from interrupt
kworker/2:1H-482 [002] 120.067541: cq_poll: cq.id=4 requested 16, returned 1
<idle>-0 [002] 120.067657: cq_schedule: cq.id=4
kworker/2:1H-482 [002] 120.067672: cq_process: cq.id=4 wake-up took 15 [us] from interrupt
kworker/2:1H-482 [002] 120.067674: cq_poll: cq.id=4 requested 16, returned 1
...
systemd-1 [002] 122.392653: cq_schedule: cq.id=4
kworker/2:1H-482 [002] 122.392688: cq_process: cq.id=4 wake-up took 35 [us] from interrupt
kworker/2:1H-482 [002] 122.392693: cq_poll: cq.id=4 requested 16, returned 16
kworker/2:1H-482 [002] 122.392836: cq_poll: cq.id=4 requested 16, returned 16
kworker/2:1H-482 [002] 122.392970: cq_poll: cq.id=4 requested 16, returned 16
kworker/2:1H-482 [002] 122.393083: cq_poll: cq.id=4 requested 16, returned 16
kworker/2:1H-482 [002] 122.393195: cq_poll: cq.id=4 requested 16, returned 3
Several features to note in this output:
- The WCE count and context type are reported at allocation time
- The CPU and kworker for each CQ is evident
- The CQ's restracker ID is tagged on each trace event
- CQ poll scheduling latency is measured
- Details about how often single completions occur versus multiple
completions are evident
- The cost of the ULP's completion handler is recorded
Link: https://lore.kernel.org/r/20191218201815.30584.3481.stgit@manet.1015granger.net
Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
Reviewed-by: Parav Pandit <parav@mellanox.com>
Signed-off-by: Jason Gunthorpe <jgg@mellanox.com>
Diffstat (limited to 'include/trace/events/rdma_core.h')
-rw-r--r-- | include/trace/events/rdma_core.h | 271 |
1 files changed, 271 insertions, 0 deletions
diff --git a/include/trace/events/rdma_core.h b/include/trace/events/rdma_core.h new file mode 100644 index 000000000000..08f481554e7f --- /dev/null +++ b/include/trace/events/rdma_core.h @@ -0,0 +1,271 @@ +/* SPDX-License-Identifier: GPL-2.0-only */ +/* + * Trace point definitions for core RDMA functions. + * + * Author: Chuck Lever <chuck.lever@oracle.com> + * + * Copyright (c) 2019, Oracle and/or its affiliates. All rights reserved. + */ + +#undef TRACE_SYSTEM +#define TRACE_SYSTEM rdma_core + +#if !defined(_TRACE_RDMA_CORE_H) || defined(TRACE_HEADER_MULTI_READ) +#define _TRACE_RDMA_CORE_H + +#include <linux/tracepoint.h> +#include <rdma/ib_verbs.h> + +/* + * enum ib_poll_context, from include/rdma/ib_verbs.h + */ +#define IB_POLL_CTX_LIST \ + ib_poll_ctx(DIRECT) \ + ib_poll_ctx(SOFTIRQ) \ + ib_poll_ctx(WORKQUEUE) \ + ib_poll_ctx_end(UNBOUND_WORKQUEUE) + +#undef ib_poll_ctx +#undef ib_poll_ctx_end + +#define ib_poll_ctx(x) TRACE_DEFINE_ENUM(IB_POLL_##x); +#define ib_poll_ctx_end(x) TRACE_DEFINE_ENUM(IB_POLL_##x); + +IB_POLL_CTX_LIST + +#undef ib_poll_ctx +#undef ib_poll_ctx_end + +#define ib_poll_ctx(x) { IB_POLL_##x, #x }, +#define ib_poll_ctx_end(x) { IB_POLL_##x, #x } + +#define rdma_show_ib_poll_ctx(x) \ + __print_symbolic(x, IB_POLL_CTX_LIST) + +/** + ** Completion Queue events + **/ + +TRACE_EVENT(cq_schedule, + TP_PROTO( + struct ib_cq *cq + ), + + TP_ARGS(cq), + + TP_STRUCT__entry( + __field(u32, cq_id) + ), + + TP_fast_assign( + cq->timestamp = ktime_get(); + cq->interrupt = true; + + __entry->cq_id = cq->res.id; + ), + + TP_printk("cq.id=%u", __entry->cq_id) +); + +TRACE_EVENT(cq_reschedule, + TP_PROTO( + struct ib_cq *cq + ), + + TP_ARGS(cq), + + TP_STRUCT__entry( + __field(u32, cq_id) + ), + + TP_fast_assign( + cq->timestamp = ktime_get(); + cq->interrupt = false; + + __entry->cq_id = cq->res.id; + ), + + TP_printk("cq.id=%u", __entry->cq_id) +); + +TRACE_EVENT(cq_process, + TP_PROTO( + const struct ib_cq *cq + ), + + TP_ARGS(cq), + + TP_STRUCT__entry( + __field(u32, cq_id) + __field(bool, interrupt) + __field(s64, latency) + ), + + TP_fast_assign( + ktime_t latency = ktime_sub(ktime_get(), cq->timestamp); + + __entry->cq_id = cq->res.id; + __entry->latency = ktime_to_us(latency); + __entry->interrupt = cq->interrupt; + ), + + TP_printk("cq.id=%u wake-up took %lld [us] from %s", + __entry->cq_id, __entry->latency, + __entry->interrupt ? "interrupt" : "reschedule" + ) +); + +TRACE_EVENT(cq_poll, + TP_PROTO( + const struct ib_cq *cq, + int requested, + int rc + ), + + TP_ARGS(cq, requested, rc), + + TP_STRUCT__entry( + __field(u32, cq_id) + __field(int, requested) + __field(int, rc) + ), + + TP_fast_assign( + __entry->cq_id = cq->res.id; + __entry->requested = requested; + __entry->rc = rc; + ), + + TP_printk("cq.id=%u requested %d, returned %d", + __entry->cq_id, __entry->requested, __entry->rc + ) +); + +TRACE_EVENT(cq_drain_complete, + TP_PROTO( + const struct ib_cq *cq + ), + + TP_ARGS(cq), + + TP_STRUCT__entry( + __field(u32, cq_id) + ), + + TP_fast_assign( + __entry->cq_id = cq->res.id; + ), + + TP_printk("cq.id=%u", + __entry->cq_id + ) +); + + +TRACE_EVENT(cq_modify, + TP_PROTO( + const struct ib_cq *cq, + u16 comps, + u16 usec + ), + + TP_ARGS(cq, comps, usec), + + TP_STRUCT__entry( + __field(u32, cq_id) + __field(unsigned int, comps) + __field(unsigned int, usec) + ), + + TP_fast_assign( + __entry->cq_id = cq->res.id; + __entry->comps = comps; + __entry->usec = usec; + ), + + TP_printk("cq.id=%u comps=%u usec=%u", + __entry->cq_id, __entry->comps, __entry->usec + ) +); + +TRACE_EVENT(cq_alloc, + TP_PROTO( + const struct ib_cq *cq, + int nr_cqe, + int comp_vector, + enum ib_poll_context poll_ctx + ), + + TP_ARGS(cq, nr_cqe, comp_vector, poll_ctx), + + TP_STRUCT__entry( + __field(u32, cq_id) + __field(int, nr_cqe) + __field(int, comp_vector) + __field(unsigned long, poll_ctx) + ), + + TP_fast_assign( + __entry->cq_id = cq->res.id; + __entry->nr_cqe = nr_cqe; + __entry->comp_vector = comp_vector; + __entry->poll_ctx = poll_ctx; + ), + + TP_printk("cq.id=%u nr_cqe=%d comp_vector=%d poll_ctx=%s", + __entry->cq_id, __entry->nr_cqe, __entry->comp_vector, + rdma_show_ib_poll_ctx(__entry->poll_ctx) + ) +); + +TRACE_EVENT(cq_alloc_error, + TP_PROTO( + int nr_cqe, + int comp_vector, + enum ib_poll_context poll_ctx, + int rc + ), + + TP_ARGS(nr_cqe, comp_vector, poll_ctx, rc), + + TP_STRUCT__entry( + __field(int, rc) + __field(int, nr_cqe) + __field(int, comp_vector) + __field(unsigned long, poll_ctx) + ), + + TP_fast_assign( + __entry->rc = rc; + __entry->nr_cqe = nr_cqe; + __entry->comp_vector = comp_vector; + __entry->poll_ctx = poll_ctx; + ), + + TP_printk("nr_cqe=%d comp_vector=%d poll_ctx=%s rc=%d", + __entry->nr_cqe, __entry->comp_vector, + rdma_show_ib_poll_ctx(__entry->poll_ctx), __entry->rc + ) +); + +TRACE_EVENT(cq_free, + TP_PROTO( + const struct ib_cq *cq + ), + + TP_ARGS(cq), + + TP_STRUCT__entry( + __field(u32, cq_id) + ), + + TP_fast_assign( + __entry->cq_id = cq->res.id; + ), + + TP_printk("cq.id=%u", __entry->cq_id) +); + +#endif /* _TRACE_RDMA_CORE_H */ + +#include <trace/define_trace.h> |