traces: add dtrace probes around qpair/controller/subsystem

Add dtrace probes aroung qpair/controller/subsystem management
to help with debugging issue #2055.

Change-Id: I0b981bffadee3fe4172ad6916c059bf357959dde
Signed-off-by: Krzysztof Karas <krzysztof.karas@intel.com>
Reviewed-on: https://review.spdk.io/gerrit/c/spdk/spdk/+/10237
Community-CI: Broadcom CI <spdk-ci.pdl@broadcom.com>
Tested-by: SPDK CI Jenkins <sys_sgci@intel.com>
Reviewed-by: Jim Harris <james.r.harris@intel.com>
Reviewed-by: Aleksey Marchuk <alexeymar@mellanox.com>

lib/nvmf/ctrlr.c

@@ -350,6 +350,9 @@ nvmf_ctrlr_create(struct spdk_nvmf_subsystem *subsystem,
 		ctrlr->cntlid = connect_data->cntlid;
 	}
 
+	SPDK_DTRACE_PROBE3(nvmf_ctrlr_create, ctrlr, subsystem->subnqn,
+			   spdk_thread_get_id(req->qpair->group->thread));
+
 	STAILQ_INIT(&ctrlr->async_events);
 	TAILQ_INIT(&ctrlr->log_head);
 	ctrlr->subsys = subsystem;
@@ -483,6 +486,9 @@ _nvmf_ctrlr_destruct(void *ctx)
 	struct spdk_nvmf_reservation_log *log, *log_tmp;
 	struct spdk_nvmf_async_event_completion *event, *event_tmp;
 
+	SPDK_DTRACE_PROBE3(nvmf_ctrlr_destruct, ctrlr, ctrlr->subsys->subnqn,
+			   spdk_thread_get_id(ctrlr->thread));
+
 	assert(spdk_get_thread() == ctrlr->thread);
 	assert(ctrlr->in_destruct);
 
@@ -524,6 +530,9 @@ nvmf_ctrlr_add_io_qpair(void *ctx)
 	struct spdk_nvmf_ctrlr *ctrlr = qpair->ctrlr;
 	struct spdk_nvmf_qpair *admin_qpair = ctrlr->admin_qpair;
 
+	SPDK_DTRACE_PROBE4(nvmf_ctrlr_add_io_qpair, ctrlr, req->qpair, req->qpair->qid,
+			   spdk_thread_get_id(ctrlr->thread));
+
 	/* Unit test will check qpair->ctrlr after calling spdk_nvmf_ctrlr_connect.
 	  * For error case, the value should be NULL. So set it to NULL at first.
 	  */

lib/nvmf/nvmf.c

@@ -117,10 +117,9 @@ nvmf_tgt_create_poll_group(void *io_device, void *ctx_buf)
 	uint32_t sid;
 	int rc;
 
-	SPDK_DTRACE_PROBE1(nvmf_create_poll_group, spdk_thread_get_id(thread));
-
 	TAILQ_INIT(&group->tgroups);
 	TAILQ_INIT(&group->qpairs);
+	group->thread = thread;
 
 	TAILQ_FOREACH(transport, &tgt->transports, link) {
 		rc = nvmf_poll_group_add_transport(group, transport);
@@ -154,7 +153,8 @@ nvmf_tgt_create_poll_group(void *io_device, void *ctx_buf)
 	pthread_mutex_unlock(&tgt->mutex);
 
 	group->poller = SPDK_POLLER_REGISTER(nvmf_poll_group_poll, group, 0);
-	group->thread = thread;
+
+	SPDK_DTRACE_PROBE1(nvmf_create_poll_group, spdk_thread_get_id(thread));
 
 	return 0;
 }
@@ -754,6 +754,8 @@ void spdk_nvmf_tgt_add_transport(struct spdk_nvmf_tgt *tgt,
 {
 	struct spdk_nvmf_tgt_add_transport_ctx *ctx;
 
+	SPDK_DTRACE_PROBE2(nvmf_tgt_add_transport, transport, tgt->name);
+
 	if (spdk_nvmf_tgt_get_transport(tgt, transport->ops->name)) {
 		cb_fn(cb_arg, -EEXIST);
 		return; /* transport already created */
@@ -1159,6 +1161,7 @@ nvmf_poll_group_add_transport(struct spdk_nvmf_poll_group *group,
 		SPDK_ERRLOG("Unable to create poll group for transport\n");
 		return -1;
 	}
+	SPDK_DTRACE_PROBE2(nvmf_transport_poll_group_create, transport, spdk_thread_get_id(group->thread));
 
 	tgroup->group = group;
 	TAILQ_INSERT_TAIL(&group->tgroups, tgroup, link);
@@ -1366,6 +1369,9 @@ fini:
 		cb_fn(cb_arg, rc);
 	}
 
+	SPDK_DTRACE_PROBE2(nvmf_poll_group_add_subsystem, spdk_thread_get_id(group->thread),
+			   subsystem->subnqn);
+
 	return rc;
 }
 
@@ -1482,6 +1488,9 @@ nvmf_poll_group_remove_subsystem(struct spdk_nvmf_poll_group *group,
 	struct nvmf_qpair_disconnect_many_ctx *ctx;
 	uint32_t i;
 
+	SPDK_DTRACE_PROBE3(nvmf_poll_group_remove_subsystem, group, spdk_thread_get_id(group->thread),
+			   subsystem->subnqn);
+
 	ctx = calloc(1, sizeof(struct nvmf_qpair_disconnect_many_ctx));
 	if (!ctx) {
 		SPDK_ERRLOG("Unable to allocate memory for context to remove poll subsystem\n");

lib/nvmf/subsystem.c

@@ -333,6 +333,8 @@ spdk_nvmf_subsystem_create(struct spdk_nvmf_tgt *tgt,
 
 	tgt->subsystems[sid] = subsystem;
 
+	SPDK_DTRACE_PROBE1(nvmf_subsystem_create, subsystem->subnqn);
+
 	return subsystem;
 }
 
@@ -441,6 +443,8 @@ spdk_nvmf_subsystem_destroy(struct spdk_nvmf_subsystem *subsystem, nvmf_subsyste
 		return -EINVAL;
 	}
 
+	SPDK_DTRACE_PROBE1(nvmf_subsystem_destroy, subsystem->subnqn);
+
 	assert(spdk_get_thread() == subsystem->thread);
 
 	if (subsystem->state != SPDK_NVMF_SUBSYSTEM_INACTIVE) {
@@ -847,6 +851,8 @@ spdk_nvmf_subsystem_add_host(struct spdk_nvmf_subsystem *subsystem, const char *
 
 	snprintf(host->nqn, sizeof(host->nqn), "%s", hostnqn);
 
+	SPDK_DTRACE_PROBE2(nvmf_subsystem_add_host, subsystem->subnqn, host->nqn);
+
 	TAILQ_INSERT_HEAD(&subsystem->hosts, host, link);
 
 	if (!TAILQ_EMPTY(&subsystem->listeners)) {
@@ -871,6 +877,8 @@ spdk_nvmf_subsystem_remove_host(struct spdk_nvmf_subsystem *subsystem, const cha
 		return -ENOENT;
 	}
 
+	SPDK_DTRACE_PROBE2(nvmf_subsystem_remove_host, subsystem->subnqn, host->nqn);
+
 	nvmf_subsystem_remove_host(subsystem, host);
 
 	if (!TAILQ_EMPTY(&subsystem->listeners)) {
@@ -1150,6 +1158,9 @@ spdk_nvmf_subsystem_add_listener(struct spdk_nvmf_subsystem *subsystem,
 		rc = transport->ops->listen_associate(transport, subsystem, trid);
 	}
 
+	SPDK_DTRACE_PROBE4(nvmf_subsystem_add_listener, subsystem->subnqn, listener->trid->trtype,
+			   listener->trid->traddr, listener->trid->trsvcid);
+
 	_nvmf_subsystem_add_listener_done(listener, rc);
 }
 
@@ -1169,6 +1180,9 @@ spdk_nvmf_subsystem_remove_listener(struct spdk_nvmf_subsystem *subsystem,
 		return -ENOENT;
 	}
 
+	SPDK_DTRACE_PROBE4(nvmf_subsystem_remove_listener, subsystem->subnqn, listener->trid->trtype,
+			   listener->trid->traddr, listener->trid->trsvcid);
+
 	_nvmf_subsystem_remove_listener(subsystem, listener, false);
 
 	return 0;
@@ -1371,6 +1385,8 @@ nvmf_ns_change_msg(void *ns_ctx)
 	struct subsystem_ns_change_ctx *ctx = ns_ctx;
 	int rc;
 
+	SPDK_DTRACE_PROBE2(nvmf_ns_change, ctx->nsid, ctx->subsystem->subnqn);
+
 	rc = spdk_nvmf_subsystem_pause(ctx->subsystem, ctx->nsid, ctx->cb_fn, ctx);
 	if (rc) {
 		if (rc == -EBUSY) {
@@ -1715,6 +1731,8 @@ spdk_nvmf_subsystem_add_ns_ext(struct spdk_nvmf_subsystem *subsystem, const char
 
 	nvmf_subsystem_ns_changed(subsystem, opts.nsid);
 
+	SPDK_DTRACE_PROBE2(nvmf_subsystem_add_ns, subsystem->subnqn, ns->nsid);
+
 	return opts.nsid;
 
 err_subsystem_add_ns:
@@ -1726,8 +1744,8 @@ err_ns_reservation_restore:
 	spdk_bdev_module_release_bdev(ns->bdev);
 	spdk_bdev_close(ns->desc);
 	free(ns);
-	return 0;
 
+	return 0;
 }
 
 static uint32_t
@@ -1943,6 +1961,8 @@ nvmf_subsystem_add_ctrlr(struct spdk_nvmf_subsystem *subsystem, struct spdk_nvmf
 
 	TAILQ_INSERT_TAIL(&subsystem->ctrlrs, ctrlr, link);
 
+	SPDK_DTRACE_PROBE3(nvmf_subsystem_add_ctrlr, subsystem->subnqn, ctrlr, ctrlr->hostnqn);
+
 	return 0;
 }
 
@@ -1950,6 +1970,8 @@ void
 nvmf_subsystem_remove_ctrlr(struct spdk_nvmf_subsystem *subsystem,
 			    struct spdk_nvmf_ctrlr *ctrlr)
 {
+	SPDK_DTRACE_PROBE3(nvmf_subsystem_remove_ctrlr, subsystem->subnqn, ctrlr, ctrlr->hostnqn);
+
 	assert(spdk_get_thread() == subsystem->thread);
 	assert(subsystem == ctrlr->subsys);
 	SPDK_DEBUGLOG(nvmf, "remove ctrlr %p from subsys %p %s\n", ctrlr, subsystem, subsystem->subnqn);

lib/nvmf/transport.c

@@ -501,6 +501,7 @@ nvmf_transport_poll_group_create(struct spdk_nvmf_transport *transport)
 
 		free(bufs);
 	}
+
 	return group;
 }
 
@@ -544,6 +545,9 @@ nvmf_transport_poll_group_add(struct spdk_nvmf_transport_poll_group *group,
 		qpair->transport = group->transport;
 	}
 
+	SPDK_DTRACE_PROBE3(nvmf_transport_poll_group_add, qpair, qpair->qid,
+			   spdk_thread_get_id(group->group->thread));
+
 	return group->transport->ops->poll_group_add(group, qpair);
 }
 
@@ -553,6 +557,9 @@ nvmf_transport_poll_group_remove(struct spdk_nvmf_transport_poll_group *group,
 {
 	int rc = ENOTSUP;
 
+	SPDK_DTRACE_PROBE3(nvmf_transport_poll_group_remove, qpair, qpair->qid,
+			   spdk_thread_get_id(group->group->thread));
+
 	assert(qpair->transport == group->transport);
 	if (group->transport->ops->poll_group_remove) {
 		rc = group->transport->ops->poll_group_remove(group, qpair);

scripts/bpf/nvmf.bt

@@ -81,3 +81,111 @@ usdt:__EXE__:nvmf_ctrlr_add_qpair {
 	       elapsed / (uint64)(1000 * 1000), elapsed % (uint64)(1000 * 1000),
 	       str(arg3), arg1, arg2, str(arg4));
 }
+
+usdt:__EXE__:nvmf_subsystem_add_host {
+	printf("%d.%06d: subsystem: %s add host: %s\n",
+	       elapsed / (uint64)(1000 * 1000), elapsed % (uint64)(1000 * 1000),
+	       str(arg1), str(arg2));
+}
+
+usdt:__EXE__:nvmf_subsystem_remove_host {
+	printf("%d.%06d: subsystem: %s remove host: %s\n",
+	       elapsed / (uint64)(1000 * 1000), elapsed % (uint64)(1000 * 1000),
+	       str(arg1), str(arg2));
+}
+
+usdt:__EXE__:nvmf_subsystem_add_listener {
+	printf("%d.%06d: subsystem: %d add listener with trtype: %d, traddr: %s, trsvcid: %s\n",
+	       elapsed / (uint64)(1000 * 1000), elapsed % (uint64)(1000 * 1000),
+	       arg1, arg2, str(arg3), str(arg4));
+}
+
+usdt:__EXE__:nvmf_subsystem_remove_listener {
+	printf("%d.%06d: subsystem: %d remove listener with trtype: %d, traddr: %s, trsvcid: %s\n",
+	       elapsed / (uint64)(1000 * 1000), elapsed % (uint64)(1000 * 1000),
+	       arg1, arg2, str(arg3), str(arg4));
+}
+
+usdt:__EXE__:nvmf_subsystem_create {
+	printf("%d.%06d: create subsystem: %s\n",
+	       elapsed / (uint64)(1000 * 1000), elapsed % (uint64)(1000 * 1000),
+	       str(arg1));
+}
+
+usdt:__EXE__:nvmf_subsystem_destroy {
+	printf("%d.%06d: destroy subsystem: %s\n",
+	       elapsed / (uint64)(1000 * 1000), elapsed % (uint64)(1000 * 1000),
+	       str(arg1));
+}
+
+usdt:__EXE__:nvmf_ns_change {
+	printf("%d.%06d: namespace change: %d for subsystem: %s\n",
+	       elapsed / (uint64)(1000 * 1000), elapsed % (uint64)(1000 * 1000),
+	       arg1, str(arg2));
+}
+
+usdt:__EXE__:nvmf_subsystem_add_ns {
+	printf("%d.%06d: subsystem: %s add namespace: %d\n",
+	       elapsed / (uint64)(1000 * 1000), elapsed % (uint64)(1000 * 1000),
+	       str(arg1), arg2);
+}
+
+usdt:__EXE__:nvmf_subsystem_add_ctrlr {
+	printf("%d.%06d: subsystem: %s add controller: %p on host: %s\n",
+	       elapsed / (uint64)(1000 * 1000), elapsed % (uint64)(1000 * 1000),
+	       str(arg1), arg2, str(arg3));
+}
+
+usdt:__EXE__:nvmf_subsystem_remove_ctrlr {
+	printf("%d.%06d: subsystem: %s remove controller: %p on host: %s\n",
+	       elapsed / (uint64)(1000 * 1000), elapsed % (uint64)(1000 * 1000),
+	       str(arg1), arg2, str(arg3));
+}
+
+usdt:__EXE__:nvmf_transport_poll_group_add {
+	printf("%d.%06d: add qpair: %p with id: %d to poll group on thread: %lu\n",
+	       elapsed / (uint64)(1000 * 1000), elapsed % (uint64)(1000 * 1000),
+	       arg1, arg2, arg3);
+}
+
+usdt:__EXE__:nvmf_transport_poll_group_remove {
+	printf("%d.%06d: remove qpair: %p with id: %d from poll group on thread: %lu\n",
+	       elapsed / (uint64)(1000 * 1000), elapsed % (uint64)(1000 * 1000),
+	       arg1, arg2, arg3);
+}
+
+usdt:__EXE__:nvmf_tgt_add_transport {
+	printf("%d.%06d: add transport: %p to target: %s\n",
+	       elapsed / (uint64)(1000 * 1000), elapsed % (uint64)(1000 * 1000),
+	       arg1, str(arg2));
+}
+
+usdt:__EXE__:nvmf_poll_group_add_subsystem {
+	printf("%d.%06d: poll group: %p add subsystem: %s\n",
+	       elapsed / (uint64)(1000 * 1000), elapsed % (uint64)(1000 * 1000),
+	       arg1, str(arg2));
+}
+
+usdt:__EXE__:nvmf_poll_group_remove_subsystem {
+	printf("%d.%06d: poll group: %p on thread: %lu remove subsystem: %s\n",
+	       elapsed / (uint64)(1000 * 1000), elapsed % (uint64)(1000 * 1000),
+	       arg1, arg2, str(arg3));
+}
+
+usdt:__EXE__:nvmf_ctrlr_create {
+	printf("%d.%06d: create ctrlr: %p on subsystem: %s on thread: %lu\n",
+	       elapsed / (uint64)(1000 * 1000), elapsed % (uint64)(1000 * 1000),
+	       arg1, str(arg2), arg3);
+}
+
+usdt:__EXE__:nvmf_ctrlr_destruct {
+	printf("%d.%06d: destroy ctrlr: %p on subsystem: %s on thread: %lu\n",
+	       elapsed / (uint64)(1000 * 1000), elapsed % (uint64)(1000 * 1000),
+	       arg1, str(arg2), arg3);
+}
+
+usdt:__EXE__:nvmf_ctrlr_add_io_qpair {
+	printf("%d.%06d: ctrlr: %p add io qpair: %p with id: %d on thread: %lu\n",
+	       elapsed / (uint64)(1000 * 1000), elapsed % (uint64)(1000 * 1000),
+	       arg1, arg2, arg3, arg4);
+}