Skip to contentSkip to conversation

nvme trace updates

PATCH New Keith Busch 5 participants 14 messages Jun 29, 2018 – Jul 2, 2018

Subsystems (3)
NVMe NVMe target NVMe FC transport
lore
Share & tools
lore

Keith Busch

author
#0 lore raw

v4 cover nvme trace updates

This patch series is based on/inspired patches from Johannes Thumshirn that improves the nvme trace events.

The first one from Sagi is saving the nvme_ctrl in the driver request data so we can reference it in other places, both for this series and future developments.

The others simplifying and add to the nvme traces so we can see uniquely identify what controller the trace event is showing, pair up completions to their submissions, and filter events for specific hardware.

For good measure, I offer the following awk script (called nvme-iosnoop, inspired by Brendan Gregg's iosnoop) to help parse the trace output. This will pair up the submission and completion trace events and tell us interesting things about nvme disk activity.

Example output:

# cat /sys/kernel/debug/tracing/trace | awk -f ~/bin/nvme-iosnoop.awk
COMM         PID    TYPE  DEV      SLBA         NLB       LATms
kworker/62:1 2550   write nvme0n1  0            8         0.051
kworker/62:1 2550   write nvme0n1  8            8         0.027
kworker/62:1 2550   write nvme0n1  16           8         0.013
kworker/62:1 2550   write nvme0n1  24           8         0.014
kworker/62:1 2550   write nvme0n1  32           8         0.013
kworker/62:1 2550   write nvme0n1  40           8         0.014
kworker/62:1 2550   write nvme0n1  48           8         0.014
kworker/63:1 2549   write nvme0n1  56           8         0.035
systemd-udev 1595   read  nvme0n1  0            8         0.087
systemd-udev 1595   read  nvme0n1  8            8         0.056
systemd-udev 4066   read  nvme0n1  781422592    8         0.060
systemd-udev 4066   read  nvme0n1  781422752    8         0.009
dd           4213   read  nvme1n1  0            8         0.070
dd           4213   read  nvme1n1  8            8         0.010
dd           4213   read  nvme1n1  16           8         0.012
dd           4213   read  nvme1n1  24           8         0.009
dd           4213   read  nvme1n1  32           8         0.011
dd           4213   read  nvme1n1  40           8         0.010
systemd-udev 4066   read  nvme0n1  64           56        0.034
systemd-udev 4066   read  nvme0n1  256          16        0.011
systemd-udev 4066   read  nvme0n1  128          128       0.057
systemd-udev 4066   read  nvme0n1  16           8         0.106
systemd-udev 4066   read  nvme0n1  32           24        0.132
systemd-udev 4066   read  nvme0n1  272          240       0.047
systemd-udev 4066   read  nvme0n1  512          256       0.051
systemd-udev 4066   read  nvme0n1  768          256       0.049

---
#!/usr/bin/awk

BEGIN {
	printf "%-12.12s %-6s %-5s %-8s %-12s %-6s %8s\n", \
		"COMM", "PID", "TYPE", "DEV", "SLBA", "NLB", "LATms"
}
{
	if ($1 != "#") {
		dev = $7; sub("disk=", "", dev); sub(",", "", dev)
		time = $4; sub(":", "", time)
		qid = $8; sub("qid=", "", qid); sub(",", "", qid)
		cid = $9; sub("cid=", "", cid); sub(",", "", cid)
	}

	if ($1 != "#" && $0 ~ /nvme_setup_cmd/) {
		comm = pid = $1
		sub(/-[0-9][0-9]*/, "", comm)
		sub(/.*-/, "", pid)
		slba = $14; sub("slba=", "", slba); sub(",", "", slba)
		len = $15; sub("len=", "", len); sub(",", "", len)

		starts[dev, qid, cid] = time
		slbas[dev, qid, cid] = slba
		lens[dev, qid, cid] = len + 1
		pids[dev, qid, cid] = pid
		comms[dev, qid, cid] = comm

		if ($0 ~ /nvme_cmd_read/) {
			dir[dev, qid, cid] = "read"
		}
		if ($0 ~ /nvme_cmd_write/) {
			dir[dev, qid, cid] = "write"
		}
		next
	}

	if ($1 != "#" && $0 ~ /nvme_complete_rq/) {
		if (starts[dev, qid, cid] > 0) {
			latency = sprintf("%.3f", 1000 * (time - starts[dev, qid, cid]))
			printf "%-12.12s %-6s %-5s %-8s %-12s %-6s %8s\n",
				comms[dev, qid, cid], pids[dev, qid, cid], dir[dev, qid, cid],
				dev, slbas[dev, qid, cid], lens[dev, qid, cid], latency

			delete comms[dev, qid, cid]
			delete pids[dev, qid, cid]
			delete dir[dev, qid, cid]
			delete slbas[dev, qid, cid]
			delete lens[dev, qid, cid]
			delete starts[dev, qid, cid]
		}
		next
	}
}

END{}
--

v3 -> v4:

Fixed the parameter print order, nsid and cmdid

v2 -> v3:

Removed unrelated code that leaked into the previous series

Added helpers for setting the new qid and disk name fields

Updated change logs

Minor code formatting updates

Added Reviewed-by for Sagi's patch

v1 -> v2:

Dropped the blk-mq patch as there were pre-existing ways to get to the desired information without introducing a new API

Changelog typo fixups

Keith Busch (3):
nvme: use hw qid in trace events
nvme: add controller name to trace events
nvme: add disk name to trace events

Sagi Grimberg (1):
nvme: cache struct nvme_ctrl reference to struct nvme_request

 drivers/nvme/host/core.c   |   5 +-
 drivers/nvme/host/fc.c     |   1 +
 drivers/nvme/host/nvme.h   |   1 +
 drivers/nvme/host/pci.c    |   2 +
 drivers/nvme/host/rdma.c   |   1 +
 drivers/nvme/host/trace.c  |  11 ++++
 drivers/nvme/host/trace.h  | 139 +++++++++++++++++++++++++--------------------
 drivers/nvme/target/loop.c |   1 +
 8 files changed, 94 insertions(+), 67 deletions(-)
Signature · 1 line
2.14.3
author
#1 lore raw

PATCH v4 1/4 nvme: cache struct nvme_ctrl reference to struct nvme_request

From: Sagi Grimberg <[email protected]>

We will need to reference the controller in the setup and completion time for tracing and future traffic based keep alive support.

Reviewed-by Johannes Thumshirn <jthumshirn at suse.de>
Signed-off-by Sagi Grimberg <sagi at grimberg.me>
---
 drivers/nvme/host/fc.c     | 1 +
 drivers/nvme/host/nvme.h   | 1 +
 drivers/nvme/host/pci.c    | 2 ++
 drivers/nvme/host/rdma.c   | 1 +
 drivers/nvme/target/loop.c | 1 +
 5 files changed, 6 insertions(+)
drivers/nvme/host/fc.c +1 -0
index 41d45a1b5c62..9cc33752539a 100644
@@ -1737,6 +1737,7 @@ nvme_fc_init_request(struct blk_mq_tag_set *set, struct request *rq,
 	int queue_idx = (set == &ctrl->tag_set) ? hctx_idx + 1 : 0;
 	struct nvme_fc_queue *queue = &ctrl->queues[queue_idx];
 
+	nvme_req(rq)->ctrl = &ctrl->ctrl;
 	return __nvme_fc_init_request(ctrl, queue, op, rq, queue->rqcnt++);
 }
drivers/nvme/host/nvme.h +1 -0
index 0c4a33df3b2f..f2249387b60d 100644
@@ -102,6 +102,7 @@ struct nvme_request {
 	u8			retries;
 	u8			flags;
 	u16			status;
+	struct nvme_ctrl	*ctrl;
 };
 
 /*
drivers/nvme/host/pci.c +2 -0
index ba943f211687..8dcae11bbf3a 100644
@@ -418,6 +418,8 @@ static int nvme_init_request(struct blk_mq_tag_set *set, struct request *req,
 
 	BUG_ON(!nvmeq);
 	iod->nvmeq = nvmeq;
+
+	nvme_req(req)->ctrl = &dev->ctrl;
 	return 0;
 }
drivers/nvme/host/rdma.c +1 -0
index 9544625c0b7d..ade55977d432 100644
@@ -286,6 +286,7 @@ static int nvme_rdma_init_request(struct blk_mq_tag_set *set,
 	struct ib_device *ibdev = dev->dev;
 	int ret;
 
+	nvme_req(rq)->ctrl = &ctrl->ctrl;
 	ret = nvme_rdma_alloc_qe(ibdev, &req->sqe, sizeof(struct nvme_command),
 			DMA_TO_DEVICE);
 	if (ret)
drivers/nvme/target/loop.c +1 -0
index d8d91f04bd7e..af7fbf4132b0 100644
@@ -227,6 +227,7 @@ static int nvme_loop_init_request(struct blk_mq_tag_set *set,
 {
 	struct nvme_loop_ctrl *ctrl = set->driver_data;
 
+	nvme_req(req)->ctrl = &ctrl->ctrl;
 	return nvme_loop_init_iod(ctrl, blk_mq_rq_to_pdu(req),
 			(set == &ctrl->tag_set) ? hctx_idx + 1 : 0);
 }
Signature · 1 line
2.14.3
author
#2 lore raw

PATCH v4 2/4 nvme: use hw qid in trace events

In reply to Keith Busch

We can not match a command to its completion based on the command id alone. We need the submitting queue identifier to pair with the completion, so this patch adds that to the trace buffer.

This patch is also collapsing the admin and IO submission traces into a single one so we don't need to duplicate this and creating unnecessary code branches: we know if the command is an admin vs IO based on the qid.

And since we're here, the patch fixes code formatting in the area.

Signed-off-by Keith Busch <keith.busch at intel.com>
---
 drivers/nvme/host/core.c  |   5 +-
 drivers/nvme/host/trace.h | 113 +++++++++++++++++++++-------------------------
 2 files changed, 53 insertions(+), 65 deletions(-)
drivers/nvme/host/core.c +1 -4
index 46df030b2c3f..90eb7c55415b 100644
@@ -652,10 +652,7 @@ 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);
+	trace_nvme_setup_cmd(req, cmd);
 	return ret;
 }
 EXPORT_SYMBOL_GPL(nvme_setup_cmd);
drivers/nvme/host/trace.h +52 -61

152 lines not on this page · raw message

Signature · 1 line
2.14.3
#3 lore raw

PATCH v4 2/4 nvme: use hw qid in trace events

Looks good,
Reviewed-by: Johannes Thumshirn <jthumshirn at suse.de>

Signature · 6 lines
Johannes Thumshirn                                          Storage
jthumshirn at 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
maintainer
#4 lore raw

PATCH v4 2/4 nvme: use hw qid in trace events

In reply to Keith Busch
Quoted 6 lines
drivers/nvme/host/trace.h +0 -0
index 01390f0e1671..6f9ee5fe5e09 100644
@@ -24,6 +24,15 @@

drivers/nvme/host/trace.h line 34

Quoted 10 lines
drivers/nvme/host/trace.h +8 -0
 #include "nvme.h"
 
+#define __assign_nvme_qid(req, qid)					\
+	do {								\
+		if (req->rq_disk)					\
+			qid = 1 + blk_mq_unique_tag_to_hwq(		\
+					blk_mq_unique_tag(req));	\
+		else							\
+			qid = 0;					\
+	} while (0)

Why can't we use an inline function for this?

Relying on assining to macro paramters is a good way to generate unreadable code.

#5 lore raw

PATCH v4 2/4 nvme: use hw qid in trace events

Quoted 19 lines · Christoph Hellwig
Quoted 6 lines
drivers/nvme/host/trace.h +0 -0
index 01390f0e1671..6f9ee5fe5e09 100644
@@ -24,6 +24,15 @@

drivers/nvme/host/trace.h line 34

Quoted 10 lines
drivers/nvme/host/trace.h +8 -0
 #include "nvme.h"
 
+#define __assign_nvme_qid(req, qid)					\
+	do {								\
+		if (req->rq_disk)					\
+			qid = 1 + blk_mq_unique_tag_to_hwq(		\
+					blk_mq_unique_tag(req));	\
+		else							\
+			qid = 0;					\
+	} while (0)

Why can't we use an inline function for this?

Quoted 2 lines

Relying on assining to macro paramters is a good way to generate unreadable code.

Sure, I can respin these as inline functions.

maintainer
#6 lore raw

PATCH v4 2/4 nvme: use hw qid in trace events

Quoted 4 lines · Keith Busch
Quoted 2 lines

Relying on assining to macro paramters is a good way to generate unreadable code.

Sure, I can respin these as inline functions.

I'll fix it up when applying.

#7 lore raw

PATCH v4 2/4 nvme: use hw qid in trace events

Quoted 7 lines · Christoph Hellwig
Quoted 4 lines · Keith Busch
Quoted 2 lines

Relying on assining to macro paramters is a good way to generate unreadable code.

Sure, I can respin these as inline functions.

I'll fix it up when applying.

Even better. :)

author
#8 lore raw

PATCH v4 3/4 nvme: add controller name to trace events

In reply to Keith Busch

This appends the controller instance to the nvme trace buffer to distinguish which controller is dispatching and completing a command.

Signed-off-by Keith Busch <keith.busch at intel.com>
---
 drivers/nvme/host/trace.h | 17 +++++++++++------
 1 file changed, 11 insertions(+), 6 deletions(-)
drivers/nvme/host/trace.h +11 -6
index 6f9ee5fe5e09..b171b54f4b0e 100644
@@ -95,6 +95,7 @@ TRACE_EVENT(nvme_setup_cmd,
 	    TP_PROTO(struct request *req, struct nvme_command *cmd),
 	    TP_ARGS(req, cmd),
 	    TP_STRUCT__entry(
+		__field(int, ctrl_id)
 		__field(int, qid)
 		__field(u8, opcode)
 		__field(u8, flags)

@@ -105,6 +106,7 @@ TRACE_EVENT(nvme_setup_cmd,
 	    ),
 	    TP_fast_assign(
 		__assign_nvme_qid(req, __entry->qid);
+		__entry->ctrl_id = nvme_req(req)->ctrl->instance;
 		__entry->opcode = cmd->common.opcode;
 		__entry->flags = cmd->common.flags;
 		__entry->cid = cmd->common.command_id;

@@ -113,9 +115,9 @@ TRACE_EVENT(nvme_setup_cmd,
 		memcpy(__entry->cdw10, cmd->common.cdw10,
 		       sizeof(__entry->cdw10));
 	    ),
-	    TP_printk("qid=%d, cmdid=%u, nsid=%u, flags=0x%x, meta=0x%llx, cmd=(%s %s)",
-		      __entry->qid, __entry->cid, __entry->nsid,
-		      __entry->flags, __entry->metadata,
+	    TP_printk("nvme%d: qid=%d, cmdid=%u, nsid=%u, flags=0x%x, meta=0x%llx, cmd=(%s %s)",
+		      __entry->ctrl_id, __entry->qid, __entry->cid,
+		      __entry->nsid, __entry->flags, __entry->metadata,
 		      show_opcode_name(__entry->qid, __entry->opcode),
 		      parse_nvme_cmd(__entry->qid, __entry->opcode, __entry->cdw10))
 );

@@ -124,6 +126,7 @@ TRACE_EVENT(nvme_complete_rq,
 	    TP_PROTO(struct request *req),
 	    TP_ARGS(req),
 	    TP_STRUCT__entry(
+		__field(int, ctrl_id)
 		__field(int, qid)
 		__field(int, cid)
 		__field(u64, result)

@@ -133,15 +136,17 @@ TRACE_EVENT(nvme_complete_rq,
 	    ),
 	    TP_fast_assign(
 		__assign_nvme_qid(req, __entry->qid);
+		__entry->ctrl_id = nvme_req(req)->ctrl->instance;
 		__entry->cid = req->tag;
 		__entry->result = le64_to_cpu(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("qid=%d, cmdid=%u, res=%llu, retries=%u, flags=0x%x, status=%u",
-		      __entry->qid, __entry->cid, __entry->result,
-		      __entry->retries, __entry->flags, __entry->status)
+	    TP_printk("nvme%d: qid=%d, cmdid=%u, res=%llu, retries=%u, flags=0x%x, status=%u",
+		      __entry->ctrl_id,  __entry->qid, __entry->cid,
+		      __entry->result, __entry->retries, __entry->flags,
+		      __entry->status)
 
 );
Signature · 1 line
2.14.3
#9 lore raw

PATCH v4 3/4 nvme: add controller name to trace events

Looks good,
Reviewed-by: Johannes Thumshirn <jthumshirn at suse.de>

Signature · 6 lines
Johannes Thumshirn                                          Storage
jthumshirn at 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
author
#10 lore raw

PATCH v4 4/4 nvme: add disk name to trace events

In reply to Keith Busch

This will print the disk name to the nvme event trace for io requests so a user can better distinguish traffic to different disks. This can be used to create disk based filters. For example, to see only nvme0n2 traffic:

echo "disk == \"nvme0n2\"" > /sys/kernel/debug/tracing/events/nvme/filter

Signed-off-by Keith Busch <keith.busch at intel.com>
---
 drivers/nvme/host/trace.c | 11 +++++++++++
 drivers/nvme/host/trace.h | 31 ++++++++++++++++++++++++-------
 2 files changed, 35 insertions(+), 7 deletions(-)
drivers/nvme/host/trace.c +11 -0
index 41944bbef835..25b0e310f4a8 100644
@@ -128,3 +128,14 @@ const char *nvme_trace_parse_nvm_cmd(struct trace_seq *p,
 		return nvme_trace_common(p, cdw10);
 	}
 }
+
+const char *nvme_trace_disk_name(struct trace_seq *p, char *name)
+{
+	const char *ret = trace_seq_buffer_ptr(p);
+
+	if (*name)
+		trace_seq_printf(p, "disk=%s, ", name);
+	trace_seq_putc(p, 0);
+
+	return ret;
+}
drivers/nvme/host/trace.h +24 -7
index b171b54f4b0e..6d6a25934765 100644
@@ -91,10 +91,23 @@ const char *nvme_trace_parse_nvm_cmd(struct trace_seq *p, u8 opcode,
 	(qid ? __parse_nvm_cmd(opcode, cdw10) : 		\
 	       __parse_admin_cmd(opcode, cdw10))
 
+#define __assign_disk_name(name, disk)					\
+	do {								\
+		if (disk)						\
+			memcpy(name, disk->disk_name, DISK_NAME_LEN);	\
+		else							\
+			memset(name, 0, DISK_NAME_LEN);			\
+	} while (0)
+
+const char *nvme_trace_disk_name(struct trace_seq *p, char *name);
+#define __print_disk_name(name)				\
+	nvme_trace_disk_name(p, name)
+
 TRACE_EVENT(nvme_setup_cmd,
 	    TP_PROTO(struct request *req, struct nvme_command *cmd),
 	    TP_ARGS(req, cmd),
 	    TP_STRUCT__entry(
+		__array(char, disk, DISK_NAME_LEN)
 		__field(int, ctrl_id)
 		__field(int, qid)
 		__field(u8, opcode)

@@ -112,12 +125,14 @@ TRACE_EVENT(nvme_setup_cmd,
 		__entry->cid = cmd->common.command_id;
 		__entry->nsid = le32_to_cpu(cmd->common.nsid);
 		__entry->metadata = le64_to_cpu(cmd->common.metadata);
+		__assign_disk_name(__entry->disk, req->rq_disk);
 		memcpy(__entry->cdw10, cmd->common.cdw10,
 		       sizeof(__entry->cdw10));
 	    ),
-	    TP_printk("nvme%d: qid=%d, cmdid=%u, nsid=%u, flags=0x%x, meta=0x%llx, cmd=(%s %s)",
-		      __entry->ctrl_id, __entry->qid, __entry->cid,
-		      __entry->nsid, __entry->flags, __entry->metadata,
+	    TP_printk("nvme%d: %sqid=%d, cmdid=%u, nsid=%u, flags=0x%x, meta=0x%llx, cmd=(%s %s)",
+		      __entry->ctrl_id, __print_disk_name(__entry->disk),
+		      __entry->qid, __entry->cid, __entry->nsid,
+		      __entry->flags, __entry->metadata,
 		      show_opcode_name(__entry->qid, __entry->opcode),
 		      parse_nvme_cmd(__entry->qid, __entry->opcode, __entry->cdw10))
 );

@@ -126,6 +141,7 @@ TRACE_EVENT(nvme_complete_rq,
 	    TP_PROTO(struct request *req),
 	    TP_ARGS(req),
 	    TP_STRUCT__entry(
+		__array(char, disk, DISK_NAME_LEN)
 		__field(int, ctrl_id)
 		__field(int, qid)
 		__field(int, cid)

@@ -142,11 +158,12 @@ TRACE_EVENT(nvme_complete_rq,
 		__entry->retries = nvme_req(req)->retries;
 		__entry->flags = nvme_req(req)->flags;
 		__entry->status = nvme_req(req)->status;
+		__assign_disk_name(__entry->disk, req->rq_disk);
 	    ),
-	    TP_printk("nvme%d: qid=%d, cmdid=%u, res=%llu, retries=%u, flags=0x%x, status=%u",
-		      __entry->ctrl_id,  __entry->qid, __entry->cid,
-		      __entry->result, __entry->retries, __entry->flags,
-		      __entry->status)
+	    TP_printk("nvme%d: %sqid=%d, cmdid=%u, res=%llu, retries=%u, flags=0x%x, status=%u",
+		      __entry->ctrl_id, __print_disk_name(__entry->disk),
+		      __entry->qid, __entry->cid, __entry->result,
+		      __entry->retries, __entry->flags, __entry->status)
 
 );
Signature · 1 line
2.14.3
#11 lore raw

PATCH v4 4/4 nvme: add disk name to trace events

Looks good,
Reviewed-by: Johannes Thumshirn <jthumshirn at suse.de>

Signature · 6 lines
Johannes Thumshirn                                          Storage
jthumshirn at 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
maintainer
#12 lore raw

PATCH v4 4/4 nvme: add disk name to trace events

In reply to Keith Busch

drivers/nvme/host/trace.h const char *nvme_trace_parse_nvm_cmd(struct trace_seq *p, u8 opcode, · line 100

Quoted 7 lines
drivers/nvme/host/trace.h +7 -0
+#define __assign_disk_name(name, disk)					\
+	do {								\
+		if (disk)						\
+			memcpy(name, disk->disk_name, DISK_NAME_LEN);	\
+		else							\
+			memset(name, 0, DISK_NAME_LEN);			\
+	} while (0)

This one at least doesn't rely on assigning to arguments, but an inline function would still be much nicer.