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

[PATCH v4 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
#              | |       |   ||||       |         |
    kworker/u8:0-5     [003] ....     3.927513: nvme_setup_cmd: nsid=0, cmdid=3, flags=0x0, meta=0x0, cmd=(nvme_admin_create_cq cqid=1, qsize=1023, cq_flags=0x3, irq_vector=0)
          <idle>-0     [003] d.h.     3.927553: nvme_complete_rq: cmdid=3, res=0, retries=0, flags=0x0, status=0
    kworker/u8:0-5     [003] ....     3.927559: nvme_setup_cmd: nsid=0, cmdid=3, flags=0x0, meta=0x0, cmd=(nvme_admin_create_sq sqid=1, qsize=1023, sq_flags=0x1, cqid=1)
          <idle>-0     [003] d.h.     3.927732: nvme_complete_rq: cmdid=3, res=0, retries=0, flags=0x0, status=0
    kworker/u8:0-5     [003] ....     3.927741: nvme_setup_cmd: nsid=0, cmdid=3, flags=0x0, meta=0x0, cmd=(nvme_admin_create_cq cqid=2, qsize=1023, cq_flags=0x3, irq_vector=1)
          <idle>-0     [003] d.h.     3.927775: nvme_complete_rq: cmdid=3, res=0, retries=0, flags=0x0, status=0
    kworker/u8:0-5     [003] ....     3.927778: nvme_setup_cmd: nsid=0, cmdid=3, flags=0x0, meta=0x0, cmd=(nvme_admin_create_sq sqid=2, qsize=1023, sq_flags=0x1, cqid=2)
          <idle>-0     [003] d.h.     3.927915: nvme_complete_rq: cmdid=3, res=0, retries=0, flags=0x0, status=0
    kworker/u8:0-5     [003] ....     3.927960: nvme_setup_cmd: nsid=0, cmdid=3, flags=0x0, meta=0x0, cmd=(nvme_admin_create_cq cqid=3, qsize=1023, cq_flags=0x3, irq_vector=2)
          <idle>-0     [003] d.h.     3.928006: nvme_complete_rq: cmdid=3, res=0, retries=0, flags=0x0, status=0
    kworker/u8:0-5     [003] ....     3.928009: nvme_setup_cmd: nsid=0, cmdid=3, flags=0x0, meta=0x0, cmd=(nvme_admin_create_sq sqid=3, qsize=1023, sq_flags=0x1, cqid=3)
          <idle>-0     [003] d.h.     3.928141: nvme_complete_rq: cmdid=3, res=0, retries=0, flags=0x0, status=0
    kworker/u8:0-5     [003] ....     3.928183: nvme_setup_cmd: nsid=0, cmdid=3, flags=0x0, meta=0x0, cmd=(nvme_admin_create_cq cqid=4, qsize=1023, cq_flags=0x3, irq_vector=3)
          <idle>-0     [003] d.h.     3.928217: nvme_complete_rq: cmdid=3, res=0, retries=0, flags=0x0, status=0
    kworker/u8:0-5     [003] ....     3.928220: nvme_setup_cmd: nsid=0, cmdid=3, flags=0x0, meta=0x0, cmd=(nvme_admin_create_sq sqid=4, qsize=1023, sq_flags=0x1, cqid=4)
          <idle>-0     [003] d.h.     3.928336: nvme_complete_rq: cmdid=3, res=0, retries=0, flags=0x0, status=0
    kworker/u8:0-5     [003] ....     3.929405: nvme_setup_cmd: nsid=0, cmdid=3, flags=0x0, meta=0x0, cmd=(nvme_admin_identify cns=1, ctrlid=0)
          <idle>-0     [003] d.h.     3.929492: nvme_complete_rq: cmdid=3, res=0, retries=0, flags=0x0, status=0
    kworker/u8:0-5     [003] ....     3.929547: nvme_setup_cmd: nsid=1, cmdid=3, flags=0x0, meta=0x0, cmd=(nvme_admin_identify cns=0, ctrlid=0)
          <idle>-0     [003] d.h.     3.929592: nvme_complete_rq: cmdid=3, res=0, retries=0, flags=0x0, status=0
    kworker/u8:0-5     [003] ....     3.929750: nvme_setup_cmd: nsid=1, cmdid=3, flags=0x0, meta=0x0, cmd=(nvme_admin_identify cns=0, ctrlid=0)
          <idle>-0     [003] d.h.     3.929792: nvme_complete_rq: cmdid=3, res=0, retries=0, flags=0x0, status=0
    kworker/u8:0-5     [003] ....     3.929860: nvme_setup_cmd: nsid=1, cmdid=622, flags=0x0, meta=0x0, cmd=(nvme_cmd_read slba=0, len=7, ctrl=0x0, dsmgmt=0, reftag=0)
          <idle>-0     [003] d.h.     3.930002: nvme_complete_rq: cmdid=622, res=0, retries=0, flags=0x0, status=0
    kworker/u8:0-5     [003] ....     3.930033: nvme_setup_cmd: nsid=1, cmdid=622, flags=0x0, meta=0x0, cmd=(nvme_cmd_read slba=24, len=7, ctrl=0x0, dsmgmt=0, reftag=0)
          <idle>-0     [003] d.h.     3.930104: nvme_complete_rq: cmdid=622, res=0, retries=0, flags=0x0, status=0
              dd-205   [002] .N..     4.430448: nvme_setup_cmd: nsid=1, cmdid=626, flags=0x0, meta=0x0, cmd=(nvme_cmd_read slba=0, len=2559, ctrl=0x0, dsmgmt=0, reftag=0)
              dd-205   [002] .N..     4.430490: nvme_setup_cmd: nsid=1, cmdid=627, flags=0x0, meta=0x0, cmd=(nvme_cmd_read slba=2560, len=1535, ctrl=0x0, dsmgmt=0, reftag=0)
          <idle>-0     [002] d.h.     4.431423: nvme_complete_rq: cmdid=626, res=0, retries=0, flags=0x0, status=0
          <idle>-0     [002] d.h.     4.431771: nvme_complete_rq: cmdid=627, res=0, retries=0, flags=0x0, status=0
              dd-205   [002] ....     4.432657: nvme_setup_cmd: nsid=1, cmdid=627, flags=0x0, meta=0x0, cmd=(nvme_cmd_read slba=4096, len=2047, ctrl=0x0, dsmgmt=0, reftag=0)
              dd-205   [002] ....     4.433779: nvme_setup_cmd: nsid=1, cmdid=628, flags=0x0, meta=0x0, cmd=(nvme_cmd_read slba=6144, len=2047, ctrl=0x0, dsmgmt=0, reftag=0)
          <idle>-0     [002] d.h.     4.434007: nvme_complete_rq: cmdid=627, res=0, retries=0, flags=0x0, status=0
              dd-205   [002] ....     4.434372: nvme_setup_cmd: nsid=1, cmdid=627, flags=0x0, meta=0x0, cmd=(nvme_cmd_read slba=8192, len=2047, ctrl=0x0, dsmgmt=0, reftag=0)
          <idle>-0     [002] d.h.     4.434750: nvme_complete_rq: cmdid=628, res=0, retries=0, flags=0x0, status=0
              dd-205   [002] ....     4.435215: nvme_setup_cmd: nsid=1, cmdid=628, flags=0x0, meta=0x0, cmd=(nvme_cmd_read slba=10240, len=2047, ctrl=0x0, dsmgmt=0, reftag=0)
          <idle>-0     [002] d.h.     4.435494: nvme_complete_rq: cmdid=627, res=0, retries=0, flags=0x0, status=0
          <idle>-0     [002] d.h.     4.436182: nvme_complete_rq: cmdid=628, res=0, retries=0, flags=0x0, status=0
              dd-206   [003] ....     4.442316: nvme_setup_cmd: nsid=1, cmdid=622, flags=0x0, meta=0x0, cmd=(nvme_cmd_write slba=0, len=2559, ctrl=0x0, dsmgmt=0, reftag=0)
              dd-206   [003] ....     4.442579: nvme_setup_cmd: nsid=1, cmdid=623, flags=0x0, meta=0x0, cmd=(nvme_cmd_write slba=2560, len=2559, ctrl=0x0, dsmgmt=0, reftag=0)
              dd-206   [003] ....     4.442823: nvme_setup_cmd: nsid=1, cmdid=624, flags=0x0, meta=0x0, cmd=(nvme_cmd_write slba=5120, len=2559, ctrl=0x0, dsmgmt=0, reftag=0)
              dd-206   [003] ....     4.443064: nvme_setup_cmd: nsid=1, cmdid=625, flags=0x0, meta=0x0, cmd=(nvme_cmd_write slba=7680, len=2559, ctrl=0x0, dsmgmt=0, reftag=0)
          <idle>-0     [003] d.h.     4.444250: nvme_complete_rq: cmdid=622, res=0, retries=0, flags=0x0, status=0
          <idle>-0     [003] d.h.     4.444912: nvme_complete_rq: cmdid=623, res=0, retries=0, flags=0x0, status=0
          <idle>-0     [003] d.h.     4.445615: nvme_complete_rq: cmdid=624, res=0, retries=0, flags=0x0, status=0
          <idle>-0     [003] d.h.     4.446504: nvme_complete_rq: cmdid=625, res=0, retries=0, flags=0x0, status=0


Note: I decided to keep the Reviewd-by's although I added the admin command decoding.


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

 drivers/nvme/host/Makefile |   4 ++
 drivers/nvme/host/core.c   |   6 ++
 drivers/nvme/host/trace.c  | 161 +++++++++++++++++++++++++++++++++++++++++++++
 drivers/nvme/host/trace.h  | 136 ++++++++++++++++++++++++++++++++++++++
 4 files changed, 307 insertions(+)
 create mode 100644 drivers/nvme/host/trace.c
 create mode 100644 drivers/nvme/host/trace.h

-- 
2.12.3

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

[Johannes Thumshirn]

Signed-off-by: Johannes Thumshirn <jthumshirn@suse.de>
Reviewed-by: Hannes Reinecke <hare@suse.de>
Reviewed-by: Martin K. Petersen <martin.petersen@oracle.com>
Reviewed-by: Keith Busch <keith.busch@intel.com>

---
Changes to v2:
* Don't cast le64_to_cpu() conversions to unsigned long long (Christoph)
* Add proper copyright header (Christoph)
* Move trace decoding into own file (Christoph)
* Include the src directory in the Makefile for trace (Christoph)
* Removed spaces before and after parenthesis (Christoph)
* Reduced print lines to fit the 80 char limit (Christoph)
* Only build trace.o when CONFIG_TRACE=y (Christoph)
* Only copy non-common command fields to trace decoder (Christoph)
* Merge write_zeros decoder into rw decoder
* Don't decode admin commands as I/O commands

Changes to v1:
* Fix typo (Hannes)
* move include/trace/events/nvme.h -> drivers/nvme/host/trace.h (Christoph)
---
 drivers/nvme/host/Makefile |   4 ++
 drivers/nvme/host/core.c   |   4 ++
 drivers/nvme/host/trace.c  | 161 +++++++++++++++++++++++++++++++++++++++++++++
 drivers/nvme/host/trace.h  | 112 +++++++++++++++++++++++++++++++
 4 files changed, 281 insertions(+)
 create mode 100644 drivers/nvme/host/trace.c
 create mode 100644 drivers/nvme/host/trace.h

diff --git a/drivers/nvme/host/Makefile b/drivers/nvme/host/Makefile
index a25fd43650ad..441e67e3a9d7 100644
--- a/drivers/nvme/host/Makefile
+++ b/drivers/nvme/host/Makefile
@@ -1,4 +1,7 @@
 # SPDX-License-Identifier: GPL-2.0
+
+ccflags-y				+= -I$(src)
+
 obj-$(CONFIG_NVME_CORE)			+= nvme-core.o
 obj-$(CONFIG_BLK_DEV_NVME)		+= nvme.o
 obj-$(CONFIG_NVME_FABRICS)		+= nvme-fabrics.o
@@ -6,6 +9,7 @@ obj-$(CONFIG_NVME_RDMA)			+= nvme-rdma.o
 obj-$(CONFIG_NVME_FC)			+= nvme-fc.o
 
 nvme-core-y				:= core.o
+nvme-core-$(CONFIG_TRACING)		+= trace.o
 nvme-core-$(CONFIG_NVME_MULTIPATH)	+= multipath.o
 nvme-core-$(CONFIG_NVM)			+= lightnvm.o
 
diff --git a/drivers/nvme/host/core.c b/drivers/nvme/host/core.c
index 839650e0926a..1ca515720216 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.h"
+
 #include "nvme.h"
 #include "fabrics.h"
 
@@ -591,6 +594,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, ns ? 0 : 1);
 	return ret;
 }
 EXPORT_SYMBOL_GPL(nvme_setup_cmd);
diff --git a/drivers/nvme/host/trace.c b/drivers/nvme/host/trace.c
new file mode 100644
index 000000000000..1cdc2edee81e
--- /dev/null
+++ b/drivers/nvme/host/trace.c
@@ -0,0 +1,161 @@
+/*
+ * NVM Express device driver tracepoints
+ * Copyright (c) 2018 Johannes Thumshirn, SUSE Linux GmbH
+ *
+ * This program is free software; you can redistribute it and/or modify it
+ * under the terms and conditions of the GNU General Public License,
+ * version 2, as published by the Free Software Foundation.
+ *
+ * This program is distributed in the hope it will be useful, but WITHOUT
+ * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
+ * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License for
+ * more details.
+ */
+
+#include "trace.h"
+
+struct rw_cmd {
+	__le64 slba;
+	__le16 length;
+	__le16 control;
+	__le32 dsmgmt;
+	__le32 reftag;
+	__le16 apptag;
+	__le16 appmask;
+};
+
+struct dsm_cmd {
+	__le32 nr;
+	__le32 attributes;
+	__u32 rsvd12[4];
+};
+
+struct create_sq {
+	__le16 sqid;
+	__le16 qsize;
+	__le16 sq_flags;
+	__le16 cqid;
+	__u32 rsvd12[4];
+};
+
+struct create_cq {
+	__le16 cqid;
+	__le16 qsize;
+	__le16 cq_flags;
+	__le16 irq_vector;
+	__u32 rsvd12[4];
+};
+
+struct identify {
+	__u8 cns;
+	__u8 rsvd;
+	__le16 ctrlid;
+	u32 rsvd2[5];
+};
+
+static const char *nvme_trace_create_sq(struct trace_seq *p, __le32 *cdw10)
+{
+	const char *ret = trace_seq_buffer_ptr(p);
+	struct create_sq *csq = (struct create_sq *) cdw10;
+
+	trace_seq_printf(p, "sqid=%u, qsize=%u, sq_flags=0x%x, cqid=%u",
+			 le16_to_cpu(csq->sqid), le16_to_cpu(csq->qsize),
+			 le16_to_cpu(csq->sq_flags), le16_to_cpu(csq->cqid));
+	trace_seq_putc(p, 0);
+
+	return ret;
+}
+
+static const char *nvme_trace_create_cq(struct trace_seq *p, __le32 *cdw10)
+{
+	const char *ret = trace_seq_buffer_ptr(p);
+	struct create_cq *ccq = (struct create_cq *) cdw10;
+
+	trace_seq_printf(p, "cqid=%u, qsize=%u, cq_flags=0x%x, irq_vector=%u",
+			 le16_to_cpu(ccq->cqid), le16_to_cpu(ccq->qsize),
+			 le16_to_cpu(ccq->cq_flags),
+			 le16_to_cpu(ccq->irq_vector));
+	trace_seq_putc(p, 0);
+
+	return ret;
+}
+
+static const char *nvme_trace_admin_identify(struct trace_seq *p, __le32 *cdw10)
+{
+	const char *ret = trace_seq_buffer_ptr(p);
+	struct identify *idf = (struct identify *) cdw10;
+
+	trace_seq_printf(p, "cns=%u, ctrlid=%u",
+			 idf->cns, le16_to_cpu(idf->ctrlid));
+
+	trace_seq_putc(p, 0);
+
+	return ret;
+}
+
+
+
+static const char *nvme_trace_read_write(struct trace_seq *p, __le32 *cdw10)
+{
+	const char *ret = trace_seq_buffer_ptr(p);
+	struct rw_cmd *rw = (struct rw_cmd *) cdw10;
+
+	trace_seq_printf(p,
+			 "slba=%llu, len=%u, ctrl=0x%x, dsmgmt=%u, reftag=%u",
+			 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, __le32 *cdw10)
+{
+	const char *ret = trace_seq_buffer_ptr(p);
+	struct dsm_cmd *dsm = (struct dsm_cmd *) cdw10;
+
+	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_common(struct trace_seq *p, __le32 *cdw10)
+{
+	const char *ret = trace_seq_buffer_ptr(p);
+
+	trace_seq_printf(p, "cdw10=%*ph", 6, cdw10);
+	trace_seq_putc(p, 0);
+
+	return ret;
+}
+
+const char *nvme_trace_parse_cmd(struct trace_seq *p, bool admin,
+				 u8 opcode, __le32 *cdw10)
+{
+	if (admin) {
+		switch (opcode) {
+		case nvme_admin_create_sq:
+			return nvme_trace_create_sq(p, cdw10);
+		case nvme_admin_create_cq:
+			return nvme_trace_create_cq(p, cdw10);
+		case nvme_admin_identify:
+			return nvme_trace_admin_identify(p, cdw10);
+		default:
+			return nvme_trace_common(p, cdw10);
+		}
+	} else {
+		switch (opcode) {
+		case nvme_cmd_read:
+		case nvme_cmd_write:
+		case nvme_cmd_write_zeroes:
+			return nvme_trace_read_write(p, cdw10);
+		case nvme_cmd_dsm:
+			return nvme_trace_dsm(p, cdw10);
+		default:
+			return nvme_trace_common(p, cdw10);
+		}
+	}
+}
diff --git a/drivers/nvme/host/trace.h b/drivers/nvme/host/trace.h
new file mode 100644
index 000000000000..69e054c2e791
--- /dev/null
+++ b/drivers/nvme/host/trace.h
@@ -0,0 +1,112 @@
+/*
+ * NVM Express device driver tracepoints
+ * Copyright (c) 2018 Johannes Thumshirn, SUSE Linux GmbH
+ *
+ * This program is free software; you can redistribute it and/or modify it
+ * under the terms and conditions of the GNU General Public License,
+ * version 2, as published by the Free Software Foundation.
+ *
+ * This program is distributed in the hope it will be useful, but WITHOUT
+ * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
+ * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License for
+ * more details.
+ */
+
+#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>
+
+#include "nvme.h"
+
+#define nvme_admin_opcode_name(opcode)	{ opcode, #opcode }
+#define show_admin_opcode_name(val)					\
+	__print_symbolic(val,						\
+		nvme_admin_opcode_name(nvme_admin_delete_sq),		\
+		nvme_admin_opcode_name(nvme_admin_create_sq),		\
+		nvme_admin_opcode_name(nvme_admin_get_log_page),	\
+		nvme_admin_opcode_name(nvme_admin_delete_cq),		\
+		nvme_admin_opcode_name(nvme_admin_create_cq),		\
+		nvme_admin_opcode_name(nvme_admin_identify),		\
+		nvme_admin_opcode_name(nvme_admin_abort_cmd),		\
+		nvme_admin_opcode_name(nvme_admin_set_features),	\
+		nvme_admin_opcode_name(nvme_admin_get_features),	\
+		nvme_admin_opcode_name(nvme_admin_async_event),		\
+		nvme_admin_opcode_name(nvme_admin_ns_mgmt),		\
+		nvme_admin_opcode_name(nvme_admin_activate_fw),		\
+		nvme_admin_opcode_name(nvme_admin_download_fw),		\
+		nvme_admin_opcode_name(nvme_admin_ns_attach),		\
+		nvme_admin_opcode_name(nvme_admin_keep_alive),		\
+		nvme_admin_opcode_name(nvme_admin_directive_send),	\
+		nvme_admin_opcode_name(nvme_admin_directive_recv),	\
+		nvme_admin_opcode_name(nvme_admin_dbbuf),		\
+		nvme_admin_opcode_name(nvme_admin_format_nvm),		\
+		nvme_admin_opcode_name(nvme_admin_security_send),	\
+		nvme_admin_opcode_name(nvme_admin_security_recv),	\
+		nvme_admin_opcode_name(nvme_admin_sanitize_nvm))
+
+#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, bool admin, u8 opcode,
+				 __le32 *cdw10);
+#define __parse_nvme_cmd(admin, opcode, cdw10) \
+	nvme_trace_parse_cmd(p, admin, opcode, cdw10)
+
+TRACE_EVENT(nvme_setup_cmd,
+	    TP_PROTO(struct nvme_command *cmd, bool admin),
+	    TP_ARGS(cmd, admin),
+	    TP_STRUCT__entry(
+		    __field(bool, admin)
+		    __field(__u8, opcode)
+		    __field(__u8, flags)
+		    __field(__u16, cid)
+		    __field(__le32, nsid)
+		    __field(__le64, metadata)
+		    __array(__le32, cdw10, 6)
+	    ),
+	    TP_fast_assign(
+		    __entry->admin = admin;
+		    __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->cdw10, cmd->common.cdw10,
+			   sizeof(__entry->cdw10));
+	    ),
+	    TP_printk("nsid=%u, cmdid=%u, flags=0x%x, meta=0x%llx, cmd=(%s %s)",
+		      le32_to_cpu(__entry->nsid), __entry->cid, __entry->flags,
+		      le64_to_cpu(__entry->metadata),
+		      __entry->admin ? show_admin_opcode_name(__entry->opcode)
+			    : show_opcode_name(__entry->opcode),
+		      __parse_nvme_cmd(__entry->admin, __entry->opcode,
+				       __entry->cdw10))
+);
+
+#endif /* _TRACE_NVME_H */
+
+#undef TRACE_INCLUDE_PATH
+#define TRACE_INCLUDE_PATH .
+#undef TRACE_INCLUDE_FILE
+#define TRACE_INCLUDE_FILE trace
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
-- 
2.12.3

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

[Johannes Thumshirn]

Signed-off-by: Johannes Thumshirn <jthumshirn@suse.de>
Reviewed-by: Hannes Reinecke <hare@suse.com>
Reviewed-by: Martin K. Petersen <martin.petersen@oracle.com>
Reviewed-by: Keith Busch <keith.busch@intel.com>

---
Changes to v2:
* Pass the whole struct request to the tracepoint
* Removed spaces after parenthesis (Christoph)
---
 drivers/nvme/host/core.c  |  2 ++
 drivers/nvme/host/trace.h | 24 ++++++++++++++++++++++++
 2 files changed, 26 insertions(+)

diff --git a/drivers/nvme/host/core.c b/drivers/nvme/host/core.c
index 1ca515720216..45a9b7092993 100644
--- a/drivers/nvme/host/core.c
+++ b/drivers/nvme/host/core.c
@@ -193,6 +193,8 @@ static inline bool nvme_req_needs_retry(struct request *req)
 
 void nvme_complete_rq(struct request *req)
 {
+	trace_nvme_complete_rq(req);
+
 	if (unlikely(nvme_req(req)->status && nvme_req_needs_retry(req))) {
 		if (nvme_req_needs_failover(req)) {
 			nvme_failover_req(req);
diff --git a/drivers/nvme/host/trace.h b/drivers/nvme/host/trace.h
index 69e054c2e791..41d000fdd96f 100644
--- a/drivers/nvme/host/trace.h
+++ b/drivers/nvme/host/trace.h
@@ -101,6 +101,30 @@ TRACE_EVENT(nvme_setup_cmd,
 				       __entry->cdw10))
 );
 
+TRACE_EVENT(nvme_complete_rq,
+	    TP_PROTO(struct request *req),
+	    TP_ARGS(req),
+	    TP_STRUCT__entry(
+		    __field(int, cid)
+		    __field(__le64, result)
+		    __field(u8, retries)
+		    __field(u8, flags)
+		    __field(u16, status)
+	    ),
+	    TP_fast_assign(
+		    __entry->cid = req->tag;
+		    __entry->result = nvme_req(req)->result.u64;
+		    __entry->retries = nvme_req(req)->retries;
+		    __entry->flags = nvme_req(req)->flags;
+		    __entry->status = nvme_req(req)->status;
+	    ),
+	    TP_printk("cmdid=%u, res=%llu, retries=%u, flags=0x%x, status=%u",
+		      __entry->cid,
+		      le64_to_cpu(__entry->result),
+		      __entry->retries, __entry->flags, __entry->status)
+
+);
+
 #endif /* _TRACE_NVME_H */
 
 #undef TRACE_INCLUDE_PATH
-- 
2.12.3

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

[Christoph Hellwig]

On Fri, Jan 19, 2018 at 03:18:18PM +0100, Johannes Thumshirn wrote:
> Signed-off-by: Johannes Thumshirn <jthumshirn@suse.de>
> Reviewed-by: Hannes Reinecke <hare@suse.de>
> Reviewed-by: Martin K. Petersen <martin.petersen@oracle.com>
> Reviewed-by: Keith Busch <keith.busch@intel.com>

This could really use a changelog explaining what you're tracing,
and most importantly why.

> +struct rw_cmd {
> +	__le64 slba;
> +	__le16 length;
> +	__le16 control;
> +	__le32 dsmgmt;
> +	__le32 reftag;
> +	__le16 apptag;
> +	__le16 appmask;
> +};
> +
> +struct dsm_cmd {
> +	__le32 nr;
> +	__le32 attributes;
> +	__u32 rsvd12[4];
> +};

Why do we need all these different defintions?  Just use
cdw2/3/10/11/12/13 for the fields and decode those __le32 on
a per-command basis where needed.

> +const char *nvme_trace_parse_cmd(struct trace_seq *p, bool admin,
> +				 u8 opcode, __le32 *cdw10)
> +{
> +	if (admin) {
> +		switch (opcode) {
> +		case nvme_admin_create_sq:
> +			return nvme_trace_create_sq(p, cdw10);
> +		case nvme_admin_create_cq:
> +			return nvme_trace_create_cq(p, cdw10);
> +		case nvme_admin_identify:
> +			return nvme_trace_admin_identify(p, cdw10);
> +		default:
> +			return nvme_trace_common(p, cdw10);
> +		}
> +	} else {
> +		switch (opcode) {
> +		case nvme_cmd_read:
> +		case nvme_cmd_write:
> +		case nvme_cmd_write_zeroes:
> +			return nvme_trace_read_write(p, cdw10);
> +		case nvme_cmd_dsm:
> +			return nvme_trace_dsm(p, cdw10);
> +		default:
> +			return nvme_trace_common(p, cdw10);
> +		}
> +	}
> +}

Wouldn't it be easier to have separate tracepoints for admin vs
I/O commands?  Especially as people might often want to trace
only one or the other.

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

[Christoph Hellwig]

On Fri, Jan 19, 2018 at 03:18:19PM +0100, Johannes Thumshirn wrote:
> Signed-off-by: Johannes Thumshirn <jthumshirn@suse.de>
> Reviewed-by: Hannes Reinecke <hare@suse.com>
> Reviewed-by: Martin K. Petersen <martin.petersen@oracle.com>
> Reviewed-by: Keith Busch <keith.busch@intel.com>
> 
> ---
> Changes to v2:
> * Pass the whole struct request to the tracepoint
> * Removed spaces after parenthesis (Christoph)
> ---
>  drivers/nvme/host/core.c  |  2 ++
>  drivers/nvme/host/trace.h | 24 ++++++++++++++++++++++++
>  2 files changed, 26 insertions(+)
> 
> diff --git a/drivers/nvme/host/core.c b/drivers/nvme/host/core.c
> index 1ca515720216..45a9b7092993 100644
> --- a/drivers/nvme/host/core.c
> +++ b/drivers/nvme/host/core.c
> @@ -193,6 +193,8 @@ static inline bool nvme_req_needs_retry(struct request *req)
>  
>  void nvme_complete_rq(struct request *req)
>  {
> +	trace_nvme_complete_rq(req);
> +
>  	if (unlikely(nvme_req(req)->status && nvme_req_needs_retry(req))) {
>  		if (nvme_req_needs_failover(req)) {
>  			nvme_failover_req(req);
> diff --git a/drivers/nvme/host/trace.h b/drivers/nvme/host/trace.h
> index 69e054c2e791..41d000fdd96f 100644
> --- a/drivers/nvme/host/trace.h
> +++ b/drivers/nvme/host/trace.h
> @@ -101,6 +101,30 @@ TRACE_EVENT(nvme_setup_cmd,
>  				       __entry->cdw10))
>  );
>  
> +TRACE_EVENT(nvme_complete_rq,
> +	    TP_PROTO(struct request *req),
> +	    TP_ARGS(req),
> +	    TP_STRUCT__entry(
> +		    __field(int, cid)
> +		    __field(__le64, result)
> +		    __field(u8, retries)
> +		    __field(u8, flags)
> +		    __field(u16, status)
> +	    ),
> +	    TP_fast_assign(
> +		    __entry->cid = req->tag;
> +		    __entry->result = nvme_req(req)->result.u64;
> +		    __entry->retries = nvme_req(req)->retries;
> +		    __entry->flags = nvme_req(req)->flags;
> +		    __entry->status = nvme_req(req)->status;
> +	    ),
> +	    TP_printk("cmdid=%u, res=%llu, retries=%u, flags=0x%x, status=%u",
> +		      __entry->cid,
> +		      le64_to_cpu(__entry->result),
> +		      __entry->retries, __entry->flags, __entry->status)
> +
> +);

Wouldn't some indication on which queue this completion happens
be useful?

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

[Johannes Thumshirn]

On Mon, Jan 22, 2018 at 04:23:40PM +0100, Christoph Hellwig wrote:
> Wouldn't some indication on which queue this completion happens
> be useful?

Probably yes. I'll add it in v5.

-- 
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 v4 1/2] nvme: add tracepoint for nvme_setup_cmd

[Johannes Thumshirn]

On Mon, Jan 22, 2018 at 04:23:01PM +0100, Christoph Hellwig wrote:
> On Fri, Jan 19, 2018 at 03:18:18PM +0100, Johannes Thumshirn wrote:
> > Signed-off-by: Johannes Thumshirn <jthumshirn@suse.de>
> > Reviewed-by: Hannes Reinecke <hare@suse.de>
> > Reviewed-by: Martin K. Petersen <martin.petersen@oracle.com>
> > Reviewed-by: Keith Busch <keith.busch@intel.com>
> 
> This could really use a changelog explaining what you're tracing,
> and most importantly why.

OK.
 
> > +struct rw_cmd {
> > +	__le64 slba;
> > +	__le16 length;
> > +	__le16 control;
> > +	__le32 dsmgmt;
> > +	__le32 reftag;
> > +	__le16 apptag;
> > +	__le16 appmask;
> > +};
> > +
> > +struct dsm_cmd {
> > +	__le32 nr;
> > +	__le32 attributes;
> > +	__u32 rsvd12[4];
> > +};
> 
> Why do we need all these different defintions?  Just use
> cdw2/3/10/11/12/13 for the fields and decode those __le32 on
> a per-command basis where needed.

Yup.

> > +const char *nvme_trace_parse_cmd(struct trace_seq *p, bool admin,
> > +				 u8 opcode, __le32 *cdw10)
> > +{
> > +	if (admin) {
> > +		switch (opcode) {
> > +		case nvme_admin_create_sq:
> > +			return nvme_trace_create_sq(p, cdw10);
> > +		case nvme_admin_create_cq:
> > +			return nvme_trace_create_cq(p, cdw10);
> > +		case nvme_admin_identify:
> > +			return nvme_trace_admin_identify(p, cdw10);
> > +		default:
> > +			return nvme_trace_common(p, cdw10);
> > +		}
> > +	} else {
> > +		switch (opcode) {
> > +		case nvme_cmd_read:
> > +		case nvme_cmd_write:
> > +		case nvme_cmd_write_zeroes:
> > +			return nvme_trace_read_write(p, cdw10);
> > +		case nvme_cmd_dsm:
> > +			return nvme_trace_dsm(p, cdw10);
> > +		default:
> > +			return nvme_trace_common(p, cdw10);
> > +		}
> > +	}
> > +}
> 
> Wouldn't it be easier to have separate tracepoints for admin vs
> I/O commands?  Especially as people might often want to trace
> only one or the other.

Yes and no. I personally like to have the big hammer when tracing customer
problems and filter out maunally later. I initially had a tracepoint for each
of nvme_setup_flush(), nvme_setup_discard(), nvme_setup_rw() but decided it
was too fine grained.

nvme_setup_cmd() has the nice side effect that all commands, including
userspace passtrough commands must pass it. This was extremely helpful in the
customer bug which inspired me to implement this tracepoint.

Martin, Keith, Sagi, Hannes, any preferences here?

	Johannes
-- 
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 v4 1/2] nvme: add tracepoint for nvme_setup_cmd

[Christoph Hellwig]

On Mon, Jan 22, 2018 at 04:53:56PM +0100, Johannes Thumshirn wrote:
> Yes and no. I personally like to have the big hammer when tracing customer
> problems and filter out maunally later. I initially had a tracepoint for each
> of nvme_setup_flush(), nvme_setup_discard(), nvme_setup_rw() but decided it
> was too fine grained.
> 
> nvme_setup_cmd() has the nice side effect that all commands, including
> userspace passtrough commands must pass it. This was extremely helpful in the
> customer bug which inspired me to implement this tracepoint.

Not arguing against placing the tracepoint(s) in nvme_setup_cmd, but
it seems like we should have one for admin and one for I/O commands.
Especially as we have to special case them just about everywhere,
and the overlap of the opcode space is pretty annoying.

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

[Johannes Thumshirn]

On Mon, Jan 22, 2018 at 04:59:56PM +0100, Christoph Hellwig wrote:
> On Mon, Jan 22, 2018 at 04:53:56PM +0100, Johannes Thumshirn wrote:
> > Yes and no. I personally like to have the big hammer when tracing customer
> > problems and filter out maunally later. I initially had a tracepoint for each
> > of nvme_setup_flush(), nvme_setup_discard(), nvme_setup_rw() but decided it
> > was too fine grained.
> > 
> > nvme_setup_cmd() has the nice side effect that all commands, including
> > userspace passtrough commands must pass it. This was extremely helpful in the
> > customer bug which inspired me to implement this tracepoint.
> 
> Not arguing against placing the tracepoint(s) in nvme_setup_cmd, but
> it seems like we should have one for admin and one for I/O commands.
> Especially as we have to special case them just about everywhere,
> and the overlap of the opcode space is pretty annoying.

You mean like:
	if (ns)
		trace_nvme_setup_cmd(cmd);
	else
		trace_nvme_setup_admin_cmd(cmd);

?



-- 
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 v4 1/2] nvme: add tracepoint for nvme_setup_cmd

[Christoph Hellwig]

On Mon, Jan 22, 2018 at 05:04:37PM +0100, Johannes Thumshirn wrote:
> You mean like:
> 	if (ns)
> 		trace_nvme_setup_cmd(cmd);
> 	else
> 		trace_nvme_setup_admin_cmd(cmd);
> 
> ?

Yes.  Although I'd rename trace_nvme_setup_cmd to trace_nvme_setup_nvm_cmd
to prepare for new I/O command sets.

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

[Johannes Thumshirn]

On Mon, Jan 22, 2018 at 05:10:27PM +0100, Christoph Hellwig wrote:
> Yes.  Although I'd rename trace_nvme_setup_cmd to trace_nvme_setup_nvm_cmd
> to prepare for new I/O command sets.

OK then.
-- 
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 v4 2/2] nvme: add tracepoint for nvme_complete_rq

[Martin K. Petersen]

Johannes,

> On Mon, Jan 22, 2018 at 04:23:40PM +0100, Christoph Hellwig wrote:
>> Wouldn't some indication on which queue this completion happens
>> be useful?
>
> Probably yes. I'll add it in v5.

Yes, that would be great. I always end up having to use custom printks
for this.

-- 
Martin K. Petersen	Oracle Linux Engineering