From 7ff5ab4736333431311a4cbbfb574b155758b08c Mon Sep 17 00:00:00 2001 From: subhashj@codeaurora.org Date: Thu, 22 Dec 2016 18:39:51 -0800 Subject: scsi: ufs: add tracing support This change adds the ftrace support for following: 1. UFS initialization time 2. Clock gating states 3. Clock scaling states 4. Power management APIs latency 5. BKOPs enable/disable Usage: echo 1 > /sys/kernel/debug/tracing/events/ufs/enable cat /sys/kernel/debug/tracing/trace_pipe Reviewed-by: Sahitya Tummala Signed-off-by: Subhash Jadavani Signed-off-by: Martin K. Petersen --- include/trace/events/ufs.h | 185 +++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 185 insertions(+) create mode 100644 include/trace/events/ufs.h (limited to 'include/trace') diff --git a/include/trace/events/ufs.h b/include/trace/events/ufs.h new file mode 100644 index 000000000000..57743b6ed0b0 --- /dev/null +++ b/include/trace/events/ufs.h @@ -0,0 +1,185 @@ +/* + * Copyright (c) 2013-2014, The Linux Foundation. All rights reserved. + * + * This program is free software; you can redistribute it and/or modify + * it under the terms of the GNU General Public License version 2 and + * only version 2 as published by the Free Software Foundation. + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + */ + +#undef TRACE_SYSTEM +#define TRACE_SYSTEM ufs + +#if !defined(_TRACE_UFS_H) || defined(TRACE_HEADER_MULTI_READ) +#define _TRACE_UFS_H + +#include + +#define UFS_LINK_STATES \ + EM(UIC_LINK_OFF_STATE) \ + EM(UIC_LINK_ACTIVE_STATE) \ + EMe(UIC_LINK_HIBERN8_STATE) + +#define UFS_PWR_MODES \ + EM(UFS_ACTIVE_PWR_MODE) \ + EM(UFS_SLEEP_PWR_MODE) \ + EMe(UFS_POWERDOWN_PWR_MODE) + +#define UFSCHD_CLK_GATING_STATES \ + EM(CLKS_OFF) \ + EM(CLKS_ON) \ + EM(REQ_CLKS_OFF) \ + EMe(REQ_CLKS_ON) + +/* Enums require being exported to userspace, for user tool parsing */ +#undef EM +#undef EMe +#define EM(a) TRACE_DEFINE_ENUM(a); +#define EMe(a) TRACE_DEFINE_ENUM(a); + +UFS_LINK_STATES; +UFS_PWR_MODES; +UFSCHD_CLK_GATING_STATES; + +/* + * Now redefine the EM() and EMe() macros to map the enums to the strings + * that will be printed in the output. + */ +#undef EM +#undef EMe +#define EM(a) { a, #a }, +#define EMe(a) { a, #a } + +TRACE_EVENT(ufshcd_clk_gating, + + TP_PROTO(const char *dev_name, int state), + + TP_ARGS(dev_name, state), + + TP_STRUCT__entry( + __string(dev_name, dev_name) + __field(int, state) + ), + + TP_fast_assign( + __assign_str(dev_name, dev_name); + __entry->state = state; + ), + + TP_printk("%s: gating state changed to %s", + __get_str(dev_name), + __print_symbolic(__entry->state, UFSCHD_CLK_GATING_STATES)) +); + +TRACE_EVENT(ufshcd_clk_scaling, + + TP_PROTO(const char *dev_name, const char *state, const char *clk, + u32 prev_state, u32 curr_state), + + TP_ARGS(dev_name, state, clk, prev_state, curr_state), + + TP_STRUCT__entry( + __string(dev_name, dev_name) + __string(state, state) + __string(clk, clk) + __field(u32, prev_state) + __field(u32, curr_state) + ), + + TP_fast_assign( + __assign_str(dev_name, dev_name); + __assign_str(state, state); + __assign_str(clk, clk); + __entry->prev_state = prev_state; + __entry->curr_state = curr_state; + ), + + TP_printk("%s: %s %s from %u to %u Hz", + __get_str(dev_name), __get_str(state), __get_str(clk), + __entry->prev_state, __entry->curr_state) +); + +TRACE_EVENT(ufshcd_auto_bkops_state, + + TP_PROTO(const char *dev_name, const char *state), + + TP_ARGS(dev_name, state), + + TP_STRUCT__entry( + __string(dev_name, dev_name) + __string(state, state) + ), + + TP_fast_assign( + __assign_str(dev_name, dev_name); + __assign_str(state, state); + ), + + TP_printk("%s: auto bkops - %s", + __get_str(dev_name), __get_str(state)) +); + +DECLARE_EVENT_CLASS(ufshcd_template, + TP_PROTO(const char *dev_name, int err, s64 usecs, + int dev_state, int link_state), + + TP_ARGS(dev_name, err, usecs, dev_state, link_state), + + TP_STRUCT__entry( + __field(s64, usecs) + __field(int, err) + __string(dev_name, dev_name) + __field(int, dev_state) + __field(int, link_state) + ), + + TP_fast_assign( + __entry->usecs = usecs; + __entry->err = err; + __assign_str(dev_name, dev_name); + __entry->dev_state = dev_state; + __entry->link_state = link_state; + ), + + TP_printk( + "%s: took %lld usecs, dev_state: %s, link_state: %s, err %d", + __get_str(dev_name), + __entry->usecs, + __print_symbolic(__entry->dev_state, UFS_PWR_MODES), + __print_symbolic(__entry->link_state, UFS_LINK_STATES), + __entry->err + ) +); + +DEFINE_EVENT(ufshcd_template, ufshcd_system_suspend, + TP_PROTO(const char *dev_name, int err, s64 usecs, + int dev_state, int link_state), + TP_ARGS(dev_name, err, usecs, dev_state, link_state)); + +DEFINE_EVENT(ufshcd_template, ufshcd_system_resume, + TP_PROTO(const char *dev_name, int err, s64 usecs, + int dev_state, int link_state), + TP_ARGS(dev_name, err, usecs, dev_state, link_state)); + +DEFINE_EVENT(ufshcd_template, ufshcd_runtime_suspend, + TP_PROTO(const char *dev_name, int err, s64 usecs, + int dev_state, int link_state), + TP_ARGS(dev_name, err, usecs, dev_state, link_state)); + +DEFINE_EVENT(ufshcd_template, ufshcd_runtime_resume, + TP_PROTO(const char *dev_name, int err, s64 usecs, + int dev_state, int link_state), + TP_ARGS(dev_name, err, usecs, dev_state, link_state)); + +DEFINE_EVENT(ufshcd_template, ufshcd_init, + TP_PROTO(const char *dev_name, int err, s64 usecs, + int dev_state, int link_state), + TP_ARGS(dev_name, err, usecs, dev_state, link_state)); +#endif /* if !defined(_TRACE_UFS_H) || defined(TRACE_HEADER_MULTI_READ) */ + +/* This part must be outside protection */ +#include -- cgit v1.2.3 From 911a0771b6fa7bac5eae753c17c87ecb77c77283 Mon Sep 17 00:00:00 2001 From: subhashj@codeaurora.org Date: Thu, 22 Dec 2016 18:41:48 -0800 Subject: scsi: ufs: add time profiling support This patch adds the profiling support for some of the time critical operations like hibern8 enter/exit, clock gating & clock scaling. Reviewed-by: Venkat Gopalakrishnan Signed-off-by: Subhash Jadavani Signed-off-by: Martin K. Petersen --- drivers/scsi/ufs/ufshcd.c | 24 ++++++++++++++++++++++++ include/trace/events/ufs.h | 40 ++++++++++++++++++++++++++++++++++++++++ 2 files changed, 64 insertions(+) (limited to 'include/trace') diff --git a/drivers/scsi/ufs/ufshcd.c b/drivers/scsi/ufs/ufshcd.c index 184106fa21da..58c4df405528 100644 --- a/drivers/scsi/ufs/ufshcd.c +++ b/drivers/scsi/ufs/ufshcd.c @@ -3021,11 +3021,14 @@ static int __ufshcd_uic_hibern8_enter(struct ufs_hba *hba) { int ret; struct uic_command uic_cmd = {0}; + ktime_t start = ktime_get(); ufshcd_vops_hibern8_notify(hba, UIC_CMD_DME_HIBER_ENTER, PRE_CHANGE); uic_cmd.command = UIC_CMD_DME_HIBER_ENTER; ret = ufshcd_uic_pwr_ctrl(hba, &uic_cmd); + trace_ufshcd_profile_hibern8(dev_name(hba->dev), "enter", + ktime_to_us(ktime_sub(ktime_get(), start)), ret); if (ret) { dev_err(hba->dev, "%s: hibern8 enter failed. ret = %d\n", @@ -3061,11 +3064,15 @@ static int ufshcd_uic_hibern8_exit(struct ufs_hba *hba) { struct uic_command uic_cmd = {0}; int ret; + ktime_t start = ktime_get(); ufshcd_vops_hibern8_notify(hba, UIC_CMD_DME_HIBER_EXIT, PRE_CHANGE); uic_cmd.command = UIC_CMD_DME_HIBER_EXIT; ret = ufshcd_uic_pwr_ctrl(hba, &uic_cmd); + trace_ufshcd_profile_hibern8(dev_name(hba->dev), "exit", + ktime_to_us(ktime_sub(ktime_get(), start)), ret); + if (ret) { dev_err(hba->dev, "%s: hibern8 exit failed. ret = %d\n", __func__, ret); @@ -5950,6 +5957,8 @@ static int __ufshcd_setup_clocks(struct ufs_hba *hba, bool on, struct ufs_clk_info *clki; struct list_head *head = &hba->clk_list_head; unsigned long flags; + ktime_t start = ktime_get(); + bool clk_state_changed = false; if (!head || list_empty(head)) goto out; @@ -5963,6 +5972,7 @@ static int __ufshcd_setup_clocks(struct ufs_hba *hba, bool on, if (skip_ref_clk && !strcmp(clki->name, "ref_clk")) continue; + clk_state_changed = on ^ clki->enabled; if (on && !clki->enabled) { ret = clk_prepare_enable(clki->clk); if (ret) { @@ -5997,6 +6007,10 @@ out: spin_unlock_irqrestore(hba->host->host_lock, flags); } + if (clk_state_changed) + trace_ufshcd_profile_clk_gating(dev_name(hba->dev), + (on ? "on" : "off"), + ktime_to_us(ktime_sub(ktime_get(), start)), ret); return ret; } @@ -6996,6 +7010,8 @@ static int ufshcd_scale_clks(struct ufs_hba *hba, bool scale_up) int ret = 0; struct ufs_clk_info *clki; struct list_head *head = &hba->clk_list_head; + ktime_t start = ktime_get(); + bool clk_state_changed = false; if (!head || list_empty(head)) goto out; @@ -7009,6 +7025,8 @@ static int ufshcd_scale_clks(struct ufs_hba *hba, bool scale_up) if (scale_up && clki->max_freq) { if (clki->curr_freq == clki->max_freq) continue; + + clk_state_changed = true; ret = clk_set_rate(clki->clk, clki->max_freq); if (ret) { dev_err(hba->dev, "%s: %s clk set rate(%dHz) failed, %d\n", @@ -7026,6 +7044,8 @@ static int ufshcd_scale_clks(struct ufs_hba *hba, bool scale_up) } else if (!scale_up && clki->min_freq) { if (clki->curr_freq == clki->min_freq) continue; + + clk_state_changed = true; ret = clk_set_rate(clki->clk, clki->min_freq); if (ret) { dev_err(hba->dev, "%s: %s clk set rate(%dHz) failed, %d\n", @@ -7047,6 +7067,10 @@ static int ufshcd_scale_clks(struct ufs_hba *hba, bool scale_up) ret = ufshcd_vops_clk_scale_notify(hba, scale_up, POST_CHANGE); out: + if (clk_state_changed) + trace_ufshcd_profile_clk_scaling(dev_name(hba->dev), + (scale_up ? "up" : "down"), + ktime_to_us(ktime_sub(ktime_get(), start)), ret); return ret; } diff --git a/include/trace/events/ufs.h b/include/trace/events/ufs.h index 57743b6ed0b0..e9634dff51a8 100644 --- a/include/trace/events/ufs.h +++ b/include/trace/events/ufs.h @@ -123,6 +123,46 @@ TRACE_EVENT(ufshcd_auto_bkops_state, __get_str(dev_name), __get_str(state)) ); +DECLARE_EVENT_CLASS(ufshcd_profiling_template, + TP_PROTO(const char *dev_name, const char *profile_info, s64 time_us, + int err), + + TP_ARGS(dev_name, profile_info, time_us, err), + + TP_STRUCT__entry( + __string(dev_name, dev_name) + __string(profile_info, profile_info) + __field(s64, time_us) + __field(int, err) + ), + + TP_fast_assign( + __assign_str(dev_name, dev_name); + __assign_str(profile_info, profile_info); + __entry->time_us = time_us; + __entry->err = err; + ), + + TP_printk("%s: %s: took %lld usecs, err %d", + __get_str(dev_name), __get_str(profile_info), + __entry->time_us, __entry->err) +); + +DEFINE_EVENT(ufshcd_profiling_template, ufshcd_profile_hibern8, + TP_PROTO(const char *dev_name, const char *profile_info, s64 time_us, + int err), + TP_ARGS(dev_name, profile_info, time_us, err)); + +DEFINE_EVENT(ufshcd_profiling_template, ufshcd_profile_clk_gating, + TP_PROTO(const char *dev_name, const char *profile_info, s64 time_us, + int err), + TP_ARGS(dev_name, profile_info, time_us, err)); + +DEFINE_EVENT(ufshcd_profiling_template, ufshcd_profile_clk_scaling, + TP_PROTO(const char *dev_name, const char *profile_info, s64 time_us, + int err), + TP_ARGS(dev_name, profile_info, time_us, err)); + DECLARE_EVENT_CLASS(ufshcd_template, TP_PROTO(const char *dev_name, int err, s64 usecs, int dev_state, int link_state), -- cgit v1.2.3 From 1a07f2d96eb9085396cbfb2d6d42d4003aa2934a Mon Sep 17 00:00:00 2001 From: Lee Susman Date: Thu, 22 Dec 2016 18:42:03 -0800 Subject: scsi: ufs: add trace event for ufs commands 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 Signed-off-by: Subhash Jadavani Signed-off-by: Martin K. Petersen --- drivers/scsi/ufs/ufshcd.c | 42 +++++++++++++++++++++++++++++++++++++++++- include/trace/events/ufs.h | 38 ++++++++++++++++++++++++++++++++++++++ 2 files changed, 79 insertions(+), 1 deletion(-) (limited to 'include/trace') diff --git a/drivers/scsi/ufs/ufshcd.c b/drivers/scsi/ufs/ufshcd.c index 58c4df405528..2c88757eb701 100644 --- a/drivers/scsi/ufs/ufshcd.c +++ b/drivers/scsi/ufs/ufshcd.c @@ -293,6 +293,41 @@ static inline void ufshcd_remove_non_printable(char *val) *val = ' '; } +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; + + if (!trace_ufshcd_command_enabled()) + return; + + 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 void ufshcd_print_host_regs(struct ufs_hba *hba) { /* @@ -1166,6 +1201,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_add_command_trace(hba, task_tag, "send"); } /** @@ -3955,6 +3991,7 @@ static void __ufshcd_transfer_req_compl(struct ufs_hba *hba, lrbp = &hba->lrb[index]; cmd = lrbp->cmd; if (cmd) { + ufshcd_add_command_trace(hba, index, "complete"); result = ufshcd_transfer_rsp_status(hba, lrbp); scsi_dma_unmap(cmd); cmd->result = result; @@ -3966,8 +4003,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_add_command_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 e9634dff51a8..bf6f82673492 100644 --- a/include/trace/events/ufs.h +++ b/include/trace/events/ufs.h @@ -219,6 +219,44 @@ DEFINE_EVENT(ufshcd_template, ufshcd_init, TP_PROTO(const char *dev_name, int err, s64 usecs, int dev_state, int 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 */ -- cgit v1.2.3