Commit e8881867 authored by Jim Harris's avatar Jim Harris
Browse files

nvmf: add tracepoints for ib async events 



While here, clean up the trace application output based
on some debugging done with these tracepoints.

Signed-off-by: default avatarJim Harris <james.r.harris@intel.com>
Change-Id: Iaf79f0ff8c80d0a6b9768ae0da213d57e98ec552

Reviewed-on: https://review.gerrithub.io/424286


Reviewed-by: default avatarBen Walker <benjamin.walker@intel.com>
Reviewed-by: default avatarChangpeng Liu <changpeng.liu@intel.com>
Reviewed-by: default avatarShuhei Matsumoto <shuhei.matsumoto.xt@hitachi.com>
Tested-by: default avatarSPDK CI Jenkins <sys_sgci@intel.com>
Chandler-Test-Pool: SPDK Automated Test System <sys_sgsw@intel.com>
parent 82c3c30f

app/trace/trace.cpp

+2 −0
Original line number Diff line number Diff line
@@ -194,6 +194,8 @@ print_event(struct spdk_trace_entry *e, uint64_t tsc_rate, 
		} else {

			printf("id:    N/A");

		}

	} else if (e->object_id != 0) {

		print_arg(true, "object: ", e->object_id);

	}

	printf("\n");

}

lib/nvmf/rdma.c

+43 −1
Original line number Diff line number Diff line
@@ -126,6 +126,12 @@ enum spdk_nvmf_rdma_request_state { 
#define TRACE_RDMA_REQUEST_STATE_TRANSFERRING_CONTROLLER_TO_HOST	SPDK_TPOINT_ID(TRACE_GROUP_NVMF_RDMA, 0x8)

#define TRACE_RDMA_REQUEST_STATE_COMPLETING				SPDK_TPOINT_ID(TRACE_GROUP_NVMF_RDMA, 0x9)

#define TRACE_RDMA_REQUEST_STATE_COMPLETED				SPDK_TPOINT_ID(TRACE_GROUP_NVMF_RDMA, 0xA)

#define TRACE_RDMA_QP_CREATE						SPDK_TPOINT_ID(TRACE_GROUP_NVMF_RDMA, 0xB)

#define TRACE_RDMA_IBV_ASYNC_EVENT					SPDK_TPOINT_ID(TRACE_GROUP_NVMF_RDMA, 0xC)

#define TRACE_RDMA_CM_ASYNC_EVENT					SPDK_TPOINT_ID(TRACE_GROUP_NVMF_RDMA, 0xD)

#define TRACE_RDMA_QP_STATE_CHANGE					SPDK_TPOINT_ID(TRACE_GROUP_NVMF_RDMA, 0xE)

#define TRACE_RDMA_QP_DISCONNECT					SPDK_TPOINT_ID(TRACE_GROUP_NVMF_RDMA, 0xF)

#define TRACE_RDMA_QP_DESTROY						SPDK_TPOINT_ID(TRACE_GROUP_NVMF_RDMA, 0x10)



SPDK_TRACE_REGISTER_FN(nvmf_trace)

{
@@ -163,6 +169,19 @@ SPDK_TRACE_REGISTER_FN(nvmf_trace) 
	spdk_trace_register_description("RDMA_REQ_COMPLETED", "",

					TRACE_RDMA_REQUEST_STATE_COMPLETED,

					OWNER_NONE, OBJECT_NVMF_RDMA_IO, 0, 1, "cmid:   ");



	spdk_trace_register_description("RDMA_QP_CREATE", "", TRACE_RDMA_QP_CREATE,

					OWNER_NONE, OBJECT_NONE, 0, 0, "");

	spdk_trace_register_description("RDMA_IBV_ASYNC_EVENT", "", TRACE_RDMA_IBV_ASYNC_EVENT,

					OWNER_NONE, OBJECT_NONE, 0, 0, "type:   ");

	spdk_trace_register_description("RDMA_CM_ASYNC_EVENT", "", TRACE_RDMA_CM_ASYNC_EVENT,

					OWNER_NONE, OBJECT_NONE, 0, 0, "type:   ");

	spdk_trace_register_description("RDMA_QP_STATE_CHANGE", "", TRACE_RDMA_QP_STATE_CHANGE,

					OWNER_NONE, OBJECT_NONE, 0, 1, "state:  ");

	spdk_trace_register_description("RDMA_QP_DISCONNECT", "", TRACE_RDMA_QP_DISCONNECT,

					OWNER_NONE, OBJECT_NONE, 0, 0, "");

	spdk_trace_register_description("RDMA_QP_DESTROY", "", TRACE_RDMA_QP_DESTROY,

					OWNER_NONE, OBJECT_NONE, 0, 0, "");

}



/* This structure holds commands as they are received off the wire.
@@ -342,6 +361,7 @@ static const char *str_ibv_qp_state[] = { 


static enum ibv_qp_state

spdk_nvmf_rdma_update_ibv_state(struct spdk_nvmf_rdma_qpair *rqpair) {

	enum ibv_qp_state old_state, new_state;

	int rc;



	/* All the attributes needed for recovery */
@@ -362,6 +382,7 @@ spdk_nvmf_rdma_update_ibv_state(struct spdk_nvmf_rdma_qpair *rqpair) { 
	IBV_QP_RNR_RETRY |

	IBV_QP_MAX_QP_RD_ATOMIC;



	old_state = rqpair->ibv_attr.qp_state;

	rc = ibv_query_qp(rqpair->cm_id->qp, &rqpair->ibv_attr,

			  spdk_nvmf_ibv_attr_mask, &rqpair->ibv_init_attr);
@@ -371,7 +392,13 @@ spdk_nvmf_rdma_update_ibv_state(struct spdk_nvmf_rdma_qpair *rqpair) { 
		assert(false);

	}



	return rqpair->ibv_attr.qp_state;

	new_state = rqpair->ibv_attr.qp_state;

	if (old_state != new_state)

	{

		spdk_trace_record(TRACE_RDMA_QP_STATE_CHANGE, 0, 0,

				  (uintptr_t)rqpair->cm_id, new_state);

	}

	return new_state;

}



static int
@@ -499,6 +526,8 @@ spdk_nvmf_rdma_cur_queue_depth(struct spdk_nvmf_rdma_qpair *rqpair) 
static void

spdk_nvmf_rdma_qpair_destroy(struct spdk_nvmf_rdma_qpair *rqpair)

{

	spdk_trace_record(TRACE_RDMA_QP_DESTROY, 0, 0, (uintptr_t)rqpair->cm_id, 0);



	if (spdk_nvmf_rdma_cur_queue_depth(rqpair)) {

		rqpair->qpair_disconnected = true;

		return;
@@ -572,6 +601,7 @@ spdk_nvmf_rdma_qpair_initialize(struct spdk_nvmf_qpair *qpair) 
		return -1;

	}



	spdk_trace_record(TRACE_RDMA_QP_CREATE, 0, 0, (uintptr_t)rqpair->cm_id, 0);

	SPDK_DEBUGLOG(SPDK_LOG_RDMA, "New RDMA Connection: %p\n", qpair);



	rqpair->reqs = calloc(rqpair->max_queue_depth, sizeof(*rqpair->reqs));
@@ -949,6 +979,7 @@ nvmf_rdma_disconnect(struct rdma_cm_event *evt) 
	}



	rqpair = SPDK_CONTAINEROF(qpair, struct spdk_nvmf_rdma_qpair, qpair);

	spdk_trace_record(TRACE_RDMA_QP_DISCONNECT, 0, 0, (uintptr_t)rqpair->cm_id, 0);

	spdk_nvmf_rdma_update_ibv_state(rqpair);



	spdk_nvmf_qpair_disconnect(qpair, NULL, NULL);
@@ -995,6 +1026,8 @@ spdk_nvmf_process_cm_event(struct spdk_nvmf_transport *transport, new_qpair_fn c 
		if (rc == 0) {

			SPDK_DEBUGLOG(SPDK_LOG_RDMA, "Acceptor Event: %s\n", CM_EVENT_STR[event->event]);



			spdk_trace_record(TRACE_RDMA_CM_ASYNC_EVENT, 0, 0, 0, event->event);



			switch (event->event) {

			case RDMA_CM_EVENT_ADDR_RESOLVED:

			case RDMA_CM_EVENT_ADDR_ERROR:
@@ -2164,10 +2197,14 @@ spdk_nvmf_process_ib_event(struct spdk_nvmf_rdma_device *device) 


	switch (event.event_type) {

	case IBV_EVENT_QP_FATAL:

		spdk_trace_record(TRACE_RDMA_IBV_ASYNC_EVENT, 0, 0,

				  (uintptr_t)rqpair->cm_id, event.event_type);

		spdk_nvmf_rdma_update_ibv_state(rqpair);

		spdk_thread_send_msg(rqpair->qpair.group->thread, _spdk_nvmf_rdma_qp_error, rqpair);

		break;

	case IBV_EVENT_QP_LAST_WQE_REACHED:

		spdk_trace_record(TRACE_RDMA_IBV_ASYNC_EVENT, 0, 0,

				  (uintptr_t)rqpair->cm_id, event.event_type);

		spdk_nvmf_rdma_update_ibv_state(rqpair);

		spdk_thread_send_msg(rqpair->qpair.group->thread, _spdk_nvmf_rdma_qp_last_wqe, rqpair);

		break;
@@ -2177,6 +2214,8 @@ spdk_nvmf_process_ib_event(struct spdk_nvmf_rdma_device *device) 
		 * Note that we're not on the correct thread to access the qpair, but

		 * the operations that the below calls make all happen to be thread

		 * safe. */

		spdk_trace_record(TRACE_RDMA_IBV_ASYNC_EVENT, 0, 0,

				  (uintptr_t)rqpair->cm_id, event.event_type);

		state = spdk_nvmf_rdma_update_ibv_state(rqpair);

		if (state == IBV_QPS_ERR) {

			spdk_thread_send_msg(rqpair->qpair.group->thread, _spdk_nvmf_rdma_qp_error, rqpair);
@@ -2187,6 +2226,8 @@ spdk_nvmf_process_ib_event(struct spdk_nvmf_rdma_device *device) 
	case IBV_EVENT_COMM_EST:

	case IBV_EVENT_PATH_MIG:

	case IBV_EVENT_PATH_MIG_ERR:

		spdk_trace_record(TRACE_RDMA_IBV_ASYNC_EVENT, 0, 0,

				  (uintptr_t)rqpair->cm_id, event.event_type);

		spdk_nvmf_rdma_update_ibv_state(rqpair);

		break;

	case IBV_EVENT_CQ_ERR:
@@ -2201,6 +2242,7 @@ spdk_nvmf_process_ib_event(struct spdk_nvmf_rdma_device *device) 
	case IBV_EVENT_CLIENT_REREGISTER:

	case IBV_EVENT_GID_CHANGE:

	default:

		spdk_trace_record(TRACE_RDMA_IBV_ASYNC_EVENT, 0, 0, 0, event.event_type);

		break;

	}

	ibv_ack_async_event(&event);