On 2016-12-13 12:22, Steven Rostedt wrote:
On Tue, 13 Dec 2016 11:52:16 -0800
Subhash Jadavani <subha...@codeaurora.org> wrote:

From: Lee Susman <lsus...@codeaurora.org>

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 <lsus...@codeaurora.org>
Signed-off-by: Subhash Jadavani <subha...@codeaurora.org>
---
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

Reply via email to