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(-)
--
2.14.3
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 <[email protected]>
---
drivers/nvme/host/trace.h | 17 +++++++++++------
1 file changed, 11 insertions(+), 6 deletions(-)
diff --git a/drivers/nvme/host/trace.h b/drivers/nvme/host/trace.h
index 67ca8d8e78e1..8058f1c9a33e 100644
--- a/drivers/nvme/host/trace.h
+++ b/drivers/nvme/host/trace.h
@@ -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)
);
--
2.14.3
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 <[email protected]>
Signed-off-by: Sagi Grimberg <[email protected]>
---
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(+)
diff --git a/drivers/nvme/host/fc.c b/drivers/nvme/host/fc.c
index 41d45a1b5c62..9cc33752539a 100644
--- a/drivers/nvme/host/fc.c
+++ b/drivers/nvme/host/fc.c
@@ -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++);
}
diff --git a/drivers/nvme/host/nvme.h b/drivers/nvme/host/nvme.h
index 0c4a33df3b2f..f2249387b60d 100644
--- a/drivers/nvme/host/nvme.h
+++ b/drivers/nvme/host/nvme.h
@@ -102,6 +102,7 @@ struct nvme_request {
u8 retries;
u8 flags;
u16 status;
+ struct nvme_ctrl *ctrl;
};
/*
diff --git a/drivers/nvme/host/pci.c b/drivers/nvme/host/pci.c
index ba943f211687..8dcae11bbf3a 100644
--- a/drivers/nvme/host/pci.c
+++ b/drivers/nvme/host/pci.c
@@ -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;
}
diff --git a/drivers/nvme/host/rdma.c b/drivers/nvme/host/rdma.c
index 9544625c0b7d..ade55977d432 100644
--- a/drivers/nvme/host/rdma.c
+++ b/drivers/nvme/host/rdma.c
@@ -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)
diff --git a/drivers/nvme/target/loop.c b/drivers/nvme/target/loop.c
index d8d91f04bd7e..af7fbf4132b0 100644
--- a/drivers/nvme/target/loop.c
+++ b/drivers/nvme/target/loop.c
@@ -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);
}
--
2.14.3
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 <[email protected]>
---
drivers/nvme/host/core.c | 5 +-
drivers/nvme/host/trace.h | 113 +++++++++++++++++++++-------------------------
2 files changed, 53 insertions(+), 65 deletions(-)
diff --git a/drivers/nvme/host/core.c b/drivers/nvme/host/core.c
index 46df030b2c3f..90eb7c55415b 100644
--- a/drivers/nvme/host/core.c
+++ b/drivers/nvme/host/core.c
@@ -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);
diff --git a/drivers/nvme/host/trace.h b/drivers/nvme/host/trace.h
index 01390f0e1671..67ca8d8e78e1 100644
--- a/drivers/nvme/host/trace.h
+++ b/drivers/nvme/host/trace.h
@@ -24,6 +24,15 @@
#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)
+
#define nvme_admin_opcode_name(opcode) { opcode, #opcode }
#define show_admin_opcode_name(val) \
__print_symbolic(val, \
@@ -52,11 +61,11 @@
const char *nvme_trace_parse_admin_cmd(struct trace_seq *p, u8 opcode,
u8 *cdw10);
-#define __parse_nvme_admin_cmd(opcode, cdw10) \
+#define __parse_admin_cmd(opcode, cdw10) \
nvme_trace_parse_admin_cmd(p, opcode, cdw10)
#define nvme_opcode_name(opcode) { opcode, #opcode }
-#define show_opcode_name(val) \
+#define show_nvm_opcode_name(val) \
__print_symbolic(val, \
nvme_opcode_name(nvme_cmd_flush), \
nvme_opcode_name(nvme_cmd_write), \
@@ -70,83 +79,65 @@ const char *nvme_trace_parse_admin_cmd(struct trace_seq *p, u8 opcode,
nvme_opcode_name(nvme_cmd_resv_acquire), \
nvme_opcode_name(nvme_cmd_resv_release))
+#define show_opcode_name(qid, opcode) \
+ (qid ? show_nvm_opcode_name(opcode) : show_admin_opcode_name(opcode))
+
const char *nvme_trace_parse_nvm_cmd(struct trace_seq *p, u8 opcode,
u8 *cdw10);
-#define __parse_nvme_cmd(opcode, cdw10) \
+#define __parse_nvm_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(u64, metadata)
- __array(u8, cdw10, 24)
- ),
- TP_fast_assign(
- __entry->opcode = cmd->common.opcode;
- __entry->flags = cmd->common.flags;
- __entry->cid = cmd->common.command_id;
- __entry->metadata = le64_to_cpu(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, __entry->metadata,
- show_admin_opcode_name(__entry->opcode),
- __parse_nvme_admin_cmd(__entry->opcode, __entry->cdw10))
-);
-
+#define parse_nvme_cmd(qid, opcode, cdw10) \
+ (qid ? __parse_nvm_cmd(opcode, cdw10) : \
+ __parse_admin_cmd(opcode, cdw10))
-TRACE_EVENT(nvme_setup_nvm_cmd,
- TP_PROTO(int qid, struct nvme_command *cmd),
- TP_ARGS(qid, cmd),
+TRACE_EVENT(nvme_setup_cmd,
+ TP_PROTO(struct request *req, struct nvme_command *cmd),
+ TP_ARGS(req, cmd),
TP_STRUCT__entry(
- __field(int, qid)
- __field(u8, opcode)
- __field(u8, flags)
- __field(u16, cid)
- __field(u32, nsid)
- __field(u64, metadata)
- __array(u8, cdw10, 24)
+ __field(int, qid)
+ __field(u8, opcode)
+ __field(u8, flags)
+ __field(u16, cid)
+ __field(u32, nsid)
+ __field(u64, metadata)
+ __array(u8, cdw10, 24)
),
TP_fast_assign(
- __entry->qid = qid;
- __entry->opcode = cmd->common.opcode;
- __entry->flags = cmd->common.flags;
- __entry->cid = cmd->common.command_id;
- __entry->nsid = le32_to_cpu(cmd->common.nsid);
- __entry->metadata = le64_to_cpu(cmd->common.metadata);
- memcpy(__entry->cdw10, cmd->common.cdw10,
- sizeof(__entry->cdw10));
+ __assign_nvme_qid(req, __entry->qid);
+ __entry->opcode = cmd->common.opcode;
+ __entry->flags = cmd->common.flags;
+ __entry->cid = cmd->common.command_id;
+ __entry->nsid = le32_to_cpu(cmd->common.nsid);
+ __entry->metadata = le64_to_cpu(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, __entry->nsid, __entry->cid,
+ 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,
- show_opcode_name(__entry->opcode),
- __parse_nvme_cmd(__entry->opcode, __entry->cdw10))
+ show_opcode_name(__entry->qid, __entry->opcode),
+ parse_nvme_cmd(__entry->qid, __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(u64, result)
- __field(u8, retries)
- __field(u8, flags)
- __field(u16, status)
+ __field(int, qid)
+ __field(int, cid)
+ __field(u64, result)
+ __field(u8, retries)
+ __field(u8, flags)
+ __field(u16, status)
),
TP_fast_assign(
- __entry->qid = req->q->id;
- __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;
+ __assign_nvme_qid(req, __entry->qid);
+ __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,
--
2.14.3
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 <[email protected]>
---
drivers/nvme/host/trace.c | 11 +++++++++++
drivers/nvme/host/trace.h | 31 ++++++++++++++++++++++++-------
2 files changed, 35 insertions(+), 7 deletions(-)
diff --git a/drivers/nvme/host/trace.c b/drivers/nvme/host/trace.c
index 41944bbef835..25b0e310f4a8 100644
--- a/drivers/nvme/host/trace.c
+++ b/drivers/nvme/host/trace.c
@@ -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;
+}
diff --git a/drivers/nvme/host/trace.h b/drivers/nvme/host/trace.h
index 8058f1c9a33e..84d12224ea4f 100644
--- a/drivers/nvme/host/trace.h
+++ b/drivers/nvme/host/trace.h
@@ -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)
);
--
2.14.3
On Fri, Jun 29, 2018 at 01:59:58PM -0600, Keith Busch wrote:
> + 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.