Skip to contentSkip to conversation

nvme trace updates

PATCH Superseded Keith Busch 2 participants 6 messages Jun 29, 2018

Subsystems (3)
NVMe NVMe target NVMe FC transport

v3 of 4 Superseded Latest is v4 →

lore
Share & tools
lore

Keith Busch

author
#0 lore raw

v3 cover nvme trace updates

This patch series is based on/inspired by 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 are adding and simplifying the nvme traces so we can see information to uniquely identify what hardware the trace event is showing, and filter events for specific hardware.

v2 -> v3:

Removed unrelated code that leaked into the previous series

Added helpers for setting the qid and disk name fields

Simplified printing the disk name: it's already null terminated, so don't need to define the limit.

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  | 137 +++++++++++++++++++++++++--------------------
 drivers/nvme/target/loop.c |   1 +
 8 files changed, 93 insertions(+), 66 deletions(-)
Signature · 1 line
2.14.3
author
#1 lore raw

PATCH v3 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 v3 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 the trace code formatting.

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

Re: [PATCHv3 2/4] nvme: use hw qid in trace events

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

Quoted 2 lines · Keith Busch
drivers/nvme/host/trace.h +2 -0
+	    TP_printk("qid=%d, cmdid=%u, nsid=%u, flags=0x%x, meta=0x%llx, cmd=(%s %s)",
+		      __entry->qid, __entry->nsid, __entry->cid,

Ugh, the nsid and cid are swapped here, and carried through to the end of the series. Will need to send a v4.

author
#4 lore raw

PATCH v3 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 67ca8d8e78e1..8058f1c9a33e 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->nsid, __entry->cid, 
-		      __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->nsid,
+		      __entry->cid, __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
author
#5 lore raw

PATCH v3 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 8058f1c9a33e..84d12224ea4f 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->nsid,
-		      __entry->cid, __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->nsid, __entry->cid,
+		      __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