[PATCH 0/2] add tracepoints for nvme command submission and completion

[PATCH 0/2] add tracepoints for nvme command submission and completion

[Johannes Thumshirn]

Add tracepoints for nvme command submission and completion. The tracepoints
are modeled after SCSI's trace_scsi_dispatch_cmd_start() and
trace_scsi_dispatch_cmd_done() tracepoints and fulfil a similar purpose,
namely a fast way to check which command is going to be queued into the HW or
Fabric driver and which command is completed again.

Here's an example output using the qemu emulated pci nvme:

# tracer: nop 
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |   
              dd-205   [002] ....     7.128368: nvme_setup_cmd: nsid=1, command_id=568, flags=0x0, metadata=0x0, cmd=(nvme_cmd_read slba=0, length=31, control=0x0, dsmgmt=0, reftag=0)
          <idle>-0     [002] d.h.     7.129098: nvme_complete_rq: command_id=568, result=0, retries=0, flags=0x0, status=0
              dd-205   [002] ....     7.129150: nvme_setup_cmd: nsid=1, command_id=568, flags=0x0, metadata=0x0, cmd=(nvme_cmd_read slba=32, length=63, control=0x0, dsmgmt=0, reftag=0)
              dd-205   [002] ....     7.129189: nvme_setup_cmd: nsid=1, command_id=569, flags=0x0, metadata=0x0, cmd=(nvme_cmd_read slba=96, length=127, control=0x0, dsmgmt=0, reftag=0)
          <idle>-0     [002] d.h.     7.129318: nvme_complete_rq: command_id=568, result=0, retries=0, flags=0x0, status=0
              dd-205   [002] d.h.     7.129355: nvme_complete_rq: command_id=569, result=0, retries=0, flags=0x0, status=0
              dd-206   [003] ....     7.137389: nvme_setup_cmd: nsid=1, command_id=22, flags=0x0, metadata=0x0, cmd=(nvme_cmd_write slba=0, length=2559, control=0x0, dsmgmt=0, reftag=0)
              dd-206   [003] ....     7.137888: nvme_setup_cmd: nsid=1, command_id=23, flags=0x0, metadata=0x0, cmd=(nvme_cmd_write slba=2560, length=2559, control=0x0, dsmgmt=0, reftag=0)
              dd-206   [003] ....     7.138365: nvme_setup_cmd: nsid=1, command_id=24, flags=0x0, metadata=0x0, cmd=(nvme_cmd_write slba=5120, length=2559, control=0x0, dsmgmt=0, reftag=0)
              dd-206   [003] d.h.     7.138634: nvme_complete_rq: command_id=22, result=0, retries=0, flags=0x0, status=0
              dd-206   [003] ....     7.139014: nvme_setup_cmd: nsid=1, command_id=25, flags=0x0, metadata=0x0, cmd=(nvme_cmd_write slba=7680, length=2559, control=0x0, dsmgmt=0, reftag=0)
          <idle>-0     [003] d.h.     7.139658: nvme_complete_rq: command_id=23, result=0, retries=0, flags=0x0, status=0
          <idle>-0     [003] d.h.     7.140650: nvme_complete_rq: command_id=24, result=0, retries=0, flags=0x0, status=0
          <idle>-0     [003] d.h.     7.141670: nvme_complete_rq: command_id=25, result=0, retries=0, flags=0x0, status=0


Johannes Thumshirn (2):
  nvme: add tracepoint for nvme_setup_cmd
  nvme: add tracepoint for nvme_complete_rq

 drivers/nvme/host/core.c    | 71 +++++++++++++++++++++++++++++++++
 include/trace/events/nvme.h | 95 +++++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 166 insertions(+)
 create mode 100644 include/trace/events/nvme.h

-- 
2.12.3

[PATCH 1/2] nvme: add tracepoint for nvme_setup_cmd

[Johannes Thumshirn]

Signed-off-by: Johannes Thumshirn <jthumshirn@suse.de>
---
 drivers/nvme/host/core.c    | 69 +++++++++++++++++++++++++++++++++++++++++++++
 include/trace/events/nvme.h | 64 +++++++++++++++++++++++++++++++++++++++++
 2 files changed, 133 insertions(+)
 create mode 100644 include/trace/events/nvme.h

diff --git a/drivers/nvme/host/core.c b/drivers/nvme/host/core.c
index 839650e0926a..4b6a56fe6ccf 100644
--- a/drivers/nvme/host/core.c
+++ b/drivers/nvme/host/core.c
@@ -29,6 +29,9 @@
 #include <linux/pm_qos.h>
 #include <asm/unaligned.h>
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/nvme.h>
+
 #include "nvme.h"
 #include "fabrics.h"
 
@@ -80,6 +83,71 @@ static struct class *nvme_subsys_class;
 static void nvme_ns_remove(struct nvme_ns *ns);
 static int nvme_revalidate_disk(struct gendisk *disk);
 
+static const char *nvme_trace_read_write(struct trace_seq *p,
+					 struct nvme_rw_command rw)
+{
+	const char *ret = trace_seq_buffer_ptr(p);
+
+	trace_seq_printf(p, "slba=%llu, length=%u, control=0x%x, dsmgmt=%u, reftag=%u",
+			 (unsigned long long)le64_to_cpu(rw.slba),
+			 le16_to_cpu(rw.length), le16_to_cpu(rw.control),
+			 le32_to_cpu(rw.dsmgmt), le32_to_cpu(rw.reftag));
+	trace_seq_putc(p, 0);
+
+	return ret;
+}
+
+static const char *nvme_trace_dsm(struct trace_seq *p, struct nvme_dsm_cmd dsm)
+{
+	const char *ret = trace_seq_buffer_ptr(p);
+
+	trace_seq_printf(p, "nr=%u, attributes=%u",
+			 le32_to_cpu(dsm.nr), le32_to_cpu(dsm.attributes));
+	trace_seq_putc(p, 0);
+
+	return ret;
+}
+
+static const char *nvme_trace_write_zeroes(struct trace_seq *p,
+					   struct nvme_write_zeroes_cmd wz)
+{
+	const char *ret = trace_seq_buffer_ptr(p);
+
+	trace_seq_printf(p, "slba=%llu, length=%u, control=%u, dsmgmt=%u, reftag=%u",
+			 (unsigned long long) le64_to_cpu(wz.slba),
+			 le16_to_cpu(wz.length), le16_to_cpu(wz.control),
+			 le32_to_cpu(wz.dsmgmt), le32_to_cpu(wz.reftag));
+	trace_seq_putc(p, 0);
+
+	return ret;
+}
+
+static const char *nvme_trace_common(struct trace_seq *p,
+				     struct nvme_common_command c)
+{
+	const char *ret = trace_seq_buffer_ptr(p);
+
+	trace_seq_printf(p, "cdw2=%*ph, cdw10=%*ph", 4, c.cdw2, 24, c.cdw10);
+	trace_seq_putc(p, 0);
+
+	return ret;
+}
+
+const char *nvme_trace_parse_cmd(struct trace_seq *p, struct nvme_command cmd)
+{
+	switch (cmd.common.opcode) {
+	case nvme_cmd_read:
+	case nvme_cmd_write:
+		return nvme_trace_read_write(p, cmd.rw);
+	case nvme_cmd_dsm:
+		return nvme_trace_dsm(p, cmd.dsm);
+	case nvme_cmd_write_zeroes:
+		return nvme_trace_write_zeroes(p, cmd.write_zeroes);
+	default:
+		return nvme_trace_common(p, cmd.common);
+	}
+}
+
 static __le32 nvme_get_log_dw10(u8 lid, size_t size)
 {
 	return cpu_to_le32((((size / 4) - 1) << 16) | lid);
@@ -591,6 +659,7 @@ blk_status_t nvme_setup_cmd(struct nvme_ns *ns, struct request *req,
 	}
 
 	cmd->common.command_id = req->tag;
+	trace_nvme_setup_cmd(cmd);
 	return ret;
 }
 EXPORT_SYMBOL_GPL(nvme_setup_cmd);
diff --git a/include/trace/events/nvme.h b/include/trace/events/nvme.h
new file mode 100644
index 000000000000..2e93bc7d4f84
--- /dev/null
+++ b/include/trace/events/nvme.h
@@ -0,0 +1,64 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM nvme
+
+#if !defined(_TRACE_NVME_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_NVME_H
+
+#include <linux/nvme.h>
+#include <linux/tracepoint.h>
+#include <linux/trace_seq.h>
+
+#define nvme_opcode_name(opcode)	{ opcode, #opcode }
+#define show_opcode_name(val)					\
+	__print_symbolic(val,					\
+		nvme_opcode_name(nvme_cmd_flush),		\
+		nvme_opcode_name(nvme_cmd_write),		\
+		nvme_opcode_name(nvme_cmd_read),		\
+		nvme_opcode_name(nvme_cmd_write_uncor),		\
+		nvme_opcode_name(nvme_cmd_compare),		\
+		nvme_opcode_name(nvme_cmd_write_zeroes),	\
+		nvme_opcode_name(nvme_cmd_dsm),			\
+		nvme_opcode_name(nvme_cmd_resv_register),	\
+		nvme_opcode_name(nvme_cmd_resv_report),		\
+		nvme_opcode_name(nvme_cmd_resv_acquire),	\
+		nvme_opcode_name(nvme_cmd_resv_release))
+
+const char *nvme_trace_parse_cmd(struct trace_seq *p, struct nvme_command cmnd);
+#define __parse_nvme_cmd(cmd) nvme_trace_parse_cmd(p, cmd)
+
+TRACE_EVENT(nvme_setup_cmd,
+
+	    TP_PROTO(struct nvme_command *cmd),
+
+	    TP_ARGS(cmd),
+
+	    TP_STRUCT__entry(
+		    __field( __u8,                opcode   )
+		    __field( __u8,                flags    )
+		    __field( __u16,               cid      )
+		    __field( __le32,              nsid     )
+		    __field( __le64,              metadata )
+		    __field_struct( struct nvme_command, cmnd )
+	    ),
+
+	    TP_fast_assign(
+		    __entry->opcode	= cmd->common.opcode;
+		    __entry->flags	= cmd->common.flags;
+		    __entry->cid	= cmd->common.command_id;
+		    __entry->nsid	= cmd->common.nsid;
+		    __entry->metadata	= cmd->common.metadata;
+		    memcpy(&__entry->cmnd, cmd, sizeof(__entry->cmnd));
+	    ),
+
+	    TP_printk("nsid=%u, command_id=%u, flags=0x%x, metadata=0x%llx, cmd=(%s %s)",
+		      le32_to_cpu(__entry->nsid), __entry->cid, __entry->flags,
+		      (unsigned long long) le64_to_cpu(__entry->metadata),
+		      show_opcode_name(__entry->opcode),
+		      __parse_nvme_cmd(__entry->cmnd))
+);
+
+#endif /* _TRACE_NVME_H */
+
+/* This part must be boutside protection */
+#include <trace/define_trace.h>
-- 
2.12.3

Re: [PATCH 1/2] nvme: add tracepoint for nvme_setup_cmd

[Hannes Reinecke]

On 01/16/2018 11:34 AM, Johannes Thumshirn wrote:
> Signed-off-by: Johannes Thumshirn <jthumshirn@suse.de>
> ---
>  drivers/nvme/host/core.c    | 69 +++++++++++++++++++++++++++++++++++++++++++++
>  include/trace/events/nvme.h | 64 +++++++++++++++++++++++++++++++++++++++++
>  2 files changed, 133 insertions(+)
>  create mode 100644 include/trace/events/nvme.h
> 
> diff --git a/drivers/nvme/host/core.c b/drivers/nvme/host/core.c
> index 839650e0926a..4b6a56fe6ccf 100644
> --- a/drivers/nvme/host/core.c
> +++ b/drivers/nvme/host/core.c
> @@ -29,6 +29,9 @@
>  #include <linux/pm_qos.h>
>  #include <asm/unaligned.h>
>  
> +#define CREATE_TRACE_POINTS
> +#include <trace/events/nvme.h>
> +
>  #include "nvme.h"
>  #include "fabrics.h"
>  
> @@ -80,6 +83,71 @@ static struct class *nvme_subsys_class;
>  static void nvme_ns_remove(struct nvme_ns *ns);
>  static int nvme_revalidate_disk(struct gendisk *disk);
>  
> +static const char *nvme_trace_read_write(struct trace_seq *p,
> +					 struct nvme_rw_command rw)
> +{
> +	const char *ret = trace_seq_buffer_ptr(p);
> +
> +	trace_seq_printf(p, "slba=%llu, length=%u, control=0x%x, dsmgmt=%u, reftag=%u",
> +			 (unsigned long long)le64_to_cpu(rw.slba),
> +			 le16_to_cpu(rw.length), le16_to_cpu(rw.control),
> +			 le32_to_cpu(rw.dsmgmt), le32_to_cpu(rw.reftag));
> +	trace_seq_putc(p, 0);
> +
> +	return ret;
> +}
> +
> +static const char *nvme_trace_dsm(struct trace_seq *p, struct nvme_dsm_cmd dsm)
> +{
> +	const char *ret = trace_seq_buffer_ptr(p);
> +
> +	trace_seq_printf(p, "nr=%u, attributes=%u",
> +			 le32_to_cpu(dsm.nr), le32_to_cpu(dsm.attributes));
> +	trace_seq_putc(p, 0);
> +
> +	return ret;
> +}
> +
> +static const char *nvme_trace_write_zeroes(struct trace_seq *p,
> +					   struct nvme_write_zeroes_cmd wz)
> +{
> +	const char *ret = trace_seq_buffer_ptr(p);
> +
> +	trace_seq_printf(p, "slba=%llu, length=%u, control=%u, dsmgmt=%u, reftag=%u",
> +			 (unsigned long long) le64_to_cpu(wz.slba),
> +			 le16_to_cpu(wz.length), le16_to_cpu(wz.control),
> +			 le32_to_cpu(wz.dsmgmt), le32_to_cpu(wz.reftag));
> +	trace_seq_putc(p, 0);
> +
> +	return ret;
> +}
> +
> +static const char *nvme_trace_common(struct trace_seq *p,
> +				     struct nvme_common_command c)
> +{
> +	const char *ret = trace_seq_buffer_ptr(p);
> +
> +	trace_seq_printf(p, "cdw2=%*ph, cdw10=%*ph", 4, c.cdw2, 24, c.cdw10);
> +	trace_seq_putc(p, 0);
> +
> +	return ret;
> +}
> +
> +const char *nvme_trace_parse_cmd(struct trace_seq *p, struct nvme_command cmd)
> +{
> +	switch (cmd.common.opcode) {
> +	case nvme_cmd_read:
> +	case nvme_cmd_write:
> +		return nvme_trace_read_write(p, cmd.rw);
> +	case nvme_cmd_dsm:
> +		return nvme_trace_dsm(p, cmd.dsm);
> +	case nvme_cmd_write_zeroes:
> +		return nvme_trace_write_zeroes(p, cmd.write_zeroes);
> +	default:
> +		return nvme_trace_common(p, cmd.common);
> +	}
> +}
> +
>  static __le32 nvme_get_log_dw10(u8 lid, size_t size)
>  {
>  	return cpu_to_le32((((size / 4) - 1) << 16) | lid);
> @@ -591,6 +659,7 @@ blk_status_t nvme_setup_cmd(struct nvme_ns *ns, struct request *req,
>  	}
>  
>  	cmd->common.command_id = req->tag;
> +	trace_nvme_setup_cmd(cmd);
>  	return ret;
>  }
>  EXPORT_SYMBOL_GPL(nvme_setup_cmd);
> diff --git a/include/trace/events/nvme.h b/include/trace/events/nvme.h
> new file mode 100644
> index 000000000000..2e93bc7d4f84
> --- /dev/null
> +++ b/include/trace/events/nvme.h
> @@ -0,0 +1,64 @@
> +/* SPDX-License-Identifier: GPL-2.0 */
> +#undef TRACE_SYSTEM
> +#define TRACE_SYSTEM nvme
> +
> +#if !defined(_TRACE_NVME_H) || defined(TRACE_HEADER_MULTI_READ)
> +#define _TRACE_NVME_H
> +
> +#include <linux/nvme.h>
> +#include <linux/tracepoint.h>
> +#include <linux/trace_seq.h>
> +
> +#define nvme_opcode_name(opcode)	{ opcode, #opcode }
> +#define show_opcode_name(val)					\
> +	__print_symbolic(val,					\
> +		nvme_opcode_name(nvme_cmd_flush),		\
> +		nvme_opcode_name(nvme_cmd_write),		\
> +		nvme_opcode_name(nvme_cmd_read),		\
> +		nvme_opcode_name(nvme_cmd_write_uncor),		\
> +		nvme_opcode_name(nvme_cmd_compare),		\
> +		nvme_opcode_name(nvme_cmd_write_zeroes),	\
> +		nvme_opcode_name(nvme_cmd_dsm),			\
> +		nvme_opcode_name(nvme_cmd_resv_register),	\
> +		nvme_opcode_name(nvme_cmd_resv_report),		\
> +		nvme_opcode_name(nvme_cmd_resv_acquire),	\
> +		nvme_opcode_name(nvme_cmd_resv_release))
> +
> +const char *nvme_trace_parse_cmd(struct trace_seq *p, struct nvme_command cmnd);
> +#define __parse_nvme_cmd(cmd) nvme_trace_parse_cmd(p, cmd)
> +
> +TRACE_EVENT(nvme_setup_cmd,
> +
> +	    TP_PROTO(struct nvme_command *cmd),
> +
> +	    TP_ARGS(cmd),
> +
> +	    TP_STRUCT__entry(
> +		    __field( __u8,                opcode   )
> +		    __field( __u8,                flags    )
> +		    __field( __u16,               cid      )
> +		    __field( __le32,              nsid     )
> +		    __field( __le64,              metadata )
> +		    __field_struct( struct nvme_command, cmnd )
> +	    ),
> +
> +	    TP_fast_assign(
> +		    __entry->opcode	= cmd->common.opcode;
> +		    __entry->flags	= cmd->common.flags;
> +		    __entry->cid	= cmd->common.command_id;
> +		    __entry->nsid	= cmd->common.nsid;
> +		    __entry->metadata	= cmd->common.metadata;
> +		    memcpy(&__entry->cmnd, cmd, sizeof(__entry->cmnd));
> +	    ),
> +
> +	    TP_printk("nsid=%u, command_id=%u, flags=0x%x, metadata=0x%llx, cmd=(%s %s)",
> +		      le32_to_cpu(__entry->nsid), __entry->cid, __entry->flags,
> +		      (unsigned long long) le64_to_cpu(__entry->metadata),
> +		      show_opcode_name(__entry->opcode),
> +		      __parse_nvme_cmd(__entry->cmnd))
> +);
> +
> +#endif /* _TRACE_NVME_H */
> +
> +/* This part must be boutside protection */
> +#include <trace/define_trace.h>
> 
'boutside proctetion'?

In general I'd rather have the tracepoints when actually submitting the
request; with this tracepoint we might be getting a trace which doesn't
really indicate if the command was submitted at all.

Cheers,

Hannes
-- 
Dr. Hannes Reinecke		   Teamlead Storage & Networking
hare@suse.de			               +49 911 74053 688
SUSE LINUX GmbH, Maxfeldstr. 5, 90409 Nürnberg
GF: F. Imendörffer, J. Smithard, J. Guild, D. Upmanyu, G. Norton
HRB 21284 (AG Nürnberg)

Re: [PATCH 1/2] nvme: add tracepoint for nvme_setup_cmd

[Johannes Thumshirn]

On Tue, Jan 16, 2018 at 12:27:33PM +0100, Hannes Reinecke wrote:
> In general I'd rather have the tracepoints when actually submitting the
> request; with this tracepoint we might be getting a trace which doesn't
> really indicate if the command was submitted at all.

yes but if we really want to be 100% certain we need to take the tracepoints
in either in blk_mq_dispatch_rq_list() and trace the return value of the respective
->queue_rq() or in the PCI/FC/RDMA drivers.

-- 
Johannes Thumshirn                                          Storage
jthumshirn@suse.de                                +49 911 74053 689
SUSE LINUX GmbH, Maxfeldstr. 5, 90409 Nürnberg
GF: Felix Imendörffer, Jane Smithard, Graham Norton
HRB 21284 (AG Nürnberg)
Key fingerprint = EC38 9CAB C2C4 F25D 8600 D0D0 0393 969D 2D76 0850

Re: [PATCH 1/2] nvme: add tracepoint for nvme_setup_cmd

[Christoph Hellwig]

On Tue, Jan 16, 2018 at 11:34:00AM +0100, Johannes Thumshirn wrote:
> Signed-off-by: Johannes Thumshirn <jthumshirn@suse.de>
> ---
>  drivers/nvme/host/core.c    | 69 +++++++++++++++++++++++++++++++++++++++++++++
>  include/trace/events/nvme.h | 64 +++++++++++++++++++++++++++++++++++++++++

Pleas keep the trace header under drivers/nvme/host/

[PATCH 2/2] nvme: add tracepoint for nvme_complete_rq

[Johannes Thumshirn]

Signed-off-by: Johannes Thumshirn <jthumshirn@suse.de>
---
 drivers/nvme/host/core.c    |  2 ++
 include/trace/events/nvme.h | 31 +++++++++++++++++++++++++++++++
 2 files changed, 33 insertions(+)

diff --git a/drivers/nvme/host/core.c b/drivers/nvme/host/core.c
index 4b6a56fe6ccf..bac4559d6134 100644
--- a/drivers/nvme/host/core.c
+++ b/drivers/nvme/host/core.c
@@ -258,6 +258,8 @@ static inline bool nvme_req_needs_retry(struct request *req)
 
 void nvme_complete_rq(struct request *req)
 {
+	trace_nvme_complete_rq(nvme_req(req), req->tag);
+
 	if (unlikely(nvme_req(req)->status && nvme_req_needs_retry(req))) {
 		if (nvme_req_needs_failover(req)) {
 			nvme_failover_req(req);
diff --git a/include/trace/events/nvme.h b/include/trace/events/nvme.h
index 2e93bc7d4f84..d47bd9223241 100644
--- a/include/trace/events/nvme.h
+++ b/include/trace/events/nvme.h
@@ -9,6 +9,8 @@
 #include <linux/tracepoint.h>
 #include <linux/trace_seq.h>
 
+#include "../../../drivers/nvme/host/nvme.h"
+
 #define nvme_opcode_name(opcode)	{ opcode, #opcode }
 #define show_opcode_name(val)					\
 	__print_symbolic(val,					\
@@ -58,6 +60,35 @@ TRACE_EVENT(nvme_setup_cmd,
 		      __parse_nvme_cmd(__entry->cmnd))
 );
 
+TRACE_EVENT(nvme_complete_rq,
+
+	    TP_PROTO(struct nvme_request *req, int tag),
+
+	    TP_ARGS(req, tag),
+
+	    TP_STRUCT__entry(
+		    __field(    int, cid     )
+		    __field( __le64, result  )
+		    __field(     u8, retries )
+		    __field(     u8, flags   )
+		    __field(    u16, status  )
+	    ),
+
+	    TP_fast_assign(
+		    __entry->cid     = tag;
+		    __entry->result  = req->result.u64;
+		    __entry->retries = req->retries;
+		    __entry->flags   = req->flags;
+		    __entry->status  = req->status;
+	    ),
+
+	    TP_printk("command_id=%u, result=%llu, retries=%u, flags=0x%x, status=%u",
+		      __entry->cid,
+		      (unsigned long long)le64_to_cpu(__entry->result),
+		      __entry->retries, __entry->flags, __entry->status)
+
+);
+
 #endif /* _TRACE_NVME_H */
 
 /* This part must be boutside protection */
-- 
2.12.3

Re: [PATCH 2/2] nvme: add tracepoint for nvme_complete_rq

[Hannes Reinecke]

On 01/16/2018 11:34 AM, Johannes Thumshirn wrote:
> Signed-off-by: Johannes Thumshirn <jthumshirn@suse.de>
> ---
>  drivers/nvme/host/core.c    |  2 ++
>  include/trace/events/nvme.h | 31 +++++++++++++++++++++++++++++++
>  2 files changed, 33 insertions(+)
> 
> diff --git a/drivers/nvme/host/core.c b/drivers/nvme/host/core.c
> index 4b6a56fe6ccf..bac4559d6134 100644
> --- a/drivers/nvme/host/core.c
> +++ b/drivers/nvme/host/core.c
> @@ -258,6 +258,8 @@ static inline bool nvme_req_needs_retry(struct request *req)
>  
>  void nvme_complete_rq(struct request *req)
>  {
> +	trace_nvme_complete_rq(nvme_req(req), req->tag);
> +
>  	if (unlikely(nvme_req(req)->status && nvme_req_needs_retry(req))) {
>  		if (nvme_req_needs_failover(req)) {
>  			nvme_failover_req(req);
> diff --git a/include/trace/events/nvme.h b/include/trace/events/nvme.h
> index 2e93bc7d4f84..d47bd9223241 100644
> --- a/include/trace/events/nvme.h
> +++ b/include/trace/events/nvme.h
> @@ -9,6 +9,8 @@
>  #include <linux/tracepoint.h>
>  #include <linux/trace_seq.h>
>  
> +#include "../../../drivers/nvme/host/nvme.h"
> +
>  #define nvme_opcode_name(opcode)	{ opcode, #opcode }
>  #define show_opcode_name(val)					\
>  	__print_symbolic(val,					\
> @@ -58,6 +60,35 @@ TRACE_EVENT(nvme_setup_cmd,
>  		      __parse_nvme_cmd(__entry->cmnd))
>  );
>  
> +TRACE_EVENT(nvme_complete_rq,
> +
> +	    TP_PROTO(struct nvme_request *req, int tag),
> +
> +	    TP_ARGS(req, tag),
> +
> +	    TP_STRUCT__entry(
> +		    __field(    int, cid     )
> +		    __field( __le64, result  )
> +		    __field(     u8, retries )
> +		    __field(     u8, flags   )
> +		    __field(    u16, status  )
> +	    ),
> +
> +	    TP_fast_assign(
> +		    __entry->cid     = tag;
> +		    __entry->result  = req->result.u64;
> +		    __entry->retries = req->retries;
> +		    __entry->flags   = req->flags;
> +		    __entry->status  = req->status;
> +	    ),
> +
> +	    TP_printk("command_id=%u, result=%llu, retries=%u, flags=0x%x, status=%u",
> +		      __entry->cid,
> +		      (unsigned long long)le64_to_cpu(__entry->result),
> +		      __entry->retries, __entry->flags, __entry->status)
> +
> +);
> +
>  #endif /* _TRACE_NVME_H */
>  
>  /* This part must be boutside protection */
> 
Again, 'boutside' protection ...

Other than that:

Reviewed-by: Hannes Reinecke <hare@suse.com>

Cheers,

Hannes
-- 
Dr. Hannes Reinecke		   Teamlead Storage & Networking
hare@suse.de			               +49 911 74053 688
SUSE LINUX GmbH, Maxfeldstr. 5, 90409 Nürnberg
GF: F. Imendörffer, J. Smithard, J. Guild, D. Upmanyu, G. Norton
HRB 21284 (AG Nürnberg)