From d11601e87f0da519fa62baa77c863b5f0d0bfb1f Mon Sep 17 00:00:00 2001 From: Krzysztof Karas Date: Mon, 15 Nov 2021 11:25:38 +0000 Subject: [PATCH] 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 Reviewed-on: https://review.spdk.io/gerrit/c/spdk/spdk/+/10237 Community-CI: Broadcom CI Tested-by: SPDK CI Jenkins Reviewed-by: Jim Harris Reviewed-by: Aleksey Marchuk --- lib/nvmf/ctrlr.c | 9 ++++ lib/nvmf/nvmf.c | 15 ++++-- lib/nvmf/subsystem.c | 24 +++++++++- lib/nvmf/transport.c | 7 +++ scripts/bpf/nvmf.bt | 108 +++++++++++++++++++++++++++++++++++++++++++ 5 files changed, 159 insertions(+), 4 deletions(-) diff --git a/lib/nvmf/ctrlr.c b/lib/nvmf/ctrlr.c index 1d67d7b87..2a35097f1 100644 --- a/lib/nvmf/ctrlr.c +++ b/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. */ diff --git a/lib/nvmf/nvmf.c b/lib/nvmf/nvmf.c index a3a1d491b..bafe3aa53 100644 --- a/lib/nvmf/nvmf.c +++ b/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"); diff --git a/lib/nvmf/subsystem.c b/lib/nvmf/subsystem.c index bf06b262c..c9de74515 100644 --- a/lib/nvmf/subsystem.c +++ b/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); diff --git a/lib/nvmf/transport.c b/lib/nvmf/transport.c index f46e2bddf..578f0d4aa 100644 --- a/lib/nvmf/transport.c +++ b/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); diff --git a/scripts/bpf/nvmf.bt b/scripts/bpf/nvmf.bt index e73bb676d..05dc6a7d4 100644 --- a/scripts/bpf/nvmf.bt +++ b/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); +}