Skip to content

Commit

Permalink
nvmf/tcp: add register owner for nvmf-tcp trace
Browse files Browse the repository at this point in the history 
Signed-off-by: zhaoshushu.zss <[email protected]>
Change-Id: Ib2d56f832b1e99603dade6e0d52115b42067652f
Reviewed-on: https://review.spdk.io/gerrit/c/spdk/spdk/+/11472
Community-CI: Mellanox Build Bot
Community-CI: Broadcom CI <[email protected]>
Tested-by: SPDK CI Jenkins <[email protected]>
Reviewed-by: Shuhei Matsumoto <[email protected]>
Reviewed-by: Jim Harris <[email protected]>
  • Loading branch information
@tomzawadzki
zhaoshushu.zss authored and tomzawadzki committed Mar 24, 2022
1 parent a9a5551 commit 027bfbb
Show file tree
Hide file tree
Showing 2 changed files with 53 additions and 45 deletions.
1 change: 1 addition & 0 deletions include/spdk_internal/trace_defs.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -41,6 +41,7 @@
#define OWNER_NVME_PCIE_QP 0x3
#define OWNER_SCSI_DEV 0x10
#define OWNER_FTL 0x20
#define OWNER_NVMF_TCP 0x30

/* Object definitions */
#define OBJECT_ISCSI_PDU 0x1
Expand Down
97 changes: 52 additions & 45 deletions lib/nvmf/tcp.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -123,96 +123,97 @@ static const char *spdk_nvmf_tcp_term_req_fes_str[] = {

SPDK_TRACE_REGISTER_FN(nvmf_tcp_trace, "nvmf_tcp", TRACE_GROUP_NVMF_TCP)
{
spdk_trace_register_owner(OWNER_NVMF_TCP, 't');
spdk_trace_register_object(OBJECT_NVMF_TCP_IO, 'r');
spdk_trace_register_description("TCP_REQ_NEW",
TRACE_TCP_REQUEST_STATE_NEW,
OWNER_NONE, OBJECT_NVMF_TCP_IO, 1,
OWNER_NVMF_TCP, OBJECT_NVMF_TCP_IO, 1,
SPDK_TRACE_ARG_TYPE_PTR, "qpair");
spdk_trace_register_description("TCP_REQ_NEED_BUFFER",
TRACE_TCP_REQUEST_STATE_NEED_BUFFER,
OWNER_NONE, OBJECT_NVMF_TCP_IO, 0,
OWNER_NVMF_TCP, OBJECT_NVMF_TCP_IO, 0,
SPDK_TRACE_ARG_TYPE_PTR, "qpair");
spdk_trace_register_description("TCP_REQ_WAIT_ZCPY_START",
TRACE_TCP_REQUEST_STATE_AWAIT_ZCOPY_START,
OWNER_NONE, OBJECT_NVMF_TCP_IO, 0,
OWNER_NVMF_TCP, OBJECT_NVMF_TCP_IO, 0,
SPDK_TRACE_ARG_TYPE_PTR, "qpair");
spdk_trace_register_description("TCP_REQ_ZCPY_START_CPL",
TRACE_TCP_REQUEST_STATE_ZCOPY_START_COMPLETED,
OWNER_NONE, OBJECT_NVMF_TCP_IO, 0,
OWNER_NVMF_TCP, OBJECT_NVMF_TCP_IO, 0,
SPDK_TRACE_ARG_TYPE_PTR, "qpair");
spdk_trace_register_description("TCP_REQ_TX_H_TO_C",
TRACE_TCP_REQUEST_STATE_TRANSFERRING_HOST_TO_CONTROLLER,
OWNER_NONE, OBJECT_NVMF_TCP_IO, 0,
OWNER_NVMF_TCP, OBJECT_NVMF_TCP_IO, 0,
SPDK_TRACE_ARG_TYPE_PTR, "qpair");
spdk_trace_register_description("TCP_REQ_RDY_TO_EXECUTE",
TRACE_TCP_REQUEST_STATE_READY_TO_EXECUTE,
OWNER_NONE, OBJECT_NVMF_TCP_IO, 0,
OWNER_NVMF_TCP, OBJECT_NVMF_TCP_IO, 0,
SPDK_TRACE_ARG_TYPE_PTR, "qpair");
spdk_trace_register_description("TCP_REQ_EXECUTING",
TRACE_TCP_REQUEST_STATE_EXECUTING,
OWNER_NONE, OBJECT_NVMF_TCP_IO, 0,
OWNER_NVMF_TCP, OBJECT_NVMF_TCP_IO, 0,
SPDK_TRACE_ARG_TYPE_PTR, "qpair");
spdk_trace_register_description("TCP_REQ_WAIT_ZCPY_CMT",
TRACE_TCP_REQUEST_STATE_AWAIT_ZCOPY_COMMIT,
OWNER_NONE, OBJECT_NVMF_TCP_IO, 0,
OWNER_NVMF_TCP, OBJECT_NVMF_TCP_IO, 0,
SPDK_TRACE_ARG_TYPE_PTR, "qpair");
spdk_trace_register_description("TCP_REQ_EXECUTED",
TRACE_TCP_REQUEST_STATE_EXECUTED,
OWNER_NONE, OBJECT_NVMF_TCP_IO, 0,
OWNER_NVMF_TCP, OBJECT_NVMF_TCP_IO, 0,
SPDK_TRACE_ARG_TYPE_PTR, "qpair");
spdk_trace_register_description("TCP_REQ_RDY_TO_COMPLETE",
TRACE_TCP_REQUEST_STATE_READY_TO_COMPLETE,
OWNER_NONE, OBJECT_NVMF_TCP_IO, 0,
OWNER_NVMF_TCP, OBJECT_NVMF_TCP_IO, 0,
SPDK_TRACE_ARG_TYPE_PTR, "qpair");
spdk_trace_register_description("TCP_REQ_TRANSFER_C2H",
TRACE_TCP_REQUEST_STATE_TRANSFERRING_CONTROLLER_TO_HOST,
OWNER_NONE, OBJECT_NVMF_TCP_IO, 0,
OWNER_NVMF_TCP, OBJECT_NVMF_TCP_IO, 0,
SPDK_TRACE_ARG_TYPE_PTR, "qpair");
spdk_trace_register_description("TCP_REQ_AWAIT_ZCPY_RLS",
TRACE_TCP_REQUEST_STATE_AWAIT_ZCOPY_RELEASE,
OWNER_NONE, OBJECT_NVMF_TCP_IO, 0,
OWNER_NVMF_TCP, OBJECT_NVMF_TCP_IO, 0,
SPDK_TRACE_ARG_TYPE_PTR, "qpair");
spdk_trace_register_description("TCP_REQ_COMPLETED",
TRACE_TCP_REQUEST_STATE_COMPLETED,
OWNER_NONE, OBJECT_NVMF_TCP_IO, 0,
OWNER_NVMF_TCP, OBJECT_NVMF_TCP_IO, 0,
SPDK_TRACE_ARG_TYPE_PTR, "qpair");
spdk_trace_register_description("TCP_WRITE_START",
TRACE_TCP_FLUSH_WRITEBUF_START,
OWNER_NONE, OBJECT_NONE, 0,
OWNER_NVMF_TCP, OBJECT_NONE, 0,
SPDK_TRACE_ARG_TYPE_PTR, "qpair");
spdk_trace_register_description("TCP_WRITE_DONE",
TRACE_TCP_FLUSH_WRITEBUF_DONE,
OWNER_NONE, OBJECT_NONE, 0,
OWNER_NVMF_TCP, OBJECT_NONE, 0,
SPDK_TRACE_ARG_TYPE_PTR, "qpair");
spdk_trace_register_description("TCP_READ_DONE",
TRACE_TCP_READ_FROM_SOCKET_DONE,
OWNER_NONE, OBJECT_NONE, 0,
OWNER_NVMF_TCP, OBJECT_NONE, 0,
SPDK_TRACE_ARG_TYPE_PTR, "qpair");
spdk_trace_register_description("TCP_REQ_AWAIT_R2T_ACK",
TRACE_TCP_REQUEST_STATE_AWAIT_R2T_ACK,
OWNER_NONE, OBJECT_NVMF_TCP_IO, 0,
OWNER_NVMF_TCP, OBJECT_NVMF_TCP_IO, 0,
SPDK_TRACE_ARG_TYPE_PTR, "qpair");

spdk_trace_register_description("TCP_QP_CREATE", TRACE_TCP_QP_CREATE,
OWNER_NONE, OBJECT_NONE, 0,
OWNER_NVMF_TCP, OBJECT_NONE, 0,
SPDK_TRACE_ARG_TYPE_INT, "");
spdk_trace_register_description("TCP_QP_SOCK_INIT", TRACE_TCP_QP_SOCK_INIT,
OWNER_NONE, OBJECT_NONE, 0,
OWNER_NVMF_TCP, OBJECT_NONE, 0,
SPDK_TRACE_ARG_TYPE_INT, "");
spdk_trace_register_description("TCP_QP_STATE_CHANGE", TRACE_TCP_QP_STATE_CHANGE,
OWNER_NONE, OBJECT_NONE, 0,
OWNER_NVMF_TCP, OBJECT_NONE, 0,
SPDK_TRACE_ARG_TYPE_INT, "state");
spdk_trace_register_description("TCP_QP_DISCONNECT", TRACE_TCP_QP_DISCONNECT,
OWNER_NONE, OBJECT_NONE, 0,
OWNER_NVMF_TCP, OBJECT_NONE, 0,
SPDK_TRACE_ARG_TYPE_INT, "");
spdk_trace_register_description("TCP_QP_DESTROY", TRACE_TCP_QP_DESTROY,
OWNER_NONE, OBJECT_NONE, 0,
OWNER_NVMF_TCP, OBJECT_NONE, 0,
SPDK_TRACE_ARG_TYPE_INT, "");
spdk_trace_register_description("TCP_QP_ABORT_REQ", TRACE_TCP_QP_ABORT_REQ,
OWNER_NONE, OBJECT_NONE, 0,
OWNER_NVMF_TCP, OBJECT_NONE, 0,
SPDK_TRACE_ARG_TYPE_PTR, "qpair");
spdk_trace_register_description("TCP_QP_RCV_STATE_CHANGE", TRACE_TCP_QP_RCV_STATE_CHANGE,
OWNER_NONE, OBJECT_NONE, 0,
OWNER_NVMF_TCP, OBJECT_NONE, 0,
SPDK_TRACE_ARG_TYPE_INT, "state");

spdk_trace_tpoint_register_relation(TRACE_BDEV_IO_START, OBJECT_NVMF_TCP_IO, 1);
Expand Down Expand Up @@ -854,7 +855,8 @@ static void
nvmf_tcp_qpair_set_state(struct spdk_nvmf_tcp_qpair *tqpair, enum nvme_tcp_qpair_state state)
{
tqpair->state = state;
spdk_trace_record(TRACE_TCP_QP_STATE_CHANGE, 0, 0, (uintptr_t)tqpair, tqpair->state);
spdk_trace_record(TRACE_TCP_QP_STATE_CHANGE, tqpair->qpair.qid, 0, (uintptr_t)tqpair,
tqpair->state);
}

static void
Expand Down Expand Up @@ -1366,7 +1368,8 @@ nvmf_tcp_qpair_set_recv_state(struct spdk_nvmf_tcp_qpair *tqpair,
SPDK_DEBUGLOG(nvmf_tcp, "tqpair(%p) recv state=%d\n", tqpair, state);
tqpair->recv_state = state;

spdk_trace_record(TRACE_TCP_QP_RCV_STATE_CHANGE, 0, 0, (uintptr_t)tqpair, tqpair->recv_state);
spdk_trace_record(TRACE_TCP_QP_RCV_STATE_CHANGE, tqpair->qpair.qid, 0, (uintptr_t)tqpair,
tqpair->recv_state);

switch (state) {
case NVME_TCP_PDU_RECV_STATE_AWAIT_PDU_CH:
Expand Down Expand Up @@ -2116,7 +2119,7 @@ nvmf_tcp_sock_process(struct spdk_nvmf_tcp_qpair *tqpair)
return NVME_TCP_PDU_FATAL;
} else if (rc > 0) {
pdu->ch_valid_bytes += rc;
spdk_trace_record(TRACE_TCP_READ_FROM_SOCKET_DONE, 0, rc, 0, tqpair);
spdk_trace_record(TRACE_TCP_READ_FROM_SOCKET_DONE, tqpair->qpair.qid, rc, 0, tqpair);
if (spdk_likely(tqpair->recv_state == NVME_TCP_PDU_RECV_STATE_AWAIT_PDU_READY)) {
nvmf_tcp_qpair_set_recv_state(tqpair, NVME_TCP_PDU_RECV_STATE_AWAIT_PDU_CH);
}
Expand All @@ -2137,7 +2140,7 @@ nvmf_tcp_sock_process(struct spdk_nvmf_tcp_qpair *tqpair)
if (rc < 0) {
return NVME_TCP_PDU_FATAL;
} else if (rc > 0) {
spdk_trace_record(TRACE_TCP_READ_FROM_SOCKET_DONE, 0, rc, 0, tqpair);
spdk_trace_record(TRACE_TCP_READ_FROM_SOCKET_DONE, tqpair->qpair.qid, rc, 0, tqpair);
pdu->psh_valid_bytes += rc;
}

Expand Down Expand Up @@ -2589,7 +2592,7 @@ nvmf_tcp_req_process(struct spdk_nvmf_tcp_transport *ttransport,
* to escape this state. */
break;
case TCP_REQUEST_STATE_NEW:
spdk_trace_record(TRACE_TCP_REQUEST_STATE_NEW, 0, 0, (uintptr_t)tcp_req, tqpair);
spdk_trace_record(TRACE_TCP_REQUEST_STATE_NEW, tqpair->qpair.qid, 0, (uintptr_t)tcp_req, tqpair);

/* copy the cmd from the receive pdu */
tcp_req->cmd = tqpair->pdu_in_progress->hdr.capsule_cmd.ccsqe;
Expand Down Expand Up @@ -2630,7 +2633,8 @@ nvmf_tcp_req_process(struct spdk_nvmf_tcp_transport *ttransport,
STAILQ_INSERT_TAIL(&group->pending_buf_queue, &tcp_req->req, buf_link);
break;
case TCP_REQUEST_STATE_NEED_BUFFER:
spdk_trace_record(TRACE_TCP_REQUEST_STATE_NEED_BUFFER, 0, 0, (uintptr_t)tcp_req, tqpair);
spdk_trace_record(TRACE_TCP_REQUEST_STATE_NEED_BUFFER, tqpair->qpair.qid, 0, (uintptr_t)tcp_req,
tqpair);

assert(tcp_req->req.xfer != SPDK_NVME_DATA_NONE);

Expand Down Expand Up @@ -2700,13 +2704,13 @@ nvmf_tcp_req_process(struct spdk_nvmf_tcp_transport *ttransport,
nvmf_tcp_req_set_state(tcp_req, TCP_REQUEST_STATE_READY_TO_EXECUTE);
break;
case TCP_REQUEST_STATE_AWAITING_ZCOPY_START:
spdk_trace_record(TRACE_TCP_REQUEST_STATE_AWAIT_ZCOPY_START, 0, 0,
spdk_trace_record(TRACE_TCP_REQUEST_STATE_AWAIT_ZCOPY_START, tqpair->qpair.qid, 0,
(uintptr_t)tcp_req, tqpair);
/* Some external code must kick a request into TCP_REQUEST_STATE_ZCOPY_START_COMPLETED
* to escape this state. */
break;
case TCP_REQUEST_STATE_ZCOPY_START_COMPLETED:
spdk_trace_record(TRACE_TCP_REQUEST_STATE_ZCOPY_START_COMPLETED, 0, 0,
spdk_trace_record(TRACE_TCP_REQUEST_STATE_ZCOPY_START_COMPLETED, tqpair->qpair.qid, 0,
(uintptr_t)tcp_req, tqpair);
if (spdk_unlikely(spdk_nvme_cpl_is_error(&tcp_req->req.rsp->nvme_cpl))) {
SPDK_DEBUGLOG(nvmf_tcp, "Zero-copy start failed for tcp_req(%p) on tqpair=%p\n",
Expand All @@ -2722,20 +2726,20 @@ nvmf_tcp_req_process(struct spdk_nvmf_tcp_transport *ttransport,
}
break;
case TCP_REQUEST_STATE_AWAITING_R2T_ACK:
spdk_trace_record(TRACE_TCP_REQUEST_STATE_AWAIT_R2T_ACK, 0, 0, (uintptr_t)tcp_req,
spdk_trace_record(TRACE_TCP_REQUEST_STATE_AWAIT_R2T_ACK, tqpair->qpair.qid, 0, (uintptr_t)tcp_req,
tqpair);
/* The R2T completion or the h2c data incoming will kick it out of this state. */
break;
case TCP_REQUEST_STATE_TRANSFERRING_HOST_TO_CONTROLLER:

spdk_trace_record(TRACE_TCP_REQUEST_STATE_TRANSFERRING_HOST_TO_CONTROLLER, 0, 0,
spdk_trace_record(TRACE_TCP_REQUEST_STATE_TRANSFERRING_HOST_TO_CONTROLLER, tqpair->qpair.qid, 0,
(uintptr_t)tcp_req, tqpair);
/* Some external code must kick a request into TCP_REQUEST_STATE_READY_TO_EXECUTE
* to escape this state. */
break;
case TCP_REQUEST_STATE_READY_TO_EXECUTE:
spdk_trace_record(TRACE_TCP_REQUEST_STATE_READY_TO_EXECUTE, 0, 0, (uintptr_t)tcp_req,
tqpair);
spdk_trace_record(TRACE_TCP_REQUEST_STATE_READY_TO_EXECUTE, tqpair->qpair.qid, 0,
(uintptr_t)tcp_req, tqpair);

if (spdk_unlikely(tcp_req->req.dif_enabled)) {
assert(tcp_req->req.dif.elba_length >= tcp_req->req.length);
Expand All @@ -2754,18 +2758,20 @@ nvmf_tcp_req_process(struct spdk_nvmf_tcp_transport *ttransport,
}
break;
case TCP_REQUEST_STATE_EXECUTING:
spdk_trace_record(TRACE_TCP_REQUEST_STATE_EXECUTING, 0, 0, (uintptr_t)tcp_req, tqpair);
spdk_trace_record(TRACE_TCP_REQUEST_STATE_EXECUTING, tqpair->qpair.qid, 0, (uintptr_t)tcp_req,
tqpair);
/* Some external code must kick a request into TCP_REQUEST_STATE_EXECUTED
* to escape this state. */
break;
case TCP_REQUEST_STATE_AWAITING_ZCOPY_COMMIT:
spdk_trace_record(TRACE_TCP_REQUEST_STATE_AWAIT_ZCOPY_COMMIT, 0, 0,
spdk_trace_record(TRACE_TCP_REQUEST_STATE_AWAIT_ZCOPY_COMMIT, tqpair->qpair.qid, 0,
(uintptr_t)tcp_req, tqpair);
/* Some external code must kick a request into TCP_REQUEST_STATE_EXECUTED
* to escape this state. */
break;
case TCP_REQUEST_STATE_EXECUTED:
spdk_trace_record(TRACE_TCP_REQUEST_STATE_EXECUTED, 0, 0, (uintptr_t)tcp_req, tqpair);
spdk_trace_record(TRACE_TCP_REQUEST_STATE_EXECUTED, tqpair->qpair.qid, 0, (uintptr_t)tcp_req,
tqpair);

if (spdk_unlikely(tcp_req->req.dif_enabled)) {
tcp_req->req.length = tcp_req->req.dif.orig_length;
Expand All @@ -2774,25 +2780,26 @@ nvmf_tcp_req_process(struct spdk_nvmf_tcp_transport *ttransport,
nvmf_tcp_req_set_state(tcp_req, TCP_REQUEST_STATE_READY_TO_COMPLETE);
break;
case TCP_REQUEST_STATE_READY_TO_COMPLETE:
spdk_trace_record(TRACE_TCP_REQUEST_STATE_READY_TO_COMPLETE, 0, 0, (uintptr_t)tcp_req,
tqpair);
spdk_trace_record(TRACE_TCP_REQUEST_STATE_READY_TO_COMPLETE, tqpair->qpair.qid, 0,
(uintptr_t)tcp_req, tqpair);
rc = request_transfer_out(&tcp_req->req);
assert(rc == 0); /* No good way to handle this currently */
break;
case TCP_REQUEST_STATE_TRANSFERRING_CONTROLLER_TO_HOST:
spdk_trace_record(TRACE_TCP_REQUEST_STATE_TRANSFERRING_CONTROLLER_TO_HOST, 0, 0,
spdk_trace_record(TRACE_TCP_REQUEST_STATE_TRANSFERRING_CONTROLLER_TO_HOST, tqpair->qpair.qid, 0,
(uintptr_t)tcp_req, tqpair);
/* Some external code must kick a request into TCP_REQUEST_STATE_COMPLETED
* to escape this state. */
break;
case TCP_REQUEST_STATE_AWAITING_ZCOPY_RELEASE:
spdk_trace_record(TRACE_TCP_REQUEST_STATE_AWAIT_ZCOPY_RELEASE, 0, 0,
spdk_trace_record(TRACE_TCP_REQUEST_STATE_AWAIT_ZCOPY_RELEASE, tqpair->qpair.qid, 0,
(uintptr_t)tcp_req, tqpair);
/* Some external code must kick a request into TCP_REQUEST_STATE_COMPLETED
* to escape this state. */
break;
case TCP_REQUEST_STATE_COMPLETED:
spdk_trace_record(TRACE_TCP_REQUEST_STATE_COMPLETED, 0, 0, (uintptr_t)tcp_req, tqpair);
spdk_trace_record(TRACE_TCP_REQUEST_STATE_COMPLETED, tqpair->qpair.qid, 0, (uintptr_t)tcp_req,
tqpair);
if (tcp_req->req.data_from_pool) {
spdk_nvmf_request_free_buffers(&tcp_req->req, group, transport);
} else if (spdk_unlikely(tcp_req->has_in_capsule_data &&
Expand Down Expand Up @@ -3146,7 +3153,7 @@ nvmf_tcp_qpair_abort_request(struct spdk_nvmf_qpair *qpair,
}
}

spdk_trace_record(TRACE_TCP_QP_ABORT_REQ, 0, 0, (uintptr_t)req, tqpair);
spdk_trace_record(TRACE_TCP_QP_ABORT_REQ, qpair->qid, 0, (uintptr_t)req, tqpair);

if (tcp_req_to_abort == NULL) {
spdk_nvmf_request_complete(req);
Expand Down

0 comments on commit 027bfbb

Please sign in to comment.