diff --git a/include/spdk_internal/trace_defs.h b/include/spdk_internal/trace_defs.h index 573c31806..4f0ff98f7 100644 --- a/include/spdk_internal/trace_defs.h +++ b/include/spdk_internal/trace_defs.h @@ -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 diff --git a/lib/nvmf/tcp.c b/lib/nvmf/tcp.c index c45f011cd..9281920b6 100644 --- a/lib/nvmf/tcp.c +++ b/lib/nvmf/tcp.c @@ -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); @@ -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 @@ -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: @@ -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); } @@ -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; } @@ -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; @@ -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); @@ -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", @@ -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); @@ -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; @@ -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 && @@ -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);