2018-01-24 08:30:42

by Johannes Thumshirn

[permalink] [raw]
Subject: [PATCH v7 0/2] add tracepoints for nvme command submission and completion

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.

This version is a re-base onto nvme-4.16.

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] .... 9.158541: nvme_setup_admin_cmd: cmdid=14, flags=0x0, meta=0x0, cmd=(nvme_admin_create_cq cqid=1, qsize=1023, cq_flags=0x3, irq_vector=0)
<idle>-0 [003] d.h. 9.158705: nvme_complete_rq: cmdid=14, qid=0, res=0, retries=0, flags=0x0, status=0
kworker/u8:0-5 [003] .... 9.158712: nvme_setup_admin_cmd: cmdid=14, flags=0x0, meta=0x0, cmd=(nvme_admin_create_sq sqid=1, qsize=1023, sq_flags=0x1, cqid=1)
<idle>-0 [003] d.h. 9.159214: nvme_complete_rq: cmdid=14, qid=0, res=0, retries=0, flags=0x0, status=0
kworker/u8:0-5 [003] .... 9.159236: nvme_setup_admin_cmd: cmdid=14, flags=0x0, meta=0x0, cmd=(nvme_admin_create_cq cqid=2, qsize=1023, cq_flags=0x3, irq_vector=1)
<idle>-0 [003] d.h. 9.159288: nvme_complete_rq: cmdid=14, qid=0, res=0, retries=0, flags=0x0, status=0
kworker/u8:0-5 [003] .... 9.159293: nvme_setup_admin_cmd: cmdid=14, flags=0x0, meta=0x0, cmd=(nvme_admin_create_sq sqid=2, qsize=1023, sq_flags=0x1, cqid=2)
<idle>-0 [003] d.h. 9.159479: nvme_complete_rq: cmdid=14, qid=0, res=0, retries=0, flags=0x0, status=0
kworker/u8:0-5 [003] .... 9.159525: nvme_setup_admin_cmd: cmdid=14, flags=0x0, meta=0x0, cmd=(nvme_admin_create_cq cqid=3, qsize=1023, cq_flags=0x3, irq_vector=2)
<idle>-0 [003] d.h. 9.159565: nvme_complete_rq: cmdid=14, qid=0, res=0, retries=0, flags=0x0, status=0
kworker/u8:0-5 [003] .... 9.159569: nvme_setup_admin_cmd: cmdid=14, flags=0x0, meta=0x0, cmd=(nvme_admin_create_sq sqid=3, qsize=1023, sq_flags=0x1, cqid=3)
<idle>-0 [003] d.h. 9.159726: nvme_complete_rq: cmdid=14, qid=0, res=0, retries=0, flags=0x0, status=0
kworker/u8:0-5 [003] .... 9.159769: nvme_setup_admin_cmd: cmdid=14, flags=0x0, meta=0x0, cmd=(nvme_admin_create_cq cqid=4, qsize=1023, cq_flags=0x3, irq_vector=3)
<idle>-0 [003] d.h. 9.159795: nvme_complete_rq: cmdid=14, qid=0, res=0, retries=0, flags=0x0, status=0
kworker/u8:0-5 [003] .... 9.159799: nvme_setup_admin_cmd: cmdid=14, flags=0x0, meta=0x0, cmd=(nvme_admin_create_sq sqid=4, qsize=1023, sq_flags=0x1, cqid=4)
<idle>-0 [003] d.h. 9.159957: nvme_complete_rq: cmdid=14, qid=0, res=0, retries=0, flags=0x0, status=0
kworker/u8:0-5 [003] .... 9.160971: nvme_setup_admin_cmd: cmdid=14, flags=0x0, meta=0x0, cmd=(nvme_admin_identify cns=0, ctrlid=1)
<idle>-0 [003] d.h. 9.161059: nvme_complete_rq: cmdid=14, qid=0, res=0, retries=0, flags=0x0, status=0
kworker/u8:0-5 [003] .... 9.161101: nvme_setup_admin_cmd: cmdid=14, flags=0x0, meta=0x0, cmd=(nvme_admin_identify cns=0, ctrlid=0)
<idle>-0 [003] d.h. 9.161160: nvme_complete_rq: cmdid=14, qid=0, res=0, retries=0, flags=0x0, status=0
kworker/u8:0-5 [003] .... 9.161305: nvme_setup_admin_cmd: cmdid=14, flags=0x0, meta=0x0, cmd=(nvme_admin_identify cns=0, ctrlid=0)
<idle>-0 [003] d.h. 9.161344: nvme_complete_rq: cmdid=14, qid=0, res=0, retries=0, flags=0x0, status=0
kworker/u8:0-5 [003] .... 9.161390: nvme_setup_nvm_cmd: qid=1, nsid=1, cmdid=718, flags=0x0, meta=0x0, cmd=(nvme_cmd_read slba=0, len=7, ctrl=0x0, dsmgmt=0, reftag=0)
<idle>-0 [003] d.h. 9.161578: nvme_complete_rq: cmdid=718, qid=1, res=0, retries=0, flags=0x0, status=0
kworker/u8:0-5 [003] .... 9.161608: nvme_setup_nvm_cmd: qid=1, nsid=1, cmdid=718, flags=0x0, meta=0x0, cmd=(nvme_cmd_read slba=24, len=7, ctrl=0x0, dsmgmt=0, reftag=0)
<idle>-0 [003] d.h. 9.161681: nvme_complete_rq: cmdid=718, qid=1, res=0, retries=0, flags=0x0, status=0
dd-205 [001] .... 9.662909: nvme_setup_nvm_cmd: qid=1, nsid=1, cmdid=1011, flags=0x0, meta=0x0, cmd=(nvme_cmd_read slba=0, len=2559, ctrl=0x0, dsmgmt=0, reftag=0)
dd-205 [001] .... 9.662967: nvme_setup_nvm_cmd: qid=1, nsid=1, cmdid=1012, flags=0x0, meta=0x0, cmd=(nvme_cmd_read slba=2560, len=1535, ctrl=0x0, dsmgmt=0, reftag=0)
<idle>-0 [001] d.h. 9.664413: nvme_complete_rq: cmdid=1011, qid=1, res=0, retries=0, flags=0x0, status=0
<idle>-0 [001] d.h. 9.664835: nvme_complete_rq: cmdid=1012, qid=1, res=0, retries=0, flags=0x0, status=0
dd-205 [001] .... 9.666396: nvme_setup_nvm_cmd: qid=1, nsid=1, cmdid=1012, flags=0x0, meta=0x0, cmd=(nvme_cmd_read slba=4096, len=2047, ctrl=0x0, dsmgmt=0, reftag=0)
dd-205 [001] .... 9.667914: nvme_setup_nvm_cmd: qid=1, nsid=1, cmdid=1013, flags=0x0, meta=0x0, cmd=(nvme_cmd_read slba=6144, len=2047, ctrl=0x0, dsmgmt=0, reftag=0)
<idle>-0 [001] d.h. 9.676720: nvme_complete_rq: cmdid=1012, qid=1, res=0, retries=0, flags=0x0, status=0
dd-205 [001] d.h. 9.676905: nvme_complete_rq: cmdid=1013, qid=1, res=0, retries=0, flags=0x0, status=0
dd-205 [001] .... 9.677552: nvme_setup_nvm_cmd: qid=1, nsid=1, cmdid=1013, flags=0x0, meta=0x0, cmd=(nvme_cmd_read slba=8192, len=2047, ctrl=0x0, dsmgmt=0, reftag=0)
dd-205 [001] .... 9.678201: nvme_setup_nvm_cmd: qid=1, nsid=1, cmdid=1014, flags=0x0, meta=0x0, cmd=(nvme_cmd_read slba=10240, len=2047, ctrl=0x0, dsmgmt=0, reftag=0)
<idle>-0 [001] d.h. 9.678699: nvme_complete_rq: cmdid=1013, qid=1, res=0, retries=0, flags=0x0, status=0
dd-205 [001] d.h. 9.679330: nvme_complete_rq: cmdid=1014, qid=1, res=0, retries=0, flags=0x0, status=0
dd-206 [002] .... 9.687920: nvme_setup_nvm_cmd: qid=1, nsid=1, cmdid=366, flags=0x0, meta=0x0, cmd=(nvme_cmd_write slba=0, len=2559, ctrl=0x0, dsmgmt=0, reftag=0)
dd-206 [002] .... 9.688396: nvme_setup_nvm_cmd: qid=1, nsid=1, cmdid=367, flags=0x0, meta=0x0, cmd=(nvme_cmd_write slba=2560, len=2559, ctrl=0x0, dsmgmt=0, reftag=0)
dd-206 [002] .... 9.689290: nvme_setup_nvm_cmd: qid=1, nsid=1, cmdid=368, flags=0x0, meta=0x0, cmd=(nvme_cmd_write slba=5120, len=2559, ctrl=0x0, dsmgmt=0, reftag=0)
dd-206 [002] .... 9.689759: nvme_setup_nvm_cmd: qid=1, nsid=1, cmdid=369, flags=0x0, meta=0x0, cmd=(nvme_cmd_write slba=7680, len=2559, ctrl=0x0, dsmgmt=0, reftag=0)
<idle>-0 [002] d.h. 9.690222: nvme_complete_rq: cmdid=366, qid=1, res=0, retries=0, flags=0x0, status=0
<idle>-0 [002] d.h. 9.691086: nvme_complete_rq: cmdid=367, qid=1, res=0, retries=0, flags=0x0, status=0
<idle>-0 [002] d.h. 9.691935: nvme_complete_rq: cmdid=368, qid=1, res=0, retries=0, flags=0x0, status=0
<idle>-0 [002] d.h. 9.692852: nvme_complete_rq: cmdid=369, qid=1, res=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/Makefile | 4 ++
drivers/nvme/host/core.c | 9 +++
drivers/nvme/host/trace.c | 131 +++++++++++++++++++++++++++++++++++
drivers/nvme/host/trace.h | 167 +++++++++++++++++++++++++++++++++++++++++++++
4 files changed, 311 insertions(+)
create mode 100644 drivers/nvme/host/trace.c
create mode 100644 drivers/nvme/host/trace.h

--
2.13.6



2018-01-24 08:29:39

by Johannes Thumshirn

[permalink] [raw]
Subject: [PATCH v7 1/2] nvme: add tracepoint for nvme_setup_cmd

Add tracepoints for nvme_setup_cmd() for tracing admin and/or nvm commands.

Examples of the two tracepoints are as follows for trace_nvme_setup_admin_cmd():
kworker/u8:0-5 [003] .... 2.998792: nvme_setup_admin_cmd: cmdid=14, flags=0x0, meta=0x0, cmd=(nvme_admin_create_cq cqid=1, qsize=1023, cq_flags=0x3, irq_vector=0)

and trace_nvme_setup_nvm_cmd():
dd-205 [001] .... 3.503929: nvme_setup_nvm_cmd: qid=1, nsid=1, cmdid=989, flags=0x0, meta=0x0, cmd=(nvme_cmd_read slba=4096, len=2047, ctrl=0x0, dsmgmt=0, reftag=0)

Signed-off-by: Johannes Thumshirn <[email protected]>
Reviewed-by: Hannes Reinecke <[email protected]>
Reviewed-by: Martin K. Petersen <[email protected]>
Reviewed-by: Keith Busch <[email protected]>
Reviewed-by: Sagi Grimberg <[email protected]>
---
drivers/nvme/host/Makefile | 4 ++
drivers/nvme/host/core.c | 7 +++
drivers/nvme/host/trace.c | 131 +++++++++++++++++++++++++++++++++++++++++
drivers/nvme/host/trace.h | 141 +++++++++++++++++++++++++++++++++++++++++++++
4 files changed, 283 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 fde6fd2e7eef..358dfdc1f6da 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"

@@ -628,6 +631,10 @@ blk_status_t nvme_setup_cmd(struct nvme_ns *ns, struct request *req,
}

cmd->common.command_id = req->tag;
+ if (ns)
+ trace_nvme_setup_nvm_cmd(req->q->id, cmd);
+ else
+ trace_nvme_setup_admin_cmd(cmd);
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..87beb77dcc6c
--- /dev/null
+++ b/drivers/nvme/host/trace.c
@@ -0,0 +1,131 @@
+/*
+ * 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"
+
+static const char *nvme_trace_create_sq(struct trace_seq *p, __le32 *cdw10)
+{
+ const char *ret = trace_seq_buffer_ptr(p);
+ __le16 qsize = cdw10[0] >> 16;
+ __le16 sqid = cdw10[0] & 0xffff;
+ __le16 cqid = cdw10[1] >> 16;
+ __le16 sq_flags = cdw10[1] & 0xffff;
+
+ trace_seq_printf(p, "sqid=%u, qsize=%u, sq_flags=0x%x, cqid=%u",
+ le16_to_cpu(sqid), le16_to_cpu(qsize),
+ le16_to_cpu(sq_flags), le16_to_cpu(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);
+ __le16 qsize = cdw10[0] >> 16;
+ __le16 cqid = cdw10[0] & 0xffff;
+ __le16 irq_vector = cdw10[1] >> 16;
+ __le16 cq_flags = cdw10[1] & 0xffff;
+
+ trace_seq_printf(p, "cqid=%u, qsize=%u, cq_flags=0x%x, irq_vector=%u",
+ le16_to_cpu(cqid), le16_to_cpu(qsize),
+ le16_to_cpu(cq_flags), le16_to_cpu(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);
+ __u8 cns = (cdw10[0] >> 24) & 0xff;
+ __le16 ctrlid = cdw10[0] & 0xffff;
+
+ trace_seq_printf(p, "cns=%u, ctrlid=%u", cns, le16_to_cpu(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);
+ __le64 slba = ((u64)cdw10[1] << 32) | cdw10[0];
+ __le16 control = cdw10[2] >> 16;
+ __le16 length = cdw10[2] & 0xffff;
+ __le32 dsmgmt = cdw10[3];
+ __le32 reftag = cdw10[4];
+
+ trace_seq_printf(p,
+ "slba=%llu, len=%u, ctrl=0x%x, dsmgmt=%u, reftag=%u",
+ le64_to_cpu(slba), le16_to_cpu(length),
+ le16_to_cpu(control), le32_to_cpu(dsmgmt),
+ le32_to_cpu(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);
+
+ trace_seq_printf(p, "nr=%u, attributes=%u",
+ le32_to_cpu(cdw10[0]), le32_to_cpu(cdw10[1]));
+ 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_admin_cmd(struct trace_seq *p,
+ u8 opcode, __le32 *cdw10)
+{
+ 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);
+ }
+}
+
+const char *nvme_trace_parse_nvm_cmd(struct trace_seq *p,
+ u8 opcode, __le32 *cdw10)
+{
+ 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..f17dbfbead5a
--- /dev/null
+++ b/drivers/nvme/host/trace.h
@@ -0,0 +1,141 @@
+/*
+ * 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))
+
+const char *nvme_trace_parse_admin_cmd(struct trace_seq *p, u8 opcode,
+ __le32 *cdw10);
+#define __parse_nvme_admin_cmd(opcode, cdw10) \
+ nvme_trace_parse_admin_cmd(p, opcode, cdw10)
+
+#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_nvm_cmd(struct trace_seq *p, u8 opcode,
+ __le32 *cdw10);
+#define __parse_nvme_cmd(opcode, cdw10) \
+ nvme_trace_parse_nvm_cmd(p, opcode, cdw10)
+
+TRACE_EVENT(nvme_setup_admin_cmd,
+ TP_PROTO(struct nvme_command *cmd),
+ TP_ARGS(cmd),
+ TP_STRUCT__entry(
+ __field(__u8, opcode)
+ __field(__u8, flags)
+ __field(__u16, cid)
+ __field(__le64, metadata)
+ __array(__le32, cdw10, 6)
+ ),
+ TP_fast_assign(
+ __entry->opcode = cmd->common.opcode;
+ __entry->flags = cmd->common.flags;
+ __entry->cid = cmd->common.command_id;
+ __entry->metadata = cmd->common.metadata;
+ memcpy(__entry->cdw10, cmd->common.cdw10,
+ sizeof(__entry->cdw10));
+ ),
+ TP_printk(" cmdid=%u, flags=0x%x, meta=0x%llx, cmd=(%s %s)",
+ __entry->cid, __entry->flags,
+ le64_to_cpu(__entry->metadata),
+ show_admin_opcode_name(__entry->opcode),
+ __parse_nvme_admin_cmd(__entry->opcode, __entry->cdw10))
+);
+
+
+TRACE_EVENT(nvme_setup_nvm_cmd,
+ TP_PROTO(int qid, struct nvme_command *cmd),
+ TP_ARGS(qid, cmd),
+ TP_STRUCT__entry(
+ __field(int, qid)
+ __field(__u8, opcode)
+ __field(__u8, flags)
+ __field(__u16, cid)
+ __field(__le32, nsid)
+ __field(__le64, metadata)
+ __array(__le32, cdw10, 6)
+ ),
+ TP_fast_assign(
+ __entry->qid = qid;
+ __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("qid=%d, nsid=%u, cmdid=%u, flags=0x%x, meta=0x%llx, cmd=(%s %s)",
+ __entry->qid, le32_to_cpu(__entry->nsid), __entry->cid,
+ __entry->flags, le64_to_cpu(__entry->metadata),
+ show_opcode_name(__entry->opcode),
+ __parse_nvme_cmd(__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.13.6


2018-01-24 08:30:00

by Johannes Thumshirn

[permalink] [raw]
Subject: [PATCH v7 2/2] nvme: add tracepoint for nvme_complete_rq

Add a tracepoint in nvme_complete_rq() for completions of NVMe commands. An
expmale output of the trace-point is as follows:

<idle>-0 [001] d.h. 3.505266: nvme_complete_rq: cmdid=989, qid=1, res=0, retries=0, flags=0x0, status=0

Signed-off-by: Johannes Thumshirn <[email protected]>
Reviewed-by: Hannes Reinecke <[email protected]>
Reviewed-by: Martin K. Petersen <[email protected]>
Reviewed-by: Keith Busch <[email protected]>
Reviewed-by: Sagi Grimberg <[email protected]>
---
drivers/nvme/host/core.c | 2 ++
drivers/nvme/host/trace.h | 26 ++++++++++++++++++++++++++
2 files changed, 28 insertions(+)

diff --git a/drivers/nvme/host/core.c b/drivers/nvme/host/core.c
index 358dfdc1f6da..7cbd4a260d30 100644
--- a/drivers/nvme/host/core.c
+++ b/drivers/nvme/host/core.c
@@ -220,6 +220,8 @@ void nvme_complete_rq(struct request *req)
{
blk_status_t status = nvme_error_status(req);

+ trace_nvme_complete_rq(req);
+
if (unlikely(status != BLK_STS_OK && nvme_req_needs_retry(req))) {
if (nvme_req_needs_failover(req, status)) {
nvme_failover_req(req);
diff --git a/drivers/nvme/host/trace.h b/drivers/nvme/host/trace.h
index f17dbfbead5a..afd87235311b 100644
--- a/drivers/nvme/host/trace.h
+++ b/drivers/nvme/host/trace.h
@@ -130,6 +130,32 @@ TRACE_EVENT(nvme_setup_nvm_cmd,
__parse_nvme_cmd(__entry->opcode, __entry->cdw10))
);

+TRACE_EVENT(nvme_complete_rq,
+ TP_PROTO(struct request *req),
+ TP_ARGS(req),
+ TP_STRUCT__entry(
+ __field(int, qid)
+ __field(int, cid)
+ __field(__le64, result)
+ __field(u8, retries)
+ __field(u8, flags)
+ __field(u16, status)
+ ),
+ TP_fast_assign(
+ __entry->qid = req->q->id;
+ __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, qid=%d, res=%llu, retries=%u, flags=0x%x, status=%u",
+ __entry->cid, __entry->qid,
+ le64_to_cpu(__entry->result),
+ __entry->retries, __entry->flags, __entry->status)
+
+);
+
#endif /* _TRACE_NVME_H */

#undef TRACE_INCLUDE_PATH
--
2.13.6