nvmf: add traces around poll group lifecycle

The traces are tracking the lifecycle of a poll group: creating it,
adding and disconnecting qpairs, and finally destroying the group.

Signed-off-by: Konrad Sztyber <konrad.sztyber@intel.com>
Change-Id: I075b7f24d14b8fbb42bb18ddd70a668a8bace118
Reviewed-on: https://review.spdk.io/gerrit/c/spdk/spdk/+/7158
Tested-by: SPDK CI Jenkins <sys_sgci@intel.com>
Community-CI: Mellanox Build Bot
Reviewed-by: Changpeng Liu <changpeng.liu@intel.com>
Reviewed-by: Aleksey Marchuk <alexeymar@mellanox.com>
Reviewed-by: Jim Harris <james.r.harris@intel.com>
This commit is contained in:
Konrad Sztyber 2021-03-31 09:37:25 +02:00 committed by Tomasz Zawadzki
parent db71eb6a4b
commit a266b6e4be
4 changed files with 81 additions and 11 deletions

View File

@ -39,14 +39,13 @@
#include "spdk/bit_array.h"
#include "spdk/endian.h"
#include "spdk/thread.h"
#include "spdk/trace.h"
#include "spdk/nvme_spec.h"
#include "spdk/nvmf_cmd.h"
#include "spdk/string.h"
#include "spdk/util.h"
#include "spdk/version.h"
#include "spdk/log.h"
#include "spdk_internal/usdt.h"
#define MIN_KEEP_ALIVE_TIMEOUT_IN_MS 10000
#define NVMF_DISC_KATO_IN_MS 120000
@ -253,6 +252,9 @@ ctrlr_add_qpair_and_update_rsp(struct spdk_nvmf_qpair *qpair,
rsp->status_code_specific.success.cntlid = ctrlr->cntlid;
SPDK_DEBUGLOG(nvmf, "connect capsule response: cntlid = 0x%04x\n",
rsp->status_code_specific.success.cntlid);
SPDK_DTRACE_PROBE4(nvmf_ctrlr_add_qpair, qpair, qpair->qid, ctrlr->subsys->subnqn,
ctrlr->hostnqn);
}
static void

View File

@ -37,11 +37,10 @@
#include "spdk/bit_array.h"
#include "spdk/thread.h"
#include "spdk/nvmf.h"
#include "spdk/trace.h"
#include "spdk/endian.h"
#include "spdk/string.h"
#include "spdk/log.h"
#include "spdk_internal/usdt.h"
#include "nvmf_internal.h"
#include "transport.h"
@ -114,8 +113,11 @@ nvmf_tgt_create_poll_group(void *io_device, void *ctx_buf)
struct spdk_nvmf_tgt *tgt = io_device;
struct spdk_nvmf_poll_group *group = ctx_buf;
struct spdk_nvmf_transport *transport;
struct spdk_thread *thread = spdk_get_thread();
uint32_t sid;
SPDK_DTRACE_PROBE1(nvmf_create_poll_group, spdk_thread_get_id(thread));
TAILQ_INIT(&group->tgroups);
TAILQ_INIT(&group->qpairs);
@ -148,7 +150,7 @@ 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 = spdk_get_thread();
group->thread = thread;
return 0;
}
@ -162,6 +164,8 @@ nvmf_tgt_destroy_poll_group(void *io_device, void *ctx_buf)
struct spdk_nvmf_subsystem_poll_group *sgroup;
uint32_t sid, nsid;
SPDK_DTRACE_PROBE1(nvmf_destroy_poll_group, spdk_thread_get_id(group->thread));
pthread_mutex_lock(&tgt->mutex);
TAILQ_REMOVE(&tgt->poll_groups, group, link);
pthread_mutex_unlock(&tgt->mutex);
@ -221,8 +225,9 @@ nvmf_tgt_destroy_poll_group_qpairs(struct spdk_nvmf_poll_group *group)
{
struct nvmf_qpair_disconnect_many_ctx *ctx;
ctx = calloc(1, sizeof(struct nvmf_qpair_disconnect_many_ctx));
SPDK_DTRACE_PROBE1(nvmf_destroy_poll_group_qpairs, spdk_thread_get_id(group->thread));
ctx = calloc(1, sizeof(struct nvmf_qpair_disconnect_many_ctx));
if (!ctx) {
SPDK_ERRLOG("Failed to allocate memory for destroy poll group ctx\n");
return;
@ -917,6 +922,7 @@ spdk_nvmf_poll_group_add(struct spdk_nvmf_poll_group *group,
/* We add the qpair to the group only it is succesfully added into the tgroup */
if (rc == 0) {
SPDK_DTRACE_PROBE2(nvmf_poll_group_add_qpair, qpair, spdk_thread_get_id(group->thread));
TAILQ_INSERT_TAIL(&group->qpairs, qpair, link);
nvmf_qpair_set_state(qpair, SPDK_NVMF_QPAIR_ACTIVE);
}
@ -978,6 +984,8 @@ spdk_nvmf_poll_group_remove(struct spdk_nvmf_qpair *qpair)
struct spdk_nvmf_subsystem_poll_group *sgroup;
int rc;
SPDK_DTRACE_PROBE2(nvmf_poll_group_remove_qpair, qpair,
spdk_thread_get_id(qpair->group->thread));
nvmf_qpair_set_state(qpair, SPDK_NVMF_QPAIR_ERROR);
/* Find the tgroup and remove the qpair from the tgroup */
@ -1050,6 +1058,7 @@ _nvmf_qpair_disconnect_msg(void *ctx)
int
spdk_nvmf_qpair_disconnect(struct spdk_nvmf_qpair *qpair, nvmf_qpair_disconnect_cb cb_fn, void *ctx)
{
struct spdk_nvmf_poll_group *group = qpair->group;
struct nvmf_qpair_disconnect_ctx *qpair_ctx;
if (__atomic_test_and_set(&qpair->disconnect_started, __ATOMIC_RELAXED)) {
@ -1068,8 +1077,8 @@ spdk_nvmf_qpair_disconnect(struct spdk_nvmf_qpair *qpair, nvmf_qpair_disconnect_
return 0;
}
assert(qpair->group != NULL);
if (spdk_get_thread() != qpair->group->thread) {
assert(group != NULL);
if (spdk_get_thread() != group->thread) {
/* clear the atomic so we can set it on the next call on the proper thread. */
__atomic_clear(&qpair->disconnect_started, __ATOMIC_RELAXED);
qpair_ctx = calloc(1, sizeof(struct nvmf_qpair_disconnect_ctx));
@ -1079,12 +1088,13 @@ spdk_nvmf_qpair_disconnect(struct spdk_nvmf_qpair *qpair, nvmf_qpair_disconnect_
}
qpair_ctx->qpair = qpair;
qpair_ctx->cb_fn = cb_fn;
qpair_ctx->thread = qpair->group->thread;
qpair_ctx->thread = group->thread;
qpair_ctx->ctx = ctx;
spdk_thread_send_msg(qpair->group->thread, _nvmf_qpair_disconnect_msg, qpair_ctx);
spdk_thread_send_msg(group->thread, _nvmf_qpair_disconnect_msg, qpair_ctx);
return 0;
}
SPDK_DTRACE_PROBE2(nvmf_qpair_disconnect, qpair, spdk_thread_get_id(group->thread));
assert(qpair->state == SPDK_NVMF_QPAIR_ACTIVE);
nvmf_qpair_set_state(qpair, SPDK_NVMF_QPAIR_DEACTIVATING);
@ -1096,11 +1106,12 @@ spdk_nvmf_qpair_disconnect(struct spdk_nvmf_qpair *qpair, nvmf_qpair_disconnect_
qpair_ctx->qpair = qpair;
qpair_ctx->cb_fn = cb_fn;
qpair_ctx->thread = qpair->group->thread;
qpair_ctx->thread = group->thread;
qpair_ctx->ctx = ctx;
/* Check for outstanding I/O */
if (!TAILQ_EMPTY(&qpair->outstanding)) {
SPDK_DTRACE_PROBE2(nvmf_poll_group_drain_qpair, qpair, spdk_thread_get_id(group->thread));
qpair->state_cb = _nvmf_qpair_destroy;
qpair->state_cb_arg = qpair_ctx;
nvmf_qpair_free_aer(qpair);

View File

@ -42,6 +42,7 @@
#include "spdk/nvmf_transport.h"
#include "spdk/queue.h"
#include "spdk/util.h"
#include "spdk_internal/usdt.h"
#define MAX_MEMPOOL_NAME_LENGTH 40
#define NVMF_TRANSPORT_DEFAULT_ASSOCIATION_TIMEOUT_IN_MS 120000
@ -532,6 +533,8 @@ nvmf_transport_qpair_fini(struct spdk_nvmf_qpair *qpair,
spdk_nvmf_transport_qpair_fini_cb cb_fn,
void *cb_arg)
{
SPDK_DTRACE_PROBE1(nvmf_transport_qpair_fini, qpair);
qpair->transport->ops->qpair_fini(qpair, cb_fn, cb_arg);
}

View File

@ -27,3 +27,57 @@ usdt:__EXE__:nvmf_pg_change_state_done {
elapsed / (uint64)(1000 * 1000), elapsed % (uint64)(1000 * 1000),
str(arg0), arg2, @subsystem[arg1]);
}
usdt:__EXE__:nvmf_create_poll_group {
printf("%d.%06d: create poll group on thread: %d\n",
elapsed / (uint64)(1000 * 1000), elapsed % (uint64)(1000 * 1000),
arg0);
}
usdt:__EXE__:nvmf_destroy_poll_group {
printf("%d.%06d: destroy poll group on thread: %d\n",
elapsed / (uint64)(1000 * 1000), elapsed % (uint64)(1000 * 1000),
arg0);
}
usdt:__EXE__:nvmf_poll_group_add_qpair {
printf("%d.%06d: add qpair: %p to poll group on thread %d\n",
elapsed / (uint64)(1000 * 1000), elapsed % (uint64)(1000 * 1000),
arg0, arg1);
}
usdt:__EXE__:nvmf_destroy_poll_group_qpairs {
printf("%d.%06d: destroy qpairs on poll group on thread %d\n",
elapsed / (uint64)(1000 * 1000), elapsed % (uint64)(1000 * 1000),
arg0);
}
usdt:__EXE__:nvmf_poll_group_remove_qpair {
printf("%d.%06d: remove qpair: %p from poll group on thread %d\n",
elapsed / (uint64)(1000 * 1000), elapsed % (uint64)(1000 * 1000),
arg0, arg1);
}
usdt:__EXE__:nvmf_qpair_disconnect {
printf("%d.%06d: disconnect qpair: %p from poll group on thread %d\n",
elapsed / (uint64)(1000 * 1000), elapsed % (uint64)(1000 * 1000),
arg0, arg1);
}
usdt:__EXE__:nvmf_transport_qpair_fini {
printf("%d.%06d: destroy qpair: %p on transport layer\n",
elapsed / (uint64)(1000 * 1000), elapsed % (uint64)(1000 * 1000),
arg0);
}
usdt:__EXE__:nvmf_poll_group_drain_qpair {
printf("%d.%06d: drain qpair: %p from poll group on thread %d\n",
elapsed / (uint64)(1000 * 1000), elapsed % (uint64)(1000 * 1000),
arg0, arg1);
}
usdt:__EXE__:nvmf_ctrlr_add_qpair {
printf("%d.%06d: %s add qpair: %p, qid: %d for host: %s\n",
elapsed / (uint64)(1000 * 1000), elapsed % (uint64)(1000 * 1000),
str(arg2), arg0, arg1, str(arg3));
}