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 <john.levon@nutanix.com>
Change-Id: I8997d847625ee4558092dbd753e6fc1b17beca92
Reviewed-on: https://review.spdk.io/gerrit/c/spdk/spdk/+/9424
Tested-by: SPDK CI Jenkins <sys_sgci@intel.com>
Community-CI: Broadcom CI <spdk-ci.pdl@broadcom.com>
Community-CI: Mellanox Build Bot
Reviewed-by: Jim Harris <james.r.harris@intel.com>
Reviewed-by: Tomasz Zawadzki <tomasz.zawadzki@intel.com>

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);

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);
 	}

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);
 }
 

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);
 

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;
+	}
+}