[PATCH] nvme: print disposition on err req completion

[PATCH] nvme: print disposition on err req completion

[Chaitanya Kulkarni]

Currently we don't print disposition in the request completion path
in nvme_complete_rq() tracepoint, so when request fails it is not
straight forward to understand the diposition making it hard to debug
the problems in the field.

Update nvme_complete_rq() tracepoint to print the disposition when
request fails, since disposition value will always be 0 when request
status = 0.

Tested-by: Amit Engel <Amit.Engel@Dell.com>
Signed-off-by: Chaitanya Kulkarni <kch@nvidia.com>
---
Test log from Amit :-

please find below an example for 'RETRY':
4677119.335542: nvme_complete_rq: nvme0: disk=nvme0n1, qid=3, cmdid=76, res=0x8, retries=0, flags=0x1, status=0x371 dispostion=RETRY

path-related errors simulation, ANA_TRANSITION error 'FAILOVER':

4684015.100835: nvme_complete_rq: nvme1: disk=nvme1n1, qid=2, cmdid=103, res=0x1, retries=0, flags=0x0, status=0x302 disposition=FAILOVER

For IO that was completed successfully 'COMPLET',
there is no 'dispostion' on the trace (as expected):
4677116.635057: nvme_complete_rq: nvme0: disk=nvme0n1, qid=3, cmdid=69, res=0x8, retries=0, flags=0x0, status=0x0

 drivers/nvme/host/core.c  | 15 +++++----------
 drivers/nvme/host/nvme.h  |  8 ++++++++
 drivers/nvme/host/trace.c | 12 ++++++++++++
 drivers/nvme/host/trace.h | 12 ++++++++----
 4 files changed, 33 insertions(+), 14 deletions(-)

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..8793fd6b8d0d 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)
+{
+	static const char *disp_str[] = {
+		[COMPLETE]	= "",
+		[RETRY]		= " dispostion=RETRY",
+		[FAILOVER]	= " disposition=FAILOVER",
+		[AUTHENTICATE]	= " disposition=AUTHENTICATE",
+	};
+
+	return disp > AUTHENTICATE ? "disposition=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))
 
 );
 
-- 
2.40.0

Re: [PATCH] nvme: print disposition on err req completion

[Sagi Grimberg]

Reviewed-by: Sagi Grimberg <sagi@grimberg.me>

Re: [PATCH] nvme: print disposition on err req completion

[Christoph Hellwig]

On Sun, Jun 04, 2023 at 11:49:33PM -0700, Chaitanya Kulkarni wrote:
> Currently we don't print disposition in the request completion path
> in nvme_complete_rq() tracepoint, so when request fails it is not
> straight forward to understand the diposition making it hard to debug
> the problems in the field.
> 
> Update nvme_complete_rq() tracepoint to print the disposition when
> request fails, since disposition value will always be 0 when request
> status = 0.

Hmm, not sure this is the right way to approach it.  I'd rather
redo how the trace points work by having a class and the ondividual
tracepoints in nvme_end_req/nvme_retry_req/nvme_failover_req.

Re: [PATCH] nvme: print disposition on err req completion

[Sagi Grimberg]

>> Currently we don't print disposition in the request completion path
>> in nvme_complete_rq() tracepoint, so when request fails it is not
>> straight forward to understand the diposition making it hard to debug
>> the problems in the field.
>>
>> Update nvme_complete_rq() tracepoint to print the disposition when
>> request fails, since disposition value will always be 0 when request
>> status = 0.
> 
> Hmm, not sure this is the right way to approach it.  I'd rather
> redo how the trace points work by having a class and the ondividual
> tracepoints in nvme_end_req/nvme_retry_req/nvme_failover_req.

:)

This was the original proposal (posted as a question to the list),
and I proposed this approach. You don't like it?

I kinda like the explicit disposition output.

RE: [PATCH] nvme: print disposition on err req completion

[Engel, Amit]

That’s correct, my original proposal was to have a dedicated tracepoint for
nvme_end_req/nvme_retry_req/nvme_failover_req.

But, ck proposed a bit different approach and
We agreed to go with optionally printing disposition value only
when disposition != COMPLETE in the trace_nvme_complete_rq()

Thanks,
Amit
-----Original Message-----
From: Sagi Grimberg <sagi@grimberg.me> 
Sent: Wednesday, 7 June 2023 18:08
To: Christoph Hellwig <hch@lst.de>; Chaitanya Kulkarni <kch@nvidia.com>
Cc: linux-nvme@lists.infradead.org; Engel, Amit <Amit.Engel@Dell.com>; kbusch@kernel.org
Subject: Re: [PATCH] nvme: print disposition on err req completion


[EXTERNAL EMAIL] 


>> Currently we don't print disposition in the request completion path 
>> in nvme_complete_rq() tracepoint, so when request fails it is not 
>> straight forward to understand the diposition making it hard to debug 
>> the problems in the field.
>>
>> Update nvme_complete_rq() tracepoint to print the disposition when 
>> request fails, since disposition value will always be 0 when request 
>> status = 0.
> 
> Hmm, not sure this is the right way to approach it.  I'd rather redo 
> how the trace points work by having a class and the ondividual 
> tracepoints in nvme_end_req/nvme_retry_req/nvme_failover_req.

:)

This was the original proposal (posted as a question to the list), and I proposed this approach. You don't like it?

I kinda like the explicit disposition output.

Re: [PATCH] nvme: print disposition on err req completion

[Chaitanya Kulkarni]

On 6/7/2023 10:06 AM, Engel, Amit wrote:
> That’s correct, my original proposal was to have a dedicated tracepoint for
> nvme_end_req/nvme_retry_req/nvme_failover_req.
> 
> But, ck proposed a bit different approach and
> We agreed to go with optionally printing disposition value only
> when disposition != COMPLETE in the trace_nvme_complete_rq()
> 
> Thanks,
> Amit
> -----Original Message-----
> From: Sagi Grimberg <sagi@grimberg.me>
> Sent: Wednesday, 7 June 2023 18:08
> To: Christoph Hellwig <hch@lst.de>; Chaitanya Kulkarni <kch@nvidia.com>
> Cc: linux-nvme@lists.infradead.org; Engel, Amit <Amit.Engel@Dell.com>; kbusch@kernel.org
> Subject: Re: [PATCH] nvme: print disposition on err req completion
> 
> 
> [EXTERNAL EMAIL]
> 
> 
>>> Currently we don't print disposition in the request completion path
>>> in nvme_complete_rq() tracepoint, so when request fails it is not
>>> straight forward to understand the diposition making it hard to debug
>>> the problems in the field.
>>>
>>> Update nvme_complete_rq() tracepoint to print the disposition when
>>> request fails, since disposition value will always be 0 when request
>>> status = 0.
>>
>> Hmm, not sure this is the right way to approach it.  I'd rather redo
>> how the trace points work by having a class and the ondividual
>> tracepoints in nvme_end_req/nvme_retry_req/nvme_failover_req.
> 
> :)
> 
> This was the original proposal (posted as a question to the list), and I proposed this approach. You don't like it?
> 
> I kinda like the explicit disposition output.

I thought it could save a code to add class.

I'll send V2 with above approach.

-ck

Re: [PATCH] nvme: print disposition on err req completion

[Christoph Hellwig]

On Wed, Jun 07, 2023 at 06:08:16PM +0300, Sagi Grimberg wrote:
>> Hmm, not sure this is the right way to approach it.  I'd rather
>> redo how the trace points work by having a class and the ondividual
>> tracepoints in nvme_end_req/nvme_retry_req/nvme_failover_req.
>
> :)
>
> This was the original proposal (posted as a question to the list),
> and I proposed this approach. You don't like it?

 1) the different dispostitions are really very different events,
    lumping them up does make tracing harder because you need to
    manually filter every time
 2) I really don't like exposing the disposition enum outside of core.c

Re: [PATCH] nvme: print disposition on err req completion

[Sagi Grimberg]

>>> Hmm, not sure this is the right way to approach it.  I'd rather
>>> redo how the trace points work by having a class and the ondividual
>>> tracepoints in nvme_end_req/nvme_retry_req/nvme_failover_req.
>>
>> :)
>>
>> This was the original proposal (posted as a question to the list),
>> and I proposed this approach. You don't like it?
> 
>   1) the different dispostitions are really very different events,
>      lumping them up does make tracing harder because you need to
>      manually filter every time

True.

>   2) I really don't like exposing the disposition enum outside of core.c

Don't think its much of an issue. But in any event I agree with having
different classes for easier tracing.