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

From: Hannes Reinecke
Date: Tue Jan 16 2018 - 06:27:42 EST

On 01/16/2018 11:34 AM, Johannes Thumshirn wrote:
> Signed-off-by: Johannes Thumshirn <jthumshirn@xxxxxxx>
> ---
> drivers/nvme/host/core.c | 69 +++++++++++++++++++++++++++++++++++++++++++++
> include/trace/events/nvme.h | 64 +++++++++++++++++++++++++++++++++++++++++
> 2 files changed, 133 insertions(+)
> create mode 100644 include/trace/events/nvme.h
>
> diff --git a/drivers/nvme/host/core.c b/drivers/nvme/host/core.c
> index 839650e0926a..4b6a56fe6ccf 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/events/nvme.h>
> +
> #include "nvme.h"
> #include "fabrics.h"
>
> @@ -80,6 +83,71 @@ static struct class *nvme_subsys_class;
> static void nvme_ns_remove(struct nvme_ns *ns);
> static int nvme_revalidate_disk(struct gendisk *disk);
>
> +static const char *nvme_trace_read_write(struct trace_seq *p,
> + struct nvme_rw_command rw)
> +{
> + const char *ret = trace_seq_buffer_ptr(p);
> +
> + trace_seq_printf(p, "slba=%llu, length=%u, control=0x%x, dsmgmt=%u, reftag=%u",
> + (unsigned long long)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, struct nvme_dsm_cmd dsm)
> +{
> + const char *ret = trace_seq_buffer_ptr(p);
> +
> + 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_write_zeroes(struct trace_seq *p,
> + struct nvme_write_zeroes_cmd wz)
> +{
> + const char *ret = trace_seq_buffer_ptr(p);
> +
> + trace_seq_printf(p, "slba=%llu, length=%u, control=%u, dsmgmt=%u, reftag=%u",
> + (unsigned long long) le64_to_cpu(wz.slba),
> + le16_to_cpu(wz.length), le16_to_cpu(wz.control),
> + le32_to_cpu(wz.dsmgmt), le32_to_cpu(wz.reftag));
> + trace_seq_putc(p, 0);
> +
> + return ret;
> +}
> +
> +static const char *nvme_trace_common(struct trace_seq *p,
> + struct nvme_common_command c)
> +{
> + const char *ret = trace_seq_buffer_ptr(p);
> +
> + trace_seq_printf(p, "cdw2=%*ph, cdw10=%*ph", 4, c.cdw2, 24, c.cdw10);
> + trace_seq_putc(p, 0);
> +
> + return ret;
> +}
> +
> +const char *nvme_trace_parse_cmd(struct trace_seq *p, struct nvme_command cmd)
> +{
> + switch (cmd.common.opcode) {
> + case nvme_cmd_read:
> + case nvme_cmd_write:
> + return nvme_trace_read_write(p, cmd.rw);
> + case nvme_cmd_dsm:
> + return nvme_trace_dsm(p, cmd.dsm);
> + case nvme_cmd_write_zeroes:
> + return nvme_trace_write_zeroes(p, cmd.write_zeroes);
> + default:
> + return nvme_trace_common(p, cmd.common);
> + }
> +}
> +
> static __le32 nvme_get_log_dw10(u8 lid, size_t size)
> {
> return cpu_to_le32((((size / 4) - 1) << 16) | lid);
> @@ -591,6 +659,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);
> return ret;
> }
> EXPORT_SYMBOL_GPL(nvme_setup_cmd);
> diff --git a/include/trace/events/nvme.h b/include/trace/events/nvme.h
> new file mode 100644
> index 000000000000..2e93bc7d4f84
> --- /dev/null
> +++ b/include/trace/events/nvme.h
> @@ -0,0 +1,64 @@
> +/* SPDX-License-Identifier: GPL-2.0 */
> +#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>
> +
> +#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, struct nvme_command cmnd);
> +#define __parse_nvme_cmd(cmd) nvme_trace_parse_cmd(p, cmd)
> +
> +TRACE_EVENT(nvme_setup_cmd,
> +
> + TP_PROTO(struct nvme_command *cmd),
> +
> + TP_ARGS(cmd),
> +
> + TP_STRUCT__entry(
> + __field( __u8, opcode )
> + __field( __u8, flags )
> + __field( __u16, cid )
> + __field( __le32, nsid )
> + __field( __le64, metadata )
> + __field_struct( struct nvme_command, cmnd )
> + ),
> +
> + TP_fast_assign(
> + __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->cmnd, cmd, sizeof(__entry->cmnd));
> + ),
> +
> + TP_printk("nsid=%u, command_id=%u, flags=0x%x, metadata=0x%llx, cmd=(%s %s)",
> + le32_to_cpu(__entry->nsid), __entry->cid, __entry->flags,
> + (unsigned long long) le64_to_cpu(__entry->metadata),
> + show_opcode_name(__entry->opcode),
> + __parse_nvme_cmd(__entry->cmnd))
> +);
> +
> +#endif /* _TRACE_NVME_H */
> +
> +/* This part must be boutside protection */
> +#include <trace/define_trace.h>
>
'boutside proctetion'?

In general I'd rather have the tracepoints when actually submitting the
request; with this tracepoint we might be getting a trace which doesn't
really indicate if the command was submitted at all.

Cheers,

Hannes
--
Dr. Hannes Reinecke Teamlead Storage & Networking
hare@xxxxxxx +49 911 74053 688
SUSE LINUX GmbH, Maxfeldstr. 5, 90409 NÃrnberg
GF: F. ImendÃrffer, J. Smithard, J. Guild, D. Upmanyu, G. Norton
HRB 21284 (AG NÃrnberg)