From 70f3606bfc207762fcceb8b58ba8a4a563caaabf Mon Sep 17 00:00:00 2001 From: John Levon Date: Tue, 7 Sep 2021 22:49:31 +0100 Subject: [PATCH] add USDT tracepoints for interrupt wakeups With these we can write a simple bpftrace script to identify work being done, and in particular what woke us up from sleeping. Signed-off-by: John Levon Change-Id: I8997d847625ee4558092dbd753e6fc1b17beca92 Reviewed-on: https://review.spdk.io/gerrit/c/spdk/spdk/+/9424 Tested-by: SPDK CI Jenkins Community-CI: Broadcom CI Community-CI: Mellanox Build Bot Reviewed-by: Jim Harris Reviewed-by: Tomasz Zawadzki --- app/trace/trace.cpp | 6 ++++ lib/event/reactor.c | 4 +++ lib/thread/thread.c | 6 ++++ lib/util/fd_group.c | 9 +++++- scripts/bpf/intr-wakeups.bt | 60 +++++++++++++++++++++++++++++++++++++ 5 files changed, 84 insertions(+), 1 deletion(-) create mode 100644 scripts/bpf/intr-wakeups.bt diff --git a/app/trace/trace.cpp b/app/trace/trace.cpp index 6eeb4724f..430171b3f 100644 --- a/app/trace/trace.cpp +++ b/app/trace/trace.cpp @@ -68,6 +68,12 @@ extern "C" { { assert(false); } + + uint64_t + spdk_get_ticks(void) + { + return 0; + } } /* extern "C" */ static void usage(void); diff --git a/lib/event/reactor.c b/lib/event/reactor.c index b3c8dea03..5e874a53e 100644 --- a/lib/event/reactor.c +++ b/lib/event/reactor.c @@ -35,6 +35,7 @@ #include "spdk/likely.h" #include "spdk_internal/event.h" +#include "spdk_internal/usdt.h" #include "spdk/log.h" #include "spdk/thread.h" @@ -596,6 +597,9 @@ event_queue_run_batch(void *arg) assert(event != NULL); spdk_set_thread(thread); + + SPDK_DTRACE_PROBE3(event_exec, event->fn, + event->arg1, event->arg2); event->fn(event->arg1, event->arg2); spdk_set_thread(NULL); } diff --git a/lib/thread/thread.c b/lib/thread/thread.c index f339591d8..6c9340765 100644 --- a/lib/thread/thread.c +++ b/lib/thread/thread.c @@ -44,6 +44,7 @@ #include "spdk/log.h" #include "spdk_internal/thread.h" +#include "spdk_internal/usdt.h" #include "thread_internal.h" #include "spdk_internal/trace_defs.h" @@ -709,6 +710,9 @@ msg_queue_run_batch(struct spdk_thread *thread, uint32_t max_msgs) struct spdk_msg *msg = messages[i]; assert(msg != NULL); + + SPDK_DTRACE_PROBE2(msg_exec, msg->fn, msg->arg); + msg->fn(msg->arg); if (thread->msg_cache_count < SPDK_MSG_MEMPOOL_CACHE_SIZE) { @@ -1276,6 +1280,8 @@ interrupt_timerfd_process(void *arg) return rc; } + SPDK_DTRACE_PROBE2(timerfd_exec, poller->fn, poller->arg); + return poller->fn(poller->arg); } diff --git a/lib/util/fd_group.c b/lib/util/fd_group.c index 1f69ad2bd..eea043c26 100644 --- a/lib/util/fd_group.c +++ b/lib/util/fd_group.c @@ -31,8 +31,12 @@ * OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. */ -#include "spdk/queue.h" +#include "spdk_internal/usdt.h" + +#include "spdk/env.h" #include "spdk/log.h" +#include "spdk/queue.h" + #include "spdk/fd_group.h" #ifdef __linux__ @@ -298,6 +302,9 @@ spdk_fd_group_wait(struct spdk_fd_group *fgrp, int timeout) continue; } + SPDK_DTRACE_PROBE4(interrupt_fd_process, ehdlr->name, ehdlr->fd, + ehdlr->fn, ehdlr->fn_arg); + /* call the interrupt response function */ ehdlr->fn(ehdlr->fn_arg); diff --git a/scripts/bpf/intr-wakeups.bt b/scripts/bpf/intr-wakeups.bt new file mode 100644 index 000000000..0451712c2 --- /dev/null +++ b/scripts/bpf/intr-wakeups.bt @@ -0,0 +1,60 @@ +/* + * Trace reasons for SPDK to wake up in interrupt mode. + * + * You'll probably need bpftrace from https://github.com/fbs/el7-bpf-specs + * + * Usage: + * scripts/bpftrace.sh `pidof spdk_tgt` [all] + * all: show every event, not just the first after waking up + */ + +tracepoint:sched:sched_switch /comm == "reactor_0"/ +{ + if (str($1) == "all") { + printf("%llums: %s is off-cpu\n", elapsed / 1000000, comm); + } + @off = 1; +} + +/* + * We explicitly filter out the framework-level handlers here in favour of the + * more specific tracepoints below. + */ +usdt:__EXE__:spdk:interrupt_fd_process / + @off == 1 && + strncmp(str(arg1), "event_queue_run_batch", 40) != 0 && + strncmp(str(arg1), "interrupt_timerfd_process", 40) != 0 && + strncmp(str(arg1), "thread_interrupt_msg_process", 40) != 0 && + strncmp(str(arg1), "thread_process_interrupts", 40) != 0 +/ +{ + printf("%llums:%s: fd:%d %s(%p)\n", elapsed / 1000000, probe, arg2, usym(arg3), arg4); + if (str($1) != "all") { + @off = 0; + } +} + +usdt:__EXE__:spdk:timerfd_exec /@off == 1/ +{ + printf("%llums:%s: %s(%p)\n", elapsed / 1000000, probe, usym(arg1), arg2); + if (str($1) != "all") { + @off = 0; + } +} + +usdt:__EXE__:spdk:msg_exec /@off == 1/ +{ + printf("%llums:%s: %s(%p)\n", elapsed / 1000000, probe, usym(arg1), arg2); + if (str($1) != "all") { + @off = 0; + } +} + +usdt:__EXE__:spdk:event_exec /@off == 1/ +{ + printf("%llums:%s: %s(%p, %p)\n", elapsed / 1000000, probe, usym(arg1), + arg2, arg3); + if (str($1) != "all") { + @off = 0; + } +}