nvmf: add USDT probes for subsystem state changes

Also add scripts/bpf/nvmf.bt to enable and log these
probes.

This patch also adds a script that can generate
a bpftrace script snippet with string maps for
needed enumerations (currently nvmf_tgt_state and
spdk_nvmf_subsystem_state).  This allows us to
dynamically generate this from the source code, and
can be extended for other enums we may want to
add in the future.

Thanks to Michal Berger for converting my original
gen_enums.py script into gen_enums.sh!

Signed-off-by: Jim Harris <james.r.harris@intel.com>
Signed-off-by: Michal Berger <michalx.berger@intel.com>
Change-Id: Iff34a6218aef40055ac14932eea5fc00e1c8bcf5
Reviewed-on: https://review.spdk.io/gerrit/c/spdk/spdk/+/7194
Community-CI: Mellanox Build Bot
Tested-by: SPDK CI Jenkins <sys_sgci@intel.com>
Reviewed-by: Changpeng Liu <changpeng.liu@intel.com>
Reviewed-by: Shuhei Matsumoto <shuhei.matsumoto.xt@hitachi.com>
Reviewed-by: Konrad Sztyber <konrad.sztyber@intel.com>

lib/nvmf/subsystem.c

@@ -48,6 +48,7 @@
 #include "spdk/bdev_module.h"
 #include "spdk/log.h"
 #include "spdk_internal/utf.h"
+#include "spdk_internal/usdt.h"
 
 #define MODEL_NUMBER_DEFAULT "SPDK bdev Controller"
 #define NVMF_SUBSYSTEM_DEFAULT_NAMESPACES 32
@@ -508,6 +509,9 @@ subsystem_state_change_done(struct spdk_io_channel_iter *i, int status)
 	struct subsystem_state_change_ctx *ctx = spdk_io_channel_iter_get_ctx(i);
 	enum spdk_nvmf_subsystem_state intermediate_state;
 
+	SPDK_DTRACE_PROBE4(nvmf_subsystem_change_state_done, ctx->subsystem->subnqn,
+			   ctx->requested_state, ctx->original_state, status);
+
 	if (status == 0) {
 		status = nvmf_subsystem_set_state(ctx->subsystem, ctx->requested_state);
 		if (status) {
@@ -543,6 +547,12 @@ static void
 subsystem_state_change_continue(void *ctx, int status)
 {
 	struct spdk_io_channel_iter *i = ctx;
+	struct subsystem_state_change_ctx *_ctx __attribute__((unused));
+
+	_ctx = spdk_io_channel_iter_get_ctx(i);
+	SPDK_DTRACE_PROBE3(nvmf_pg_change_state_done, _ctx->subsystem->subnqn,
+			   _ctx->requested_state, spdk_thread_get_id(spdk_get_thread()));
+
 	spdk_for_each_channel_continue(i, status);
 }
 
@@ -557,6 +567,8 @@ subsystem_state_change_on_pg(struct spdk_io_channel_iter *i)
 	ch = spdk_io_channel_iter_get_channel(i);
 	group = spdk_io_channel_get_ctx(ch);
 
+	SPDK_DTRACE_PROBE3(nvmf_pg_change_state, ctx->subsystem->subnqn,
+			   ctx->requested_state, spdk_thread_get_id(spdk_get_thread()));
 	switch (ctx->requested_state) {
 	case SPDK_NVMF_SUBSYSTEM_INACTIVE:
 		nvmf_poll_group_remove_subsystem(group, ctx->subsystem, subsystem_state_change_continue, i);
@@ -593,6 +605,8 @@ nvmf_subsystem_state_change(struct spdk_nvmf_subsystem *subsystem,
 		return -EBUSY;
 	}
 
+	SPDK_DTRACE_PROBE3(nvmf_subsystem_change_state, subsystem->subnqn,
+			   requested_state, subsystem->state);
 	/* If we are already in the requested state, just call the callback immediately. */
 	if (subsystem->state == requested_state) {
 		subsystem->changing_state = false;

module/event/subsystems/nvmf/nvmf_tgt.c

@@ -38,6 +38,7 @@
 #include "spdk/log.h"
 #include "spdk/nvme.h"
 #include "spdk/nvmf_cmd.h"
+#include "spdk_internal/usdt.h"
 
 enum nvmf_tgt_state {
 	NVMF_TGT_INIT_NONE = 0,
@@ -378,6 +379,7 @@ nvmf_tgt_advance_state(void)
 	int ret;
 
 	do {
+		SPDK_DTRACE_PROBE1(nvmf_tgt_state, g_tgt_state);
 		prev_state = g_tgt_state;
 
 		switch (g_tgt_state) {

scripts/bpf/gen_enums.sh

@@ -0,0 +1,52 @@
+#!/usr/bin/env bash
+set -e
+
+rootdir=$(git rev-parse --show-toplevel)
+
+_print_enums() {
+	local enum_type=$1 enum_string=$2 enum_prefix=$3 enum output
+
+	output=$(< "$rootdir/$(git -C "$rootdir" grep -l "$enum_string" -- lib module)")
+
+	# Isolate the enum block
+	output=${output#*$enum_string$'\n'} output=${output%%$'\n'\};*}
+	# Fold it onto an array
+	IFS="," read -ra output <<< "${output//[[:space:]]/}"
+	# Drop the assignments
+	output=("${output[@]/=*/}")
+
+	for enum in "${!output[@]}"; do
+		if [[ ${output[enum]} != "$enum_prefix"* ]]; then
+			printf 'enum name %s does not start with expected prefix %s\n' "${output[enum]}" "$enum_prefix"
+			return 1
+		fi >&2
+		printf '  @%s[%d] = "%s";\n' "$enum_type" "$enum" "${output[enum]#$enum_prefix}"
+	done
+}
+
+print_enums() {
+	for state in "${!state_enums[@]}"; do
+		_print_enums "$state" "${state_enums["$state"]}" "${state_prefix["$state"]}"
+	done
+}
+
+print_clear() { printf '  clear(@%s);\n' "${!state_enums[@]}"; }
+
+declare -A state_enums=() state_prefix=()
+
+state_enums["target"]="enum nvmf_tgt_state {"
+state_enums["subsystem"]="enum spdk_nvmf_subsystem_state {"
+state_prefix["target"]=NVMF_TGT_
+state_prefix["subsystem"]=SPDK_NVMF_SUBSYSTEM_
+
+enums=$(print_enums)
+clear=$(print_clear)
+
+cat <<- ENUM
+	BEGIN {
+		$enums
+	}
+	END {
+		$clear
+	}
+ENUM

scripts/bpf/nvmf.bt

@@ -0,0 +1,29 @@
+usdt:__EXE__:nvmf_tgt_state {
+	printf("%d.%06d: nvmf_tgt reached state %s\n",
+	       elapsed / (uint64)(1000 * 1000), elapsed % (uint64)(1000 * 1000),
+	       @target[arg0]);
+}
+
+usdt:__EXE__:nvmf_subsystem_change_state {
+	printf("%d.%06d: %s change state from %s to %s start\n",
+	       elapsed / (uint64)(1000 * 1000), elapsed % (uint64)(1000 * 1000),
+	       str(arg0), @subsystem[arg2], @subsystem[arg1]);
+}
+
+usdt:__EXE__:nvmf_subsystem_change_state_done {
+	printf("%d.%06d: %s change state from %s to %s %s\n",
+	       elapsed / (uint64)(1000 * 1000), elapsed % (uint64)(1000 * 1000),
+	       str(arg0), @subsystem[arg2], @subsystem[arg1], arg3 ? "failed" : "done");
+}
+
+usdt:__EXE__:nvmf_pg_change_state {
+	printf("%d.%06d: %s on thread %d state to %s start\n",
+	       elapsed / (uint64)(1000 * 1000), elapsed % (uint64)(1000 * 1000),
+	       str(arg0), arg2, @subsystem[arg1]);
+}
+
+usdt:__EXE__:nvmf_pg_change_state_done {
+	printf("%d.%06d: %s on thread %d state to %s done\n",
+	       elapsed / (uint64)(1000 * 1000), elapsed % (uint64)(1000 * 1000),
+	       str(arg0), arg2, @subsystem[arg1]);
+}

scripts/bpftrace.sh

@@ -1,9 +1,15 @@
 #!/usr/bin/env bash
+set -e
+
 if [ $# -lt 2 ]; then
 	echo "usage: $0 <pid> <script>"
 	exit 1
 fi
 SCRIPTS_DIR=$(readlink -f $(dirname $0))
 BIN_PATH=$(readlink -f /proc/$1/exe)
-BPF_SCRIPT=$(sed "s#__EXE__#${BIN_PATH}#g" "${@:2}" | sed "s#__PID__#${1}#g")
+BPF_SCRIPT=$($SCRIPTS_DIR/bpf/gen_enums.sh)
+BPF_SCRIPT+=$(sed "s#__EXE__#${BIN_PATH}#g" "${@:2}" | sed "s#__PID__#${1}#g")
+if [ -n "$ECHO_SCRIPT" ]; then
+	echo "$BPF_SCRIPT"
+fi
 bpftrace -p $1 -e "$BPF_SCRIPT"