Skip to content

Commit 649deec

Browse files
author
root
committed
nvmf tcp logs
1 parent e76c814 commit 649deec

File tree

7 files changed

+126
-21
lines changed

7 files changed

+126
-21
lines changed

‎include/spdk/nvme.h

+1
Original file line numberDiff line numberDiff line change
@@ -4057,6 +4057,7 @@ uint32_t spdk_nvme_qpair_get_num_outstanding_reqs(struct spdk_nvme_qpair *qpair)
40574057
* \param cmd Pointer to the submission queue command to be formatted.
40584058
*/
40594059
void spdk_nvme_print_command(uint16_t qid, struct spdk_nvme_cmd *cmd);
4060+
void spdk_nvme_print_command_s(uint16_t qid, struct spdk_nvme_cmd *cmd);
40604061

40614062
/**
40624063
* \brief Prints (SPDK_NOTICELOG) the contents of an NVMe completion queue entry.

‎lib/nvme/nvme_qpair.c

+78-4
Original file line numberDiff line numberDiff line change
@@ -270,6 +270,80 @@ spdk_nvme_print_command(uint16_t qid, struct spdk_nvme_cmd *cmd)
270270
}
271271
}
272272

273+
274+
static void
275+
nvme_admin_qpair_print_command_s(uint16_t qid, struct spdk_nvme_cmd *cmd)
276+
{
277+
struct spdk_nvmf_capsule_cmd *fcmd = (void *)cmd;
278+
char dptr[NVME_CMD_DPTR_STR_SIZE] = {'\0'};
279+
280+
assert(cmd != NULL);
281+
282+
nvme_get_dptr(dptr, sizeof(dptr), cmd);
283+
284+
switch ((int)cmd->opc) {
285+
case SPDK_NVME_OPC_SET_FEATURES:
286+
case SPDK_NVME_OPC_GET_FEATURES:
287+
SPDK_NOTICELOG("%s %s cid:%d cdw10:%08x %s\n",
288+
nvme_get_string(admin_opcode, cmd->opc), nvme_get_string(feat_opcode,
289+
cmd->cdw10_bits.set_features.fid), cmd->cid, cmd->cdw10, dptr);
290+
break;
291+
case SPDK_NVME_OPC_FABRIC:
292+
SPDK_NOTICELOG("%s %s qid:%d cid:%d %s\n",
293+
nvme_get_string(admin_opcode, cmd->opc), nvme_get_string(fabric_opcode, fcmd->fctype), qid,
294+
fcmd->cid, dptr);
295+
break;
296+
default:
297+
SPDK_NOTICELOG("%s (%02x) qid:%d cid:%d nsid:%x cdw10:%08x cdw11:%08x %s\n",
298+
nvme_get_string(admin_opcode, cmd->opc), cmd->opc, qid, cmd->cid, cmd->nsid, cmd->cdw10,
299+
cmd->cdw11, dptr);
300+
}
301+
}
302+
303+
static void
304+
nvme_io_qpair_print_command_s(uint16_t qid, struct spdk_nvme_cmd *cmd)
305+
{
306+
char dptr[NVME_CMD_DPTR_STR_SIZE] = {'\0'};
307+
308+
assert(cmd != NULL);
309+
310+
nvme_get_dptr(dptr, sizeof(dptr), cmd);
311+
312+
switch ((int)cmd->opc) {
313+
case SPDK_NVME_OPC_WRITE:
314+
case SPDK_NVME_OPC_READ:
315+
case SPDK_NVME_OPC_WRITE_UNCORRECTABLE:
316+
case SPDK_NVME_OPC_COMPARE:
317+
SPDK_NOTICELOG("%s sqid:%d cid:%d nsid:%d "
318+
"lba:%llu len:%d %s\n",
319+
nvme_get_string(io_opcode, cmd->opc), qid, cmd->cid, cmd->nsid,
320+
((unsigned long long)cmd->cdw11 << 32) + cmd->cdw10,
321+
(cmd->cdw12 & 0xFFFF) + 1, dptr);
322+
break;
323+
case SPDK_NVME_OPC_FLUSH:
324+
case SPDK_NVME_OPC_DATASET_MANAGEMENT:
325+
SPDK_NOTICELOG("%s sqid:%d cid:%d nsid:%d\n",
326+
nvme_get_string(io_opcode, cmd->opc), qid, cmd->cid, cmd->nsid);
327+
break;
328+
default:
329+
SPDK_NOTICELOG("%s (%02x) sqid:%d cid:%d nsid:%d\n",
330+
nvme_get_string(io_opcode, cmd->opc), cmd->opc, qid, cmd->cid, cmd->nsid);
331+
break;
332+
}
333+
}
334+
335+
void
336+
spdk_nvme_print_command_s(uint16_t qid, struct spdk_nvme_cmd *cmd)
337+
{
338+
assert(cmd != NULL);
339+
340+
if (qid == 0 || cmd->opc == SPDK_NVME_OPC_FABRIC) {
341+
nvme_admin_qpair_print_command_s(qid, cmd);
342+
} else {
343+
nvme_io_qpair_print_command_s(qid, cmd);
344+
}
345+
}
346+
273347
void
274348
spdk_nvme_qpair_print_command(struct spdk_nvme_qpair *qpair, struct spdk_nvme_cmd *cmd)
275349
{
@@ -471,10 +545,10 @@ spdk_nvme_print_completion(uint16_t qid, struct spdk_nvme_cpl *cpl)
471545
SPDK_ERRLOG("sqid %u doesn't match qid\n", cpl->sqid);
472546
}
473547

474-
SPDK_NOTICELOG("%s (%02x/%02x) qid:%d cid:%d cdw0:%x sqhd:%04x p:%x m:%x dnr:%x\n",
475-
spdk_nvme_cpl_get_status_string(&cpl->status),
476-
cpl->status.sct, cpl->status.sc, qid, cpl->cid, cpl->cdw0,
477-
cpl->sqhd, cpl->status.p, cpl->status.m, cpl->status.dnr);
548+
// SPDK_NOTICELOG("%s (%02x/%02x) qid:%d cid:%d cdw0:%x sqhd:%04x p:%x m:%x dnr:%x\n",
549+
// spdk_nvme_cpl_get_status_string(&cpl->status),
550+
// cpl->status.sct, cpl->status.sc, qid, cpl->cid, cpl->cdw0,
551+
// cpl->sqhd, cpl->status.p, cpl->status.m, cpl->status.dnr);
478552
}
479553

480554
void

‎lib/nvmf/ctrlr.c

+14
Original file line numberDiff line numberDiff line change
@@ -3733,18 +3733,25 @@ nvmf_ctrlr_process_admin_cmd(struct spdk_nvmf_request *req)
37333733

37343734
switch (cmd->opc) {
37353735
case SPDK_NVME_OPC_GET_LOG_PAGE:
3736+
SPDK_NOTICELOG("admin qpair - 2 \n");
37363737
return nvmf_ctrlr_get_log_page(req);
37373738
case SPDK_NVME_OPC_IDENTIFY:
3739+
SPDK_NOTICELOG("admin qpair - 3 \n");
37383740
return nvmf_ctrlr_identify(req);
37393741
case SPDK_NVME_OPC_ABORT:
3742+
SPDK_NOTICELOG("admin qpair - 4 \n");
37403743
return nvmf_ctrlr_abort(req);
37413744
case SPDK_NVME_OPC_GET_FEATURES:
3745+
SPDK_NOTICELOG("admin qpair - 5 \n");
37423746
return nvmf_ctrlr_get_features(req);
37433747
case SPDK_NVME_OPC_SET_FEATURES:
3748+
SPDK_NOTICELOG("admin qpair - 6 \n");
37443749
return nvmf_ctrlr_set_features(req);
37453750
case SPDK_NVME_OPC_ASYNC_EVENT_REQUEST:
3751+
SPDK_NOTICELOG("admin qpair - 7 \n");
37463752
return nvmf_ctrlr_async_event_request(req);
37473753
case SPDK_NVME_OPC_KEEP_ALIVE:
3754+
SPDK_NOTICELOG("admin qpair - 8 \n");
37483755
return nvmf_ctrlr_keep_alive(req);
37493756

37503757
case SPDK_NVME_OPC_CREATE_IO_SQ:
@@ -3776,6 +3783,7 @@ nvmf_ctrlr_process_fabrics_cmd(struct spdk_nvmf_request *req)
37763783
if (qpair->ctrlr == NULL) {
37773784
/* No ctrlr established yet; the only valid command is Connect */
37783785
assert(cap_hdr->fctype == SPDK_NVMF_FABRIC_COMMAND_CONNECT);
3786+
SPDK_NOTICELOG("SPDK_NVME_OPC_FABRIC 2 \n");
37793787
return nvmf_ctrlr_cmd_connect(req);
37803788
} else if (nvmf_qpair_is_admin_queue(qpair)) {
37813789
/*
@@ -3784,8 +3792,10 @@ nvmf_ctrlr_process_fabrics_cmd(struct spdk_nvmf_request *req)
37843792
*/
37853793
switch (cap_hdr->fctype) {
37863794
case SPDK_NVMF_FABRIC_COMMAND_PROPERTY_SET:
3795+
SPDK_NOTICELOG("SPDK_NVME_OPC_FABRIC 3 \n");
37873796
return nvmf_property_set(req);
37883797
case SPDK_NVMF_FABRIC_COMMAND_PROPERTY_GET:
3798+
SPDK_NOTICELOG("SPDK_NVME_OPC_FABRIC 4 \n");
37893799
return nvmf_property_get(req);
37903800
case SPDK_NVMF_FABRIC_COMMAND_AUTHENTICATION_SEND:
37913801
case SPDK_NVMF_FABRIC_COMMAND_AUTHENTICATION_RECV:
@@ -4734,8 +4744,12 @@ spdk_nvmf_request_exec(struct spdk_nvmf_request *req)
47344744
TAILQ_INSERT_TAIL(&qpair->outstanding, req, link);
47354745

47364746
if (spdk_unlikely(req->cmd->nvmf_cmd.opcode == SPDK_NVME_OPC_FABRIC)) {
4747+
SPDK_NOTICELOG("SPDK_NVME_OPC_FABRIC 1 \n");
4748+
spdk_nvme_print_command_s(qpair->qid, &req->cmd->nvme_cmd);
47374749
status = nvmf_ctrlr_process_fabrics_cmd(req);
47384750
} else if (spdk_unlikely(nvmf_qpair_is_admin_queue(qpair))) {
4751+
SPDK_NOTICELOG("admin qpair - 1 \n");
4752+
spdk_nvme_print_command_s(qpair->qid, &req->cmd->nvme_cmd);
47394753
status = nvmf_ctrlr_process_admin_cmd(req);
47404754
} else {
47414755
status = nvmf_ctrlr_process_io_cmd(req);

‎lib/nvmf/nvmf.c

+8
Original file line numberDiff line numberDiff line change
@@ -1575,6 +1575,13 @@ poll_group_update_subsystem(struct spdk_nvmf_poll_group *group,
15751575
group,
15761576
ns_info->num_blocks,
15771577
spdk_bdev_get_num_blocks(ns->bdev));
1578+
SPDK_NOTICELOG("Namespace resized: subsystem_id %u,"
1579+
" nsid %u, pg %p, old %" PRIu64 ", new %" PRIu64 "\n",
1580+
subsystem->id,
1581+
ns->nsid,
1582+
group,
1583+
ns_info->num_blocks,
1584+
spdk_bdev_get_num_blocks(ns->bdev));
15781585
ns_changed = true;
15791586
}
15801587

@@ -1613,6 +1620,7 @@ poll_group_update_subsystem(struct spdk_nvmf_poll_group *group,
16131620
continue;
16141621
}
16151622
if (ctrlr->admin_qpair->group == group) {
1623+
SPDK_NOTICELOG("Namespace resized: send aer request.\n");
16161624
nvmf_ctrlr_async_event_ns_notice(ctrlr);
16171625
nvmf_ctrlr_async_event_ana_change_notice(ctrlr);
16181626
}

‎lib/nvmf/tcp.c

+23-17
Original file line numberDiff line numberDiff line change
@@ -2861,10 +2861,16 @@ nvmf_tcp_check_fused_ordering(struct spdk_nvmf_tcp_transport *ttransport,
28612861
}
28622862
}
28632863

2864-
static void check_time(struct spdk_nvmf_tcp_req *tcp_req) {
2865-
if (!tcp_req->loged && tcp_req->time) {
2866-
if (spdk_get_ticks() - tcp_req->time > spdk_get_ticks_hz() * 2){
2867-
SPDK_NOTICELOG("tcp_req ttag %d, tcp_req \n", tcp_req->ttag);
2864+
static void
2865+
check_time(struct spdk_nvmf_tcp_req *tcp_req, struct spdk_nvmf_tcp_qpair *tqpair) {
2866+
if (!tcp_req->loged && tcp_req->time && (tqpair->target_port <= 9099 && tqpair->target_port >= 9090)) {
2867+
// if (spdk_get_ticks() - tcp_req->time > spdk_get_ticks_hz() && tqpair->qpair.qid) {
2868+
if (spdk_get_ticks() - tcp_req->time > spdk_get_ticks_hz()) {
2869+
SPDK_NOTICELOG("tcp_req ttag %d (QID %d) cport %d sport %d\n", tcp_req->ttag, tqpair->qpair.qid, tqpair->initiator_port, tqpair->target_port);
2870+
spdk_nvme_print_command_s(tqpair->qpair.qid, &tcp_req->cmd);
2871+
if (tqpair->qpair.qid) {
2872+
nvmf_tcp_dump_qpair_req_contents(tqpair);
2873+
}
28682874
tcp_req->loged = false;
28692875
}
28702876
}
@@ -2960,7 +2966,7 @@ nvmf_tcp_req_process(struct spdk_nvmf_tcp_transport *ttransport,
29602966
case TCP_REQUEST_STATE_NEED_BUFFER:
29612967
spdk_trace_record(TRACE_TCP_REQUEST_STATE_NEED_BUFFER, tqpair->qpair.trace_id, 0,
29622968
(uintptr_t)tcp_req);
2963-
check_time(tcp_req);
2969+
check_time(tcp_req, tqpair);
29642970

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

@@ -3027,12 +3033,12 @@ nvmf_tcp_req_process(struct spdk_nvmf_tcp_transport *ttransport,
30273033
(uintptr_t)tcp_req);
30283034
/* Some external code must kick a request into TCP_REQUEST_STATE_ZCOPY_START_COMPLETED
30293035
* to escape this state. */
3030-
check_time(tcp_req);
3036+
check_time(tcp_req, tqpair);
30313037
break;
30323038
case TCP_REQUEST_STATE_ZCOPY_START_COMPLETED:
30333039
spdk_trace_record(TRACE_TCP_REQUEST_STATE_ZCOPY_START_COMPLETED, tqpair->qpair.trace_id, 0,
30343040
(uintptr_t)tcp_req);
3035-
check_time(tcp_req);
3041+
check_time(tcp_req, tqpair);
30363042
if (spdk_unlikely(spdk_nvme_cpl_is_error(&tcp_req->req.rsp->nvme_cpl))) {
30373043
SPDK_DEBUGLOG(nvmf_tcp, "Zero-copy start failed for tcp_req(%p) on tqpair=%p\n",
30383044
tcp_req, tqpair);
@@ -3049,7 +3055,7 @@ nvmf_tcp_req_process(struct spdk_nvmf_tcp_transport *ttransport,
30493055
case TCP_REQUEST_STATE_AWAITING_R2T_ACK:
30503056
spdk_trace_record(TRACE_TCP_REQUEST_STATE_AWAIT_R2T_ACK, tqpair->qpair.trace_id, 0,
30513057
(uintptr_t)tcp_req);
3052-
check_time(tcp_req);
3058+
check_time(tcp_req, tqpair);
30533059
/* The R2T completion or the h2c data incoming will kick it out of this state. */
30543060
break;
30553061
case TCP_REQUEST_STATE_TRANSFERRING_HOST_TO_CONTROLLER:
@@ -3058,12 +3064,12 @@ nvmf_tcp_req_process(struct spdk_nvmf_tcp_transport *ttransport,
30583064
0, (uintptr_t)tcp_req);
30593065
/* Some external code must kick a request into TCP_REQUEST_STATE_READY_TO_EXECUTE
30603066
* to escape this state. */
3061-
check_time(tcp_req);
3067+
check_time(tcp_req, tqpair);
30623068
break;
30633069
case TCP_REQUEST_STATE_READY_TO_EXECUTE:
30643070
spdk_trace_record(TRACE_TCP_REQUEST_STATE_READY_TO_EXECUTE, tqpair->qpair.trace_id, 0,
30653071
(uintptr_t)tcp_req);
3066-
check_time(tcp_req);
3072+
check_time(tcp_req, tqpair);
30673073

30683074
if (spdk_unlikely(tcp_req->req.dif_enabled)) {
30693075
assert(tcp_req->req.dif.elba_length >= tcp_req->req.length);
@@ -3131,28 +3137,28 @@ nvmf_tcp_req_process(struct spdk_nvmf_tcp_transport *ttransport,
31313137
spdk_trace_record(TRACE_TCP_REQUEST_STATE_EXECUTING, tqpair->qpair.trace_id, 0, (uintptr_t)tcp_req);
31323138
/* Some external code must kick a request into TCP_REQUEST_STATE_EXECUTED
31333139
* to escape this state. */
3134-
check_time(tcp_req);
3140+
check_time(tcp_req, tqpair);
31353141
break;
31363142
case TCP_REQUEST_STATE_AWAITING_ZCOPY_COMMIT:
31373143
spdk_trace_record(TRACE_TCP_REQUEST_STATE_AWAIT_ZCOPY_COMMIT, tqpair->qpair.trace_id, 0,
31383144
(uintptr_t)tcp_req);
31393145
/* Some external code must kick a request into TCP_REQUEST_STATE_EXECUTED
31403146
* to escape this state. */
3141-
check_time(tcp_req);
3147+
check_time(tcp_req, tqpair);
31423148
break;
31433149
case TCP_REQUEST_STATE_EXECUTED:
31443150
spdk_trace_record(TRACE_TCP_REQUEST_STATE_EXECUTED, tqpair->qpair.trace_id, 0, (uintptr_t)tcp_req);
31453151

31463152
if (spdk_unlikely(tcp_req->req.dif_enabled)) {
31473153
tcp_req->req.length = tcp_req->req.dif.orig_length;
31483154
}
3149-
check_time(tcp_req);
3155+
check_time(tcp_req, tqpair);
31503156
nvmf_tcp_req_set_state(tcp_req, TCP_REQUEST_STATE_READY_TO_COMPLETE);
31513157
break;
31523158
case TCP_REQUEST_STATE_READY_TO_COMPLETE:
31533159
spdk_trace_record(TRACE_TCP_REQUEST_STATE_READY_TO_COMPLETE, tqpair->qpair.trace_id, 0,
31543160
(uintptr_t)tcp_req);
3155-
check_time(tcp_req);
3161+
check_time(tcp_req, tqpair);
31563162
tcp_req->time = 0;
31573163
if (request_transfer_out(&tcp_req->req) != 0) {
31583164
assert(0); /* No good way to handle this currently */
@@ -3163,22 +3169,22 @@ nvmf_tcp_req_process(struct spdk_nvmf_tcp_transport *ttransport,
31633169
0, (uintptr_t)tcp_req);
31643170
/* Some external code must kick a request into TCP_REQUEST_STATE_COMPLETED
31653171
* to escape this state. */
3166-
check_time(tcp_req);
3172+
check_time(tcp_req, tqpair);
31673173
break;
31683174
case TCP_REQUEST_STATE_AWAITING_ZCOPY_RELEASE:
31693175
spdk_trace_record(TRACE_TCP_REQUEST_STATE_AWAIT_ZCOPY_RELEASE, tqpair->qpair.trace_id, 0,
31703176
(uintptr_t)tcp_req);
31713177
/* Some external code must kick a request into TCP_REQUEST_STATE_COMPLETED
31723178
* to escape this state. */
3173-
check_time(tcp_req);
3179+
check_time(tcp_req, tqpair);
31743180
break;
31753181
case TCP_REQUEST_STATE_COMPLETED:
31763182
spdk_trace_record(TRACE_TCP_REQUEST_STATE_COMPLETED, tqpair->qpair.trace_id, 0, (uintptr_t)tcp_req,
31773183
tqpair->qpair.queue_depth);
31783184
/* If there's an outstanding PDU sent to the host, the request is completed
31793185
* due to the qpair being disconnected. We must delay the completion until
31803186
* that write is done to avoid freeing the request twice. */
3181-
check_time(tcp_req);
3187+
check_time(tcp_req, tqpair);
31823188
if (spdk_unlikely(tcp_req->pdu_in_use)) {
31833189
SPDK_DEBUGLOG(nvmf_tcp, "Delaying completion due to outstanding "
31843190
"write on req=%p\n", tcp_req);

‎test/unit/lib/nvmf/ctrlr.c/ctrlr_ut.c

+1
Original file line numberDiff line numberDiff line change
@@ -179,6 +179,7 @@ DEFINE_STUB_V(nvmf_transport_qpair_abort_request,
179179
(struct spdk_nvmf_qpair *qpair, struct spdk_nvmf_request *req));
180180

181181
DEFINE_STUB_V(spdk_nvme_print_command, (uint16_t qid, struct spdk_nvme_cmd *cmd));
182+
DEFINE_STUB_V(spdk_nvme_print_command_s, (uint16_t qid, struct spdk_nvme_cmd *cmd));
182183
DEFINE_STUB_V(spdk_nvme_print_completion, (uint16_t qid, struct spdk_nvme_cpl *cpl));
183184

184185
DEFINE_STUB_V(nvmf_subsystem_remove_ctrlr, (struct spdk_nvmf_subsystem *subsystem,

‎test/unit/lib/nvmf/tcp.c/tcp_ut.c

+1
Original file line numberDiff line numberDiff line change
@@ -218,6 +218,7 @@ DEFINE_STUB_V(nvmf_transport_qpair_abort_request,
218218
DEFINE_STUB_V(nvmf_qpair_set_state, (struct spdk_nvmf_qpair *q, enum spdk_nvmf_qpair_state s));
219219

220220
DEFINE_STUB_V(spdk_nvme_print_command, (uint16_t qid, struct spdk_nvme_cmd *cmd));
221+
DEFINE_STUB_V(spdk_nvme_print_command_s, (uint16_t qid, struct spdk_nvme_cmd *cmd));
221222
DEFINE_STUB_V(spdk_nvme_print_completion, (uint16_t qid, struct spdk_nvme_cpl *cpl));
222223

223224
DEFINE_STUB(nvmf_transport_req_free,

0 commit comments

Comments
 (0)