nvme host complete request tracing
Engel, Amit
Amit.Engel at Dell.com
Fri May 19 02:18:19 PDT 2023
Hi,
I would go with [2],
optionally printing disposition value only when disposition != COMPLETE in the trace_nvme_complete_rq()
Thanks,
Amit
-----Original Message-----
From: Chaitanya Kulkarni <chaitanyak at nvidia.com>
Sent: Friday, 19 May 2023 12:00
To: Sagi Grimberg <sagi at grimberg.me>
Cc: linux-nvme at lists.infradead.org; Engel, Amit <Amit.Engel at Dell.com>
Subject: Re: nvme host complete request tracing
[EXTERNAL EMAIL]
Sagi,
On 5/18/23 02:18, Sagi Grimberg wrote:
>
>> Hello,
>>
>> nvme/host/core.c trace_nvme_complete_rq() is being called immediately
>> when entering nvme_complete_rq() As I understand it, the idea behind
>> this trace is to trace every single nvme request that is being
>> completed.
>> but this is actually not accurate since there are several options for
>> a request as part of this function:
>> COMPLETE, RETRY, FAILOVER
>
> Well, it is completing this particular request.
>
>> In order to better understand the status per nvme request I think
>> it’s better to have a separate trace per each case, something like:
>> trace_nvme_end_rq(req), trace_nvme_retry_rq(req),
>> trace_nvme_failover_rq(req) etc.
>
> Maybe we can add the disposition to the trace?
>
> Something like:
> --
> diff --git a/drivers/nvme/host/core.c b/drivers/nvme/host/core.c index
> b374e6007553..eaf03ff61224 100644
> --- a/drivers/nvme/host/core.c
> +++ b/drivers/nvme/host/core.c
> @@ -393,14 +393,17 @@ static inline void nvme_end_req(struct request
> *req)
> void nvme_complete_rq(struct request *req)
> {
> struct nvme_ctrl *ctrl = nvme_req(req)->ctrl;
> + enum nvme_disposition disposition;
>
> - trace_nvme_complete_rq(req);
> nvme_cleanup_cmd(req);
>
> if (ctrl->kas)
> ctrl->comp_seen = true;
>
> - switch (nvme_decide_disposition(req)) {
> + disposition = nvme_decide_disposition(req);
> + trace_nvme_complete_rq(req, disposition);
> +
> + switch (disposition) {
> case COMPLETE:
> nvme_end_req(req);
> return;
> --
>
Adding disposition to the nvme_complete_rq creates redundant
information since it will always be zero for status=0. Please have
a look at [1].
what do you think about optionally printing disposition value only
when disposition != COMPLETE in the trace_nvme_complete_rq() ?
see [2].
but if everyone is okay with redundant information I'll be happy to
send [1] :).
-ck
[1] duplicate request disposition information with unconditionally
printing disposition value :-
diff --git a/drivers/nvme/host/core.c b/drivers/nvme/host/core.c
index f586a4808e6e..9164fee13704 100644
--- a/drivers/nvme/host/core.c
+++ b/drivers/nvme/host/core.c
@@ -337,13 +337,6 @@ static void nvme_log_error(struct request *req)
nr->status & NVME_SC_DNR ? "DNR " : "");
}
-enum nvme_disposition {
- COMPLETE,
- RETRY,
- FAILOVER,
- AUTHENTICATE,
-};
-
static inline enum nvme_disposition nvme_decide_disposition(struct
request *req)
{
if (likely(nvme_req(req)->status == 0))
@@ -393,14 +386,16 @@ static inline void nvme_end_req(struct request *req)
void nvme_complete_rq(struct request *req)
{
struct nvme_ctrl *ctrl = nvme_req(req)->ctrl;
+ enum nvme_disposition disposition;
- trace_nvme_complete_rq(req);
nvme_cleanup_cmd(req);
if (ctrl->kas)
ctrl->comp_seen = true;
- switch (nvme_decide_disposition(req)) {
+ disposition = nvme_decide_disposition(req);
+ trace_nvme_complete_rq(req, disposition);
+ switch (disposition) {
case COMPLETE:
nvme_end_req(req);
return;
@@ -424,7 +419,7 @@ EXPORT_SYMBOL_GPL(nvme_complete_rq);
void nvme_complete_batch_req(struct request *req)
{
- trace_nvme_complete_rq(req);
+ trace_nvme_complete_rq(req, COMPLETE);
nvme_cleanup_cmd(req);
nvme_end_req_zoned(req);
}
diff --git a/drivers/nvme/host/nvme.h b/drivers/nvme/host/nvme.h
index f0a84e390a55..56e16bdd59ff 100644
--- a/drivers/nvme/host/nvme.h
+++ b/drivers/nvme/host/nvme.h
@@ -1119,4 +1119,12 @@ static inline const unsigned char
*nvme_opcode_str(int qid, u8 opcode, u8 fctype
return qid ? nvme_get_opcode_str(opcode) :
nvme_get_admin_opcode_str(opcode);
}
+
+enum nvme_disposition {
+ COMPLETE,
+ RETRY,
+ FAILOVER,
+ AUTHENTICATE,
+};
+
#endif /* _NVME_H */
diff --git a/drivers/nvme/host/trace.h b/drivers/nvme/host/trace.h
index 4fb5922ffdac..32290b058c0f 100644
--- a/drivers/nvme/host/trace.h
+++ b/drivers/nvme/host/trace.h
@@ -83,8 +83,8 @@ TRACE_EVENT(nvme_setup_cmd,
);
TRACE_EVENT(nvme_complete_rq,
- TP_PROTO(struct request *req),
- TP_ARGS(req),
+ TP_PROTO(struct request *req, u8 disposition),
+ TP_ARGS(req, disposition),
TP_STRUCT__entry(
__array(char, disk, DISK_NAME_LEN)
__field(int, ctrl_id)
@@ -93,6 +93,7 @@ TRACE_EVENT(nvme_complete_rq,
__field(u64, result)
__field(u8, retries)
__field(u8, flags)
+ __field(u8, disposition)
__field(u16, status)
),
TP_fast_assign(
@@ -102,13 +103,15 @@ TRACE_EVENT(nvme_complete_rq,
__entry->result = le64_to_cpu(nvme_req(req)->result.u64);
__entry->retries = nvme_req(req)->retries;
__entry->flags = nvme_req(req)->flags;
+ __entry->disposition = disposition;
__entry->status = nvme_req(req)->status;
__assign_disk_name(__entry->disk, req->q->disk);
),
- TP_printk("nvme%d: %sqid=%d, cmdid=%u, res=%#llx,
retries=%u, flags=0x%x, status=%#x",
+ TP_printk("nvme%d: %sqid=%d, cmdid=%u, res=%#llx,
retries=%u, flags=0x%x, status=%#x entry->disposition=%x",
__entry->ctrl_id, __print_disk_name(__entry->disk),
__entry->qid, __entry->cid, __entry->result,
- __entry->retries, __entry->flags, __entry->status)
+ __entry->retries, __entry->flags, __entry->status,
+ __entry->disposition)
);
modprobe-9923 [038] ..s1. 1585.696843: nvme_complete_rq:
nvme0: qid=0, cmdid=4113, res=0x0, retries=0, flags=0x0, status=0x0
entry->disposition=0
[2] optional req disposition print :-
diff --git a/drivers/nvme/host/core.c b/drivers/nvme/host/core.c
index f586a4808e6e..832715676fd1 100644
--- a/drivers/nvme/host/core.c
+++ b/drivers/nvme/host/core.c
@@ -337,13 +337,6 @@ static void nvme_log_error(struct request *req)
nr->status & NVME_SC_DNR ? "DNR " : "");
}
-enum nvme_disposition {
- COMPLETE,
- RETRY,
- FAILOVER,
- AUTHENTICATE,
-};
-
static inline enum nvme_disposition nvme_decide_disposition(struct
request *req)
{
if (likely(nvme_req(req)->status == 0))
@@ -393,14 +386,16 @@ static inline void nvme_end_req(struct request *req)
void nvme_complete_rq(struct request *req)
{
struct nvme_ctrl *ctrl = nvme_req(req)->ctrl;
+ enum nvme_disposition disposition;
- trace_nvme_complete_rq(req);
nvme_cleanup_cmd(req);
if (ctrl->kas)
ctrl->comp_seen = true;
- switch (nvme_decide_disposition(req)) {
+ disposition = nvme_decide_disposition(req);
+ trace_nvme_complete_rq(req, disposition);
+ switch (disposition) {
case COMPLETE:
nvme_end_req(req);
return;
@@ -424,7 +419,7 @@ EXPORT_SYMBOL_GPL(nvme_complete_rq);
void nvme_complete_batch_req(struct request *req)
{
- trace_nvme_complete_rq(req);
+ trace_nvme_complete_rq(req, COMPLETE);
nvme_cleanup_cmd(req);
nvme_end_req_zoned(req);
}
diff --git a/drivers/nvme/host/nvme.h b/drivers/nvme/host/nvme.h
index f0a84e390a55..56e16bdd59ff 100644
--- a/drivers/nvme/host/nvme.h
+++ b/drivers/nvme/host/nvme.h
@@ -1119,4 +1119,12 @@ static inline const unsigned char
*nvme_opcode_str(int qid, u8 opcode, u8 fctype
return qid ? nvme_get_opcode_str(opcode) :
nvme_get_admin_opcode_str(opcode);
}
+
+enum nvme_disposition {
+ COMPLETE,
+ RETRY,
+ FAILOVER,
+ AUTHENTICATE,
+};
+
#endif /* _NVME_H */
diff --git a/drivers/nvme/host/trace.c b/drivers/nvme/host/trace.c
index 1c36fcedea20..ec32faa5080e 100644
--- a/drivers/nvme/host/trace.c
+++ b/drivers/nvme/host/trace.c
@@ -343,6 +343,18 @@ const char *nvme_trace_parse_fabrics_cmd(struct
trace_seq *p,
}
}
+const char *nvme_get_disposition(enum nvme_disposition disp)
+{
+ const char *disp_str[] = {
+ "",
+ " dispostion=RETRY",
+ " disposition=FAILOVER",
+ " disposition=AUTHENTICATE",
+ };
+
+ return disp > AUTHENTICATE ? "unknown" : disp_str[disp];
+}
+
const char *nvme_trace_disk_name(struct trace_seq *p, char *name)
{
const char *ret = trace_seq_buffer_ptr(p);
diff --git a/drivers/nvme/host/trace.h b/drivers/nvme/host/trace.h
index 4fb5922ffdac..f8b33f59ff76 100644
--- a/drivers/nvme/host/trace.h
+++ b/drivers/nvme/host/trace.h
@@ -22,6 +22,7 @@ const char *nvme_trace_parse_nvm_cmd(struct trace_seq
*p, u8 opcode,
u8 *cdw10);
const char *nvme_trace_parse_fabrics_cmd(struct trace_seq *p, u8 fctype,
u8 *spc);
+const char *nvme_get_disposition(enum nvme_disposition disp);
#define parse_nvme_cmd(qid, opcode, fctype, cdw10) \
((opcode) == nvme_fabrics_command ? \
@@ -83,8 +84,8 @@ TRACE_EVENT(nvme_setup_cmd,
);
TRACE_EVENT(nvme_complete_rq,
- TP_PROTO(struct request *req),
- TP_ARGS(req),
+ TP_PROTO(struct request *req, u8 disposition),
+ TP_ARGS(req, disposition),
TP_STRUCT__entry(
__array(char, disk, DISK_NAME_LEN)
__field(int, ctrl_id)
@@ -93,6 +94,7 @@ TRACE_EVENT(nvme_complete_rq,
__field(u64, result)
__field(u8, retries)
__field(u8, flags)
+ __field(u8, disposition)
__field(u16, status)
),
TP_fast_assign(
@@ -102,13 +104,15 @@ TRACE_EVENT(nvme_complete_rq,
__entry->result = le64_to_cpu(nvme_req(req)->result.u64);
__entry->retries = nvme_req(req)->retries;
__entry->flags = nvme_req(req)->flags;
+ __entry->disposition = disposition;
__entry->status = nvme_req(req)->status;
__assign_disk_name(__entry->disk, req->q->disk);
),
- TP_printk("nvme%d: %sqid=%d, cmdid=%u, res=%#llx,
retries=%u, flags=0x%x, status=%#x",
+ TP_printk("nvme%d: %sqid=%d, cmdid=%u, res=%#llx,
retries=%u, flags=0x%x, status=%#x%s",
__entry->ctrl_id, __print_disk_name(__entry->disk),
__entry->qid, __entry->cid, __entry->result,
- __entry->retries, __entry->flags, __entry->status)
+ __entry->retries, __entry->flags, __entry->status,
+ nvme_get_disposition(__entry->disposition))
);
More information about the Linux-nvme
mailing list