From: Lee Susman <[email protected]>
Use the ftrace infrastructure to conditionally trace ufs command events.
New trace event is created, which samples the following ufs command data:
- device name
- optional identification string
- task tag
- doorbell register
- number of transfer bytes
- interrupt status register
- request start LBA
- command opcode
Currently we only fully trace read(10) and write(10) commands.
All other commands which pass through ufshcd_send_command() will be
printed with "-1" in the lba and transfer_len fields.
Usage:
echo 1 > /sys/kernel/debug/tracing/events/ufs/enable
cat /sys/kernel/debug/tracing/trace_pipe
Signed-off-by: Lee Susman <[email protected]>
Signed-off-by: Subhash Jadavani <[email protected]>
---
drivers/scsi/ufs/ufshcd.c | 52 +++++++++++++++++++++++++++++++++++++++++++++-
include/trace/events/ufs.h | 38 +++++++++++++++++++++++++++++++++
2 files changed, 89 insertions(+), 1 deletion(-)
diff --git a/drivers/scsi/ufs/ufshcd.c b/drivers/scsi/ufs/ufshcd.c
index 33f3947..926d1ef 100644
--- a/drivers/scsi/ufs/ufshcd.c
+++ b/drivers/scsi/ufs/ufshcd.c
@@ -301,6 +301,51 @@ static inline void ufshcd_remove_non_printable(char *val)
*val = ' ';
}
+#ifdef CONFIG_TRACEPOINTS
+static void ufshcd_add_command_trace(struct ufs_hba *hba,
+ unsigned int tag, const char *str)
+{
+ sector_t lba = -1;
+ u8 opcode = 0;
+ u32 intr, doorbell;
+ struct ufshcd_lrb *lrbp;
+ int transfer_len = -1;
+
+ lrbp = &hba->lrb[tag];
+
+ if (lrbp->cmd) { /* data phase exists */
+ opcode = (u8)(*lrbp->cmd->cmnd);
+ if ((opcode == READ_10) || (opcode == WRITE_10)) {
+ /*
+ * Currently we only fully trace read(10) and write(10)
+ * commands
+ */
+ if (lrbp->cmd->request && lrbp->cmd->request->bio)
+ lba =
+ lrbp->cmd->request->bio->bi_iter.bi_sector;
+ transfer_len = be32_to_cpu(
+ lrbp->ucd_req_ptr->sc.exp_data_transfer_len);
+ }
+ }
+
+ intr = ufshcd_readl(hba, REG_INTERRUPT_STATUS);
+ doorbell = ufshcd_readl(hba, REG_UTP_TRANSFER_REQ_DOOR_BELL);
+ trace_ufshcd_command(dev_name(hba->dev), str, tag,
+ doorbell, transfer_len, intr, lba, opcode);
+}
+
+static inline void ufshcd_cond_add_cmd_trace(struct ufs_hba *hba,
+ unsigned int tag, const char *str)
+{
+ ufshcd_add_command_trace(hba, tag, str);
+}
+#else
+static inline void ufshcd_cond_add_cmd_trace(struct ufs_hba *hba,
+ unsigned int tag, const char *str)
+{
+}
+#endif
+
static void ufshcd_print_host_regs(struct ufs_hba *hba)
{
/*
@@ -1193,6 +1238,7 @@ void ufshcd_send_command(struct ufs_hba *hba, unsigned int task_tag)
ufshcd_writel(hba, 1 << task_tag, REG_UTP_TRANSFER_REQ_DOOR_BELL);
/* Make sure that doorbell is committed immediately */
wmb();
+ ufshcd_cond_add_cmd_trace(hba, task_tag, "send");
}
/**
@@ -3982,6 +4028,7 @@ static void __ufshcd_transfer_req_compl(struct ufs_hba *hba,
lrbp = &hba->lrb[index];
cmd = lrbp->cmd;
if (cmd) {
+ ufshcd_cond_add_cmd_trace(hba, index, "complete");
result = ufshcd_transfer_rsp_status(hba, lrbp);
scsi_dma_unmap(cmd);
cmd->result = result;
@@ -3993,8 +4040,11 @@ static void __ufshcd_transfer_req_compl(struct ufs_hba *hba,
__ufshcd_release(hba);
} else if (lrbp->command_type == UTP_CMD_TYPE_DEV_MANAGE ||
lrbp->command_type == UTP_CMD_TYPE_UFS_STORAGE) {
- if (hba->dev_cmd.complete)
+ if (hba->dev_cmd.complete) {
+ ufshcd_cond_add_cmd_trace(hba, index,
+ "dev_complete");
complete(hba->dev_cmd.complete);
+ }
}
}
diff --git a/include/trace/events/ufs.h b/include/trace/events/ufs.h
index 8bce504..d0ed0cf 100644
--- a/include/trace/events/ufs.h
+++ b/include/trace/events/ufs.h
@@ -183,6 +183,44 @@
TP_PROTO(const char *dev_name, int err, s64 usecs,
const char *dev_state, const char *link_state),
TP_ARGS(dev_name, err, usecs, dev_state, link_state));
+
+TRACE_EVENT(ufshcd_command,
+ TP_PROTO(const char *dev_name, const char *str, unsigned int tag,
+ u32 doorbell, int transfer_len, u32 intr, u64 lba,
+ u8 opcode),
+
+ TP_ARGS(dev_name, str, tag, doorbell, transfer_len, intr, lba, opcode),
+
+ TP_STRUCT__entry(
+ __string(dev_name, dev_name)
+ __string(str, str)
+ __field(unsigned int, tag)
+ __field(u32, doorbell)
+ __field(int, transfer_len)
+ __field(u32, intr)
+ __field(u64, lba)
+ __field(u8, opcode)
+ ),
+
+ TP_fast_assign(
+ __assign_str(dev_name, dev_name);
+ __assign_str(str, str);
+ __entry->tag = tag;
+ __entry->doorbell = doorbell;
+ __entry->transfer_len = transfer_len;
+ __entry->intr = intr;
+ __entry->lba = lba;
+ __entry->opcode = opcode;
+ ),
+
+ TP_printk(
+ "%s: %s: tag: %u, DB: 0x%x, size: %d, IS: %u, LBA: %llu, opcode: 0x%x",
+ __get_str(str), __get_str(dev_name), __entry->tag,
+ __entry->doorbell, __entry->transfer_len,
+ __entry->intr, __entry->lba, (u32)__entry->opcode
+ )
+);
+
#endif /* if !defined(_TRACE_UFS_H) || defined(TRACE_HEADER_MULTI_READ) */
/* This part must be outside protection */
--
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum,
a Linux Foundation Collaborative Project
On Tue, 13 Dec 2016 11:52:16 -0800
Subhash Jadavani <[email protected]> wrote:
> From: Lee Susman <[email protected]>
>
> Use the ftrace infrastructure to conditionally trace ufs command events.
> New trace event is created, which samples the following ufs command data:
> - device name
> - optional identification string
> - task tag
> - doorbell register
> - number of transfer bytes
> - interrupt status register
> - request start LBA
> - command opcode
>
> Currently we only fully trace read(10) and write(10) commands.
> All other commands which pass through ufshcd_send_command() will be
> printed with "-1" in the lba and transfer_len fields.
>
> Usage:
> echo 1 > /sys/kernel/debug/tracing/events/ufs/enable
> cat /sys/kernel/debug/tracing/trace_pipe
>
> Signed-off-by: Lee Susman <[email protected]>
> Signed-off-by: Subhash Jadavani <[email protected]>
> ---
> drivers/scsi/ufs/ufshcd.c | 52 +++++++++++++++++++++++++++++++++++++++++++++-
> include/trace/events/ufs.h | 38 +++++++++++++++++++++++++++++++++
> 2 files changed, 89 insertions(+), 1 deletion(-)
>
> diff --git a/drivers/scsi/ufs/ufshcd.c b/drivers/scsi/ufs/ufshcd.c
> index 33f3947..926d1ef 100644
> --- a/drivers/scsi/ufs/ufshcd.c
> +++ b/drivers/scsi/ufs/ufshcd.c
> @@ -301,6 +301,51 @@ static inline void ufshcd_remove_non_printable(char *val)
> *val = ' ';
> }
>
> +#ifdef CONFIG_TRACEPOINTS
> +static void ufshcd_add_command_trace(struct ufs_hba *hba,
> + unsigned int tag, const char *str)
Is this function only to use if you enable the tracepoint? Is there
anything here doing something that wouldn't be enabled if tracing
wasn't configured in?
Also, if this is in a code execution path, it appears that you do this
work regardless if the tracer is running or not.
> +{
> + sector_t lba = -1;
> + u8 opcode = 0;
> + u32 intr, doorbell;
> + struct ufshcd_lrb *lrbp;
> + int transfer_len = -1;
> +
> + lrbp = &hba->lrb[tag];
> +
> + if (lrbp->cmd) { /* data phase exists */
> + opcode = (u8)(*lrbp->cmd->cmnd);
> + if ((opcode == READ_10) || (opcode == WRITE_10)) {
> + /*
> + * Currently we only fully trace read(10) and write(10)
> + * commands
> + */
> + if (lrbp->cmd->request && lrbp->cmd->request->bio)
> + lba =
> + lrbp->cmd->request->bio->bi_iter.bi_sector;
> + transfer_len = be32_to_cpu(
> + lrbp->ucd_req_ptr->sc.exp_data_transfer_len);
> + }
> + }
> +
> + intr = ufshcd_readl(hba, REG_INTERRUPT_STATUS);
> + doorbell = ufshcd_readl(hba, REG_UTP_TRANSFER_REQ_DOOR_BELL);
> + trace_ufshcd_command(dev_name(hba->dev), str, tag,
> + doorbell, transfer_len, intr, lba, opcode);
> +}
> +
> +static inline void ufshcd_cond_add_cmd_trace(struct ufs_hba *hba,
> + unsigned int tag, const char *str)
> +{
> + ufshcd_add_command_trace(hba, tag, str);
> +}
> +#else
> +static inline void ufshcd_cond_add_cmd_trace(struct ufs_hba *hba,
> + unsigned int tag, const char *str)
> +{
> +}
> +#endif
If my above assumptions are correct, I recommend removing the above
#if, and have it always configured. Then...
> +
> static void ufshcd_print_host_regs(struct ufs_hba *hba)
> {
> /*
> @@ -1193,6 +1238,7 @@ void ufshcd_send_command(struct ufs_hba *hba, unsigned int task_tag)
> ufshcd_writel(hba, 1 << task_tag, REG_UTP_TRANSFER_REQ_DOOR_BELL);
> /* Make sure that doorbell is committed immediately */
> wmb();
Add:
if (trace_ufshcd_command_enabled())
ufshcd_cond_add_cmd_trace(hba, task_tag, "send");
For one thing, the function only gets called if the tracepoint
ufshcd_command is enabled.
Now if CONFIG_TRACEPOINTS is not configured in, then the
trace_ufshcd_command_enabled() turns into a "return false;" which one
would hope that gcc will take that as a if (0) and optimized the entire
function out of existence.
This would make the code a bit cleaner and accomplish the same.
-- Steve
> }
>
> /**
> @@ -3982,6 +4028,7 @@ static void __ufshcd_transfer_req_compl(struct ufs_hba *hba,
> lrbp = &hba->lrb[index];
> cmd = lrbp->cmd;
> if (cmd) {
> + ufshcd_cond_add_cmd_trace(hba, index, "complete");
> result = ufshcd_transfer_rsp_status(hba, lrbp);
> scsi_dma_unmap(cmd);
> cmd->result = result;
> @@ -3993,8 +4040,11 @@ static void __ufshcd_transfer_req_compl(struct ufs_hba *hba,
> __ufshcd_release(hba);
> } else if (lrbp->command_type == UTP_CMD_TYPE_DEV_MANAGE ||
> lrbp->command_type == UTP_CMD_TYPE_UFS_STORAGE) {
> - if (hba->dev_cmd.complete)
> + if (hba->dev_cmd.complete) {
> + ufshcd_cond_add_cmd_trace(hba, index,
> + "dev_complete");
> complete(hba->dev_cmd.complete);
> + }
> }
> }
>
> diff --git a/include/trace/events/ufs.h b/include/trace/events/ufs.h
> index 8bce504..d0ed0cf 100644
> --- a/include/trace/events/ufs.h
> +++ b/include/trace/events/ufs.h
> @@ -183,6 +183,44 @@
> TP_PROTO(const char *dev_name, int err, s64 usecs,
> const char *dev_state, const char *link_state),
> TP_ARGS(dev_name, err, usecs, dev_state, link_state));
> +
> +TRACE_EVENT(ufshcd_command,
> + TP_PROTO(const char *dev_name, const char *str, unsigned int tag,
> + u32 doorbell, int transfer_len, u32 intr, u64 lba,
> + u8 opcode),
> +
> + TP_ARGS(dev_name, str, tag, doorbell, transfer_len, intr, lba, opcode),
> +
> + TP_STRUCT__entry(
> + __string(dev_name, dev_name)
> + __string(str, str)
> + __field(unsigned int, tag)
> + __field(u32, doorbell)
> + __field(int, transfer_len)
> + __field(u32, intr)
> + __field(u64, lba)
> + __field(u8, opcode)
> + ),
> +
> + TP_fast_assign(
> + __assign_str(dev_name, dev_name);
> + __assign_str(str, str);
> + __entry->tag = tag;
> + __entry->doorbell = doorbell;
> + __entry->transfer_len = transfer_len;
> + __entry->intr = intr;
> + __entry->lba = lba;
> + __entry->opcode = opcode;
> + ),
> +
> + TP_printk(
> + "%s: %s: tag: %u, DB: 0x%x, size: %d, IS: %u, LBA: %llu, opcode: 0x%x",
> + __get_str(str), __get_str(dev_name), __entry->tag,
> + __entry->doorbell, __entry->transfer_len,
> + __entry->intr, __entry->lba, (u32)__entry->opcode
> + )
> +);
> +
> #endif /* if !defined(_TRACE_UFS_H) || defined(TRACE_HEADER_MULTI_READ) */
>
> /* This part must be outside protection */
On 2016-12-13 12:22, Steven Rostedt wrote:
> On Tue, 13 Dec 2016 11:52:16 -0800
> Subhash Jadavani <[email protected]> wrote:
>
>> From: Lee Susman <[email protected]>
>>
>> Use the ftrace infrastructure to conditionally trace ufs command
>> events.
>> New trace event is created, which samples the following ufs command
>> data:
>> - device name
>> - optional identification string
>> - task tag
>> - doorbell register
>> - number of transfer bytes
>> - interrupt status register
>> - request start LBA
>> - command opcode
>>
>> Currently we only fully trace read(10) and write(10) commands.
>> All other commands which pass through ufshcd_send_command() will be
>> printed with "-1" in the lba and transfer_len fields.
>>
>> Usage:
>> echo 1 > /sys/kernel/debug/tracing/events/ufs/enable
>> cat /sys/kernel/debug/tracing/trace_pipe
>>
>> Signed-off-by: Lee Susman <[email protected]>
>> Signed-off-by: Subhash Jadavani <[email protected]>
>> ---
>> drivers/scsi/ufs/ufshcd.c | 52
>> +++++++++++++++++++++++++++++++++++++++++++++-
>> include/trace/events/ufs.h | 38 +++++++++++++++++++++++++++++++++
>> 2 files changed, 89 insertions(+), 1 deletion(-)
>>
>> diff --git a/drivers/scsi/ufs/ufshcd.c b/drivers/scsi/ufs/ufshcd.c
>> index 33f3947..926d1ef 100644
>> --- a/drivers/scsi/ufs/ufshcd.c
>> +++ b/drivers/scsi/ufs/ufshcd.c
>> @@ -301,6 +301,51 @@ static inline void
>> ufshcd_remove_non_printable(char *val)
>> *val = ' ';
>> }
>>
>> +#ifdef CONFIG_TRACEPOINTS
>> +static void ufshcd_add_command_trace(struct ufs_hba *hba,
>> + unsigned int tag, const char *str)
>
> Is this function only to use if you enable the tracepoint? Is there
> anything here doing something that wouldn't be enabled if tracing
> wasn't configured in?
>
> Also, if this is in a code execution path, it appears that you do this
> work regardless if the tracer is running or not.
That's true, need to fix this.
>
>> +{
>> + sector_t lba = -1;
>> + u8 opcode = 0;
>> + u32 intr, doorbell;
>> + struct ufshcd_lrb *lrbp;
>> + int transfer_len = -1;
>> +
>> + lrbp = &hba->lrb[tag];
>> +
>> + if (lrbp->cmd) { /* data phase exists */
>> + opcode = (u8)(*lrbp->cmd->cmnd);
>> + if ((opcode == READ_10) || (opcode == WRITE_10)) {
>> + /*
>> + * Currently we only fully trace read(10) and write(10)
>> + * commands
>> + */
>> + if (lrbp->cmd->request && lrbp->cmd->request->bio)
>> + lba =
>> + lrbp->cmd->request->bio->bi_iter.bi_sector;
>> + transfer_len = be32_to_cpu(
>> + lrbp->ucd_req_ptr->sc.exp_data_transfer_len);
>> + }
>> + }
>> +
>> + intr = ufshcd_readl(hba, REG_INTERRUPT_STATUS);
>> + doorbell = ufshcd_readl(hba, REG_UTP_TRANSFER_REQ_DOOR_BELL);
>> + trace_ufshcd_command(dev_name(hba->dev), str, tag,
>> + doorbell, transfer_len, intr, lba, opcode);
>> +}
>> +
>> +static inline void ufshcd_cond_add_cmd_trace(struct ufs_hba *hba,
>> + unsigned int tag, const char *str)
>> +{
>> + ufshcd_add_command_trace(hba, tag, str);
>> +}
>> +#else
>> +static inline void ufshcd_cond_add_cmd_trace(struct ufs_hba *hba,
>> + unsigned int tag, const char *str)
>> +{
>> +}
>> +#endif
>
> If my above assumptions are correct, I recommend removing the above
> #if, and have it always configured. Then...
Agreed.
>
>> +
>> static void ufshcd_print_host_regs(struct ufs_hba *hba)
>> {
>> /*
>> @@ -1193,6 +1238,7 @@ void ufshcd_send_command(struct ufs_hba *hba,
>> unsigned int task_tag)
>> ufshcd_writel(hba, 1 << task_tag, REG_UTP_TRANSFER_REQ_DOOR_BELL);
>> /* Make sure that doorbell is committed immediately */
>> wmb();
>
> Add:
>
> if (trace_ufshcd_command_enabled())
> ufshcd_cond_add_cmd_trace(hba, task_tag, "send");
>
> For one thing, the function only gets called if the tracepoint
> ufshcd_command is enabled.
>
> Now if CONFIG_TRACEPOINTS is not configured in, then the
> trace_ufshcd_command_enabled() turns into a "return false;" which one
> would hope that gcc will take that as a if (0) and optimized the entire
> function out of existence.
>
> This would make the code a bit cleaner and accomplish the same.
Agreed, will try this. Thank you.
>
> -- Steve
>
>
>> }
>>
>> /**
>> @@ -3982,6 +4028,7 @@ static void __ufshcd_transfer_req_compl(struct
>> ufs_hba *hba,
>> lrbp = &hba->lrb[index];
>> cmd = lrbp->cmd;
>> if (cmd) {
>> + ufshcd_cond_add_cmd_trace(hba, index, "complete");
>> result = ufshcd_transfer_rsp_status(hba, lrbp);
>> scsi_dma_unmap(cmd);
>> cmd->result = result;
>> @@ -3993,8 +4040,11 @@ static void __ufshcd_transfer_req_compl(struct
>> ufs_hba *hba,
>> __ufshcd_release(hba);
>> } else if (lrbp->command_type == UTP_CMD_TYPE_DEV_MANAGE ||
>> lrbp->command_type == UTP_CMD_TYPE_UFS_STORAGE) {
>> - if (hba->dev_cmd.complete)
>> + if (hba->dev_cmd.complete) {
>> + ufshcd_cond_add_cmd_trace(hba, index,
>> + "dev_complete");
>> complete(hba->dev_cmd.complete);
>> + }
>> }
>> }
>>
>> diff --git a/include/trace/events/ufs.h b/include/trace/events/ufs.h
>> index 8bce504..d0ed0cf 100644
>> --- a/include/trace/events/ufs.h
>> +++ b/include/trace/events/ufs.h
>> @@ -183,6 +183,44 @@
>> TP_PROTO(const char *dev_name, int err, s64 usecs,
>> const char *dev_state, const char *link_state),
>> TP_ARGS(dev_name, err, usecs, dev_state, link_state));
>> +
>> +TRACE_EVENT(ufshcd_command,
>> + TP_PROTO(const char *dev_name, const char *str, unsigned int tag,
>> + u32 doorbell, int transfer_len, u32 intr, u64 lba,
>> + u8 opcode),
>> +
>> + TP_ARGS(dev_name, str, tag, doorbell, transfer_len, intr, lba,
>> opcode),
>> +
>> + TP_STRUCT__entry(
>> + __string(dev_name, dev_name)
>> + __string(str, str)
>> + __field(unsigned int, tag)
>> + __field(u32, doorbell)
>> + __field(int, transfer_len)
>> + __field(u32, intr)
>> + __field(u64, lba)
>> + __field(u8, opcode)
>> + ),
>> +
>> + TP_fast_assign(
>> + __assign_str(dev_name, dev_name);
>> + __assign_str(str, str);
>> + __entry->tag = tag;
>> + __entry->doorbell = doorbell;
>> + __entry->transfer_len = transfer_len;
>> + __entry->intr = intr;
>> + __entry->lba = lba;
>> + __entry->opcode = opcode;
>> + ),
>> +
>> + TP_printk(
>> + "%s: %s: tag: %u, DB: 0x%x, size: %d, IS: %u, LBA: %llu, opcode:
>> 0x%x",
>> + __get_str(str), __get_str(dev_name), __entry->tag,
>> + __entry->doorbell, __entry->transfer_len,
>> + __entry->intr, __entry->lba, (u32)__entry->opcode
>> + )
>> +);
>> +
>> #endif /* if !defined(_TRACE_UFS_H) ||
>> defined(TRACE_HEADER_MULTI_READ) */
>>
>> /* This part must be outside protection */
--
The Qualcomm Innovation Center, Inc. is a member of Code Aurora Forum,
a Linux Foundation Collaborative Project