Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1752416AbbBWJP0 (ORCPT ); Mon, 23 Feb 2015 04:15:26 -0500 Received: from smtp.codeaurora.org ([198.145.29.96]:54022 "EHLO smtp.codeaurora.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1752370AbbBWJPT (ORCPT ); Mon, 23 Feb 2015 04:15:19 -0500 Message-ID: In-Reply-To: <1424678898-3723-4-git-send-email-gbroner@codeaurora.org> References: <1424678898-3723-1-git-send-email-gbroner@codeaurora.org> <1424678898-3723-4-git-send-email-gbroner@codeaurora.org> Date: Mon, 23 Feb 2015 09:15:15 -0000 Subject: Re: [PATCH v3 3/4] scsi: ufs: add trace events and dump prints for debug From: "Dov Levenglick" To: "Gilad Broner" Cc: james.bottomley@hansenpartnership.com, linux-kernel@vger.kernel.org, linux-scsi@vger.kernel.org, linux-arm-msm@vger.kernel.org, santoshsy@gmail.com, linux-scsi-owner@vger.kernel.org, subhashj@codeaurora.org, ygardi@codeaurora.org, draviv@codeaurora.org, "Gilad Broner" , "Lee Susman" , "Sujit Reddy Thumma" , "Vinayak Holikatti" , "James E.J. Bottomley" , "Steven Rostedt" , "Ingo Molnar" User-Agent: SquirrelMail/1.4.22-4.el6 MIME-Version: 1.0 Content-Type: text/plain; charset=US-ASCII Content-Transfer-Encoding: 7BIT X-Priority: 3 (Normal) Importance: Normal Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 48321 Lines: 1543 > Add trace events to driver to allow monitoring and profilig > of activities such as PM suspend/resume, hibernate enter/exit, > clock gating and clock scaling up/down. > In addition, add UFS host controller register dumps to provide > detailed information in case of errors to assist in analysis > of issues. > > Signed-off-by: Dolev Raviv > Signed-off-by: Subhash Jadavani > Signed-off-by: Lee Susman > Signed-off-by: Sujit Reddy Thumma > Signed-off-by: Yaniv Gardi > --- > drivers/scsi/ufs/ufs-qcom.c | 53 +++++ > drivers/scsi/ufs/ufshcd.c | 509 > +++++++++++++++++++++++++++++++++++++++++--- > drivers/scsi/ufs/ufshcd.h | 49 ++++- > drivers/scsi/ufs/ufshci.h | 1 + > include/trace/events/ufs.h | 227 ++++++++++++++++++++ > 5 files changed, 808 insertions(+), 31 deletions(-) > create mode 100644 include/trace/events/ufs.h > > diff --git a/drivers/scsi/ufs/ufs-qcom.c b/drivers/scsi/ufs/ufs-qcom.c > index 9217af9..9fe675d 100644 > --- a/drivers/scsi/ufs/ufs-qcom.c > +++ b/drivers/scsi/ufs/ufs-qcom.c > @@ -30,6 +30,14 @@ static int ufs_qcom_get_bus_vote(struct ufs_qcom_host > *host, > const char *speed_mode); > static int ufs_qcom_set_bus_vote(struct ufs_qcom_host *host, int vote); > > +static void ufs_qcom_dump_regs(struct ufs_hba *hba, int offset, int len, > + char *prefix) > +{ > + print_hex_dump(KERN_ERR, prefix, > + len > 4 ? DUMP_PREFIX_OFFSET : DUMP_PREFIX_NONE, > + 16, 4, hba->mmio_base + offset, len * 4, false); > +} > + > static int ufs_qcom_get_connected_tx_lanes(struct ufs_hba *hba, u32 > *tx_lanes) > { > int err = 0; > @@ -983,6 +991,50 @@ void ufs_qcom_clk_scale_notify(struct ufs_hba *hba) > dev_req_params->hs_rate); > } > > +static void ufs_qcom_print_hw_debug_reg_all(struct ufs_hba *hba) > +{ > + u32 reg; > + > + ufs_qcom_dump_regs(hba, UFS_UFS_DBG_RD_REG_OCSC, 44, > + "UFS_UFS_DBG_RD_REG_OCSC "); > + > + reg = ufshcd_readl(hba, REG_UFS_CFG1); > + reg |= UFS_BIT(17); > + ufshcd_writel(hba, reg, REG_UFS_CFG1); > + > + ufs_qcom_dump_regs(hba, UFS_UFS_DBG_RD_EDTL_RAM, 32, > + "UFS_UFS_DBG_RD_EDTL_RAM "); > + ufs_qcom_dump_regs(hba, UFS_UFS_DBG_RD_DESC_RAM, 128, > + "UFS_UFS_DBG_RD_DESC_RAM "); > + ufs_qcom_dump_regs(hba, UFS_UFS_DBG_RD_PRDT_RAM, 64, > + "UFS_UFS_DBG_RD_PRDT_RAM "); > + > + ufshcd_writel(hba, (reg & ~UFS_BIT(17)), REG_UFS_CFG1); > + > + ufs_qcom_dump_regs(hba, UFS_DBG_RD_REG_UAWM, 4, > + "UFS_DBG_RD_REG_UAWM "); > + ufs_qcom_dump_regs(hba, UFS_DBG_RD_REG_UARM, 4, > + "UFS_DBG_RD_REG_UARM "); > + ufs_qcom_dump_regs(hba, UFS_DBG_RD_REG_TXUC, 48, > + "UFS_DBG_RD_REG_TXUC "); > + ufs_qcom_dump_regs(hba, UFS_DBG_RD_REG_RXUC, 27, > + "UFS_DBG_RD_REG_RXUC "); > + ufs_qcom_dump_regs(hba, UFS_DBG_RD_REG_DFC, 19, > + "UFS_DBG_RD_REG_DFC "); > + ufs_qcom_dump_regs(hba, UFS_DBG_RD_REG_TRLUT, 34, > + "UFS_DBG_RD_REG_TRLUT "); > + ufs_qcom_dump_regs(hba, UFS_DBG_RD_REG_TMRLUT, 9, > + "UFS_DBG_RD_REG_TMRLUT "); > +} > + > +static void ufs_qcom_dump_dbg_regs(struct ufs_hba *hba) > +{ > + ufs_qcom_dump_regs(hba, REG_UFS_SYS1CLK_1US, 5, > + "REG_UFS_SYS1CLK_1US "); > + > + ufs_qcom_print_hw_debug_reg_all(hba); > +} > + > /** > * struct ufs_hba_qcom_vops - UFS QCOM specific variant operations > * > @@ -1000,5 +1052,6 @@ static const struct ufs_hba_variant_ops > ufs_hba_qcom_vops = { > .pwr_change_notify = ufs_qcom_pwr_change_notify, > .suspend = ufs_qcom_suspend, > .resume = ufs_qcom_resume, > + .dbg_register_dump = ufs_qcom_dump_dbg_regs, > }; > EXPORT_SYMBOL(ufs_hba_qcom_vops); > diff --git a/drivers/scsi/ufs/ufshcd.c b/drivers/scsi/ufs/ufshcd.c > index 84caf6d..ae934f2 100644 > --- a/drivers/scsi/ufs/ufshcd.c > +++ b/drivers/scsi/ufs/ufshcd.c > @@ -45,6 +45,9 @@ > #include "unipro.h" > #include "ufs-debugfs.h" > > +#define CREATE_TRACE_POINTS > +#include > + > #ifdef CONFIG_DEBUG_FS > > #define UFSHCD_UPDATE_ERROR_STATS(hba, type) \ > @@ -139,6 +142,8 @@ > _ret = ufshcd_disable_vreg(_dev, _vreg); \ > _ret; \ > }) > +#define ufshcd_hex_dump(prefix_str, buf, len) \ > +print_hex_dump(KERN_ERR, prefix_str, DUMP_PREFIX_OFFSET, 16, 4, buf, len, > false) > > static u32 ufs_query_desc_max_size[] = { > QUERY_DESC_DEVICE_MAX_SIZE, > @@ -266,6 +271,151 @@ static inline void ufshcd_disable_irq(struct ufs_hba > *hba) > } > } > > +#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) > +{ > + if (trace_ufshcd_command_enabled()) > + 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_uic_err_hist(struct ufs_hba *hba, > + struct ufs_uic_err_reg_hist *err_hist, char *err_name) > +{ > + int i; > + > + for (i = 0; i < UIC_ERR_REG_HIST_LENGTH; i++) { > + int p = (i + err_hist->pos - 1) % UIC_ERR_REG_HIST_LENGTH; > + > + if (err_hist->reg[p] == 0) > + continue; > + dev_err(hba->dev, "%s[%d] = 0x%x at %lld us", err_name, i, > + err_hist->reg[p], > ktime_to_us(err_hist->tstamp[p])); > + } > +} > + > +static void ufshcd_print_host_regs(struct ufs_hba *hba) > +{ > + /* > + * hex_dump reads its data without the readl macro. This might > + * cause inconsistency issues on some platform, as the printed > + * values may be from cache and not the most recent value. > + * To know whether you are looking at an un-cached version verify > + * that IORESOURCE_MEM flag is on when xxx_get_resource() is > invoked > + * during platform/pci probe function. > + */ > + ufshcd_hex_dump("host regs: ", hba->mmio_base, > UFSHCI_REG_SPACE_SIZE); > + dev_err(hba->dev, "hba->ufs_version = 0x%x, hba->capabilities = > 0x%x", > + hba->ufs_version, hba->capabilities); > + dev_err(hba->dev, > + "hba->outstanding_reqs = 0x%x, hba->outstanding_tasks = > 0x%x", > + (u32)hba->outstanding_reqs, (u32)hba->outstanding_tasks); > + dev_err(hba->dev, > + "last_hibern8_exit_tstamp at %lld us, hibern8_exit_cnt = > %d", > + ktime_to_us(hba->ufs_stats.last_hibern8_exit_tstamp), > + hba->ufs_stats.hibern8_exit_cnt); > + > + ufshcd_print_uic_err_hist(hba, &hba->ufs_stats.pa_err, "pa_err"); > + ufshcd_print_uic_err_hist(hba, &hba->ufs_stats.dl_err, "dl_err"); > + ufshcd_print_uic_err_hist(hba, &hba->ufs_stats.nl_err, "nl_err"); > + ufshcd_print_uic_err_hist(hba, &hba->ufs_stats.tl_err, "tl_err"); > + ufshcd_print_uic_err_hist(hba, &hba->ufs_stats.dme_err, > "dme_err"); > + > + if (hba->vops && hba->vops->dbg_register_dump) > + hba->vops->dbg_register_dump(hba); > +} > + > +static > +void ufshcd_print_trs(struct ufs_hba *hba, unsigned long bitmap, bool > pr_prdt) > +{ > + struct ufshcd_lrb *lrbp; > + int prdt_length; > + int tag; > + > + for_each_set_bit(tag, &bitmap, hba->nutrs) { > + lrbp = &hba->lrb[tag]; > + > + dev_err(hba->dev, "UPIU[%d] - issue time %lld us", > + tag, ktime_to_us(lrbp->issue_time_stamp)); > + dev_err(hba->dev, "UPIU[%d] - Transfer Request > Descriptor", > + tag); > + ufshcd_hex_dump("UPIU TRD: ", lrbp->utr_descriptor_ptr, > + sizeof(struct utp_transfer_req_desc)); > + dev_err(hba->dev, "UPIU[%d] - Request UPIU", tag); > + ufshcd_hex_dump("UPIU REQ: ", lrbp->ucd_req_ptr, > + sizeof(struct utp_upiu_req)); > + dev_err(hba->dev, "UPIU[%d] - Response UPIU", tag); > + ufshcd_hex_dump("UPIU RSP: ", lrbp->ucd_rsp_ptr, > + sizeof(struct utp_upiu_rsp)); > + prdt_length = > + > le16_to_cpu(lrbp->utr_descriptor_ptr->prd_table_length); > + dev_err(hba->dev, "UPIU[%d] - PRDT - %d entries", tag, > + prdt_length); > + if (pr_prdt) > + ufshcd_hex_dump("UPIU PRDT: ", lrbp->ucd_prdt_ptr, > + sizeof(struct ufshcd_sg_entry) * > prdt_length); > + } > +} > + > +static void ufshcd_print_tmrs(struct ufs_hba *hba, unsigned long bitmap) > +{ > + struct utp_task_req_desc *tmrdp; > + int tag; > + > + for_each_set_bit(tag, &bitmap, hba->nutmrs) { > + tmrdp = &hba->utmrdl_base_addr[tag]; > + dev_err(hba->dev, "TM[%d] - Task Management Header", tag); > + ufshcd_hex_dump("TM TRD: ", &tmrdp->header, > + sizeof(struct request_desc_header)); > + dev_err(hba->dev, "TM[%d] - Task Management Request UPIU", > + tag); > + ufshcd_hex_dump("TM REQ: ", tmrdp->task_req_upiu, > + sizeof(struct utp_upiu_req)); > + dev_err(hba->dev, "TM[%d] - Task Management Response > UPIU", > + tag); > + ufshcd_hex_dump("TM RSP: ", tmrdp->task_rsp_upiu, > + sizeof(struct utp_task_req_desc)); > + } > +} > + > /* > * ufshcd_wait_for_register - wait for register value to change > * @hba - per-adapter interface > @@ -567,6 +717,40 @@ static inline int ufshcd_is_hba_active(struct ufs_hba > *hba) > return (ufshcd_readl(hba, REG_CONTROLLER_ENABLE) & 0x1) ? 0 : 1; > } > > +static const char *ufschd_uic_link_state_to_string( > + enum uic_link_state state) > +{ > + switch (state) { > + case UIC_LINK_OFF_STATE: return "OFF"; > + case UIC_LINK_ACTIVE_STATE: return "ACTIVE"; > + case UIC_LINK_HIBERN8_STATE: return "HIBERN8"; > + default: return "UNKNOWN"; > + } > +} > + > +static const char *ufschd_ufs_dev_pwr_mode_to_string( > + enum ufs_dev_pwr_mode state) > +{ > + switch (state) { > + case UFS_ACTIVE_PWR_MODE: return "ACTIVE"; > + case UFS_SLEEP_PWR_MODE: return "SLEEP"; > + case UFS_POWERDOWN_PWR_MODE: return "POWERDOWN"; > + default: return "UNKNOWN"; > + } > +} > + > +static const char *ufschd_clk_gating_state_to_string( > + enum clk_gating_state state) > +{ > + switch (state) { > + case CLKS_OFF: return "CLKS_OFF"; > + case CLKS_ON: return "CLKS_ON"; > + case REQ_CLKS_OFF: return "REQ_CLKS_OFF"; > + case REQ_CLKS_ON: return "REQ_CLKS_ON"; > + default: return "UNKNOWN_STATE"; > + } > +} > + > static void ufshcd_ungate_work(struct work_struct *work) > { > int ret; > @@ -628,6 +812,9 @@ start: > case REQ_CLKS_OFF: > if (cancel_delayed_work(&hba->clk_gating.gate_work)) { > hba->clk_gating.state = CLKS_ON; > + trace_ufshcd_clk_gating(dev_name(hba->dev), > + ufschd_clk_gating_state_to_string( > + hba->clk_gating.state)); > break; > } > /* > @@ -638,6 +825,9 @@ start: > case CLKS_OFF: > scsi_block_requests(hba->host); > hba->clk_gating.state = REQ_CLKS_ON; > + trace_ufshcd_clk_gating(dev_name(hba->dev), > + ufschd_clk_gating_state_to_string( > + hba->clk_gating.state)); > schedule_work(&hba->clk_gating.ungate_work); > /* > * fall through to check if we should wait for this > @@ -674,6 +864,9 @@ static void ufshcd_gate_work(struct work_struct *work) > spin_lock_irqsave(hba->host->host_lock, flags); > if (hba->clk_gating.is_suspended) { > hba->clk_gating.state = CLKS_ON; > + trace_ufshcd_clk_gating(dev_name(hba->dev), > + ufschd_clk_gating_state_to_string( > + hba->clk_gating.state)); > goto rel_lock; > } > > @@ -689,6 +882,9 @@ static void ufshcd_gate_work(struct work_struct *work) > if (ufshcd_can_hibern8_during_gating(hba)) { > if (ufshcd_uic_hibern8_enter(hba)) { > hba->clk_gating.state = CLKS_ON; > + trace_ufshcd_clk_gating(dev_name(hba->dev), > + ufschd_clk_gating_state_to_string( > + hba->clk_gating.state)); > goto out; > } > ufshcd_set_link_hibern8(hba); > @@ -715,9 +911,12 @@ static void ufshcd_gate_work(struct work_struct > *work) > * new requests arriving before the current cancel work is done. > */ > spin_lock_irqsave(hba->host->host_lock, flags); > - if (hba->clk_gating.state == REQ_CLKS_OFF) > + if (hba->clk_gating.state == REQ_CLKS_OFF) { > hba->clk_gating.state = CLKS_OFF; > - > + trace_ufshcd_clk_gating(dev_name(hba->dev), > + ufschd_clk_gating_state_to_string( > + hba->clk_gating.state)); > + } > rel_lock: > spin_unlock_irqrestore(hba->host->host_lock, flags); > out: > @@ -739,6 +938,9 @@ static void __ufshcd_release(struct ufs_hba *hba) > return; > > hba->clk_gating.state = REQ_CLKS_OFF; > + trace_ufshcd_clk_gating(dev_name(hba->dev), > + ufschd_clk_gating_state_to_string( > + hba->clk_gating.state)); > schedule_delayed_work(&hba->clk_gating.gate_work, > msecs_to_jiffies(hba->clk_gating.delay_ms)); > } > @@ -836,9 +1038,11 @@ static void ufshcd_clk_scaling_update_busy(struct > ufs_hba *hba) > static inline > void ufshcd_send_command(struct ufs_hba *hba, unsigned int task_tag) > { > + hba->lrb[task_tag].issue_time_stamp = ktime_get(); > ufshcd_clk_scaling_start_busy(hba); > __set_bit(task_tag, &hba->outstanding_reqs); > ufshcd_writel(hba, 1 << task_tag, REG_UTP_TRANSFER_REQ_DOOR_BELL); > + ufshcd_cond_add_cmd_trace(hba, task_tag, "send"); > UFSHCD_UPDATE_TAG_STATS(hba, task_tag); > } > > @@ -1460,6 +1664,7 @@ ufshcd_dev_cmd_completion(struct ufs_hba *hba, > struct ufshcd_lrb *lrbp) > int resp; > int err = 0; > > + hba->ufs_stats.last_hibern8_exit_tstamp = ktime_set(0, 0); > resp = ufshcd_get_req_rsp(lrbp->ucd_rsp_ptr); > > switch (resp) { > @@ -1512,6 +1717,8 @@ static int ufshcd_wait_for_dev_cmd(struct ufs_hba > *hba, > > if (!time_left) { > err = -ETIMEDOUT; > + dev_dbg(hba->dev, "%s: dev_cmd request timedout, tag > %d\n", > + __func__, lrbp->task_tag); > if (!ufshcd_clear_cmd(hba, lrbp->task_tag)) > /* sucessfully cleared the command, retry if > needed */ > err = -EAGAIN; > @@ -1744,8 +1951,8 @@ static int ufshcd_query_attr(struct ufs_hba *hba, > enum query_opcode opcode, > err = ufshcd_exec_dev_cmd(hba, DEV_CMD_TYPE_QUERY, > QUERY_REQ_TIMEOUT); > > if (err) { > - dev_err(hba->dev, "%s: opcode 0x%.2x for idn %d failed, > err = %d\n", > - __func__, opcode, idn, err); > + dev_err(hba->dev, "%s: opcode 0x%.2x for idn %d failed, > index %d, err = %d\n", > + __func__, opcode, idn, index, err); > goto out_unlock; > } > > @@ -1821,8 +2028,8 @@ static int ufshcd_query_descriptor(struct ufs_hba > *hba, > err = ufshcd_exec_dev_cmd(hba, DEV_CMD_TYPE_QUERY, > QUERY_REQ_TIMEOUT); > > if (err) { > - dev_err(hba->dev, "%s: opcode 0x%.2x for idn %d failed, > err = %d\n", > - __func__, opcode, idn, err); > + dev_err(hba->dev, "%s: opcode 0x%.2x for idn %d failed, > index %d, err = %d\n", > + __func__, opcode, idn, index, err); > goto out_unlock; > } > > @@ -1886,8 +2093,9 @@ static int ufshcd_read_desc_param(struct ufs_hba > *hba, > (desc_buf[QUERY_DESC_LENGTH_OFFSET] != > ufs_query_desc_max_size[desc_id]) > || (desc_buf[QUERY_DESC_DESC_TYPE_OFFSET] != desc_id)) { > - dev_err(hba->dev, "%s: Failed reading descriptor. desc_id > %d param_offset %d buff_len %d ret %d", > - __func__, desc_id, param_offset, buff_len, ret); > + dev_err(hba->dev, "%s: Failed reading descriptor. desc_id > %d, param_offset %d, buff_len %d ,index %d, ret %d", > + __func__, desc_id, param_offset, buff_len, > + desc_index, ret); > if (!ret) > ret = -EINVAL; > > @@ -2385,15 +2593,20 @@ static int ufshcd_uic_hibern8_enter(struct ufs_hba > *hba) > { > int ret; > struct uic_command uic_cmd = {0}; > + ktime_t start = ktime_get(); > > 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) { > UFSHCD_UPDATE_ERROR_STATS(hba, UFS_ERR_HIBERN8_ENTER); > dev_err(hba->dev, "%s: hibern8 enter failed. ret = %d", > __func__, ret); > + } else { > + dev_dbg(hba->dev, "%s: Hibern8 Enter at %lld us", > __func__, > + ktime_to_us(ktime_get())); > } > > return ret; > @@ -2403,20 +2616,55 @@ static int ufshcd_uic_hibern8_exit(struct ufs_hba > *hba) > { > struct uic_command uic_cmd = {0}; > int ret; > + ktime_t start = ktime_get(); > > 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) { > ufshcd_set_link_off(hba); > UFSHCD_UPDATE_ERROR_STATS(hba, UFS_ERR_HIBERN8_EXIT); > dev_err(hba->dev, "%s: hibern8 exit failed. ret = %d", > __func__, ret); > ret = ufshcd_host_reset_and_restore(hba); > + } else { > + dev_dbg(hba->dev, "%s: Hibern8 Exit at %lld us", __func__, > + ktime_to_us(ktime_get())); > + hba->ufs_stats.last_hibern8_exit_tstamp = ktime_get(); > + hba->ufs_stats.hibern8_exit_cnt++; > } > > return ret; > } > > +/** > + * ufshcd_print_pwr_info - print power params as saved in hba > + * power info > + * @hba: per-adapter instance > + */ > +static void ufshcd_print_pwr_info(struct ufs_hba *hba) > +{ > + static const char * const names[] = { > + "INVALID MODE", > + "FAST MODE", > + "SLOW_MODE", > + "INVALID MODE", > + "FASTAUTO_MODE", > + "SLOWAUTO_MODE", > + "INVALID MODE", > + }; > + > + dev_info(hba->dev, "%s:[RX, TX]: gear=[%d, %d], lane[%d, %d], > pwr[%s, %s], rate = %d\n", > + __func__, > + hba->pwr_info.gear_rx, hba->pwr_info.gear_tx, > + hba->pwr_info.lane_rx, hba->pwr_info.lane_tx, > + names[hba->pwr_info.pwr_rx], > + names[hba->pwr_info.pwr_tx], > + hba->pwr_info.hs_rate); > +} > + > /** > * ufshcd_init_pwr_info - setting the POR (power on reset) > * values in hba power info > @@ -2560,6 +2808,8 @@ int ufshcd_change_power_mode(struct ufs_hba *hba, > sizeof(struct ufs_pa_layer_attr)); > } > > + ufshcd_print_pwr_info(hba); > + > return ret; > } > > @@ -2803,6 +3053,10 @@ static int ufshcd_link_startup(struct ufs_hba *hba) > /* failed to get the link up... retire */ > goto out; > > + /* Mark that link is up in PWM-G1, 1-lane, SLOW-AUTO mode */ > + ufshcd_init_pwr_info(hba); > + ufshcd_print_pwr_info(hba); > + > /* Include any host controller configuration via UIC commands */ > if (hba->vops && hba->vops->link_startup_notify) { > ret = hba->vops->link_startup_notify(hba, POST_CHANGE); > @@ -3110,6 +3364,7 @@ ufshcd_transfer_rsp_status(struct ufs_hba *hba, > struct ufshcd_lrb *lrbp) > int result = 0; > int scsi_status; > int ocs; > + bool print_prdt; > > /* overall command status of utrd */ > ocs = ufshcd_get_tr_ocs(lrbp); > @@ -3117,7 +3372,7 @@ ufshcd_transfer_rsp_status(struct ufs_hba *hba, > struct ufshcd_lrb *lrbp) > switch (ocs) { > case OCS_SUCCESS: > result = ufshcd_get_req_rsp(lrbp->ucd_rsp_ptr); > - > + hba->ufs_stats.last_hibern8_exit_tstamp = ktime_set(0, 0); > switch (result) { > case UPIU_TRANSACTION_RESPONSE: > /* > @@ -3165,10 +3420,17 @@ ufshcd_transfer_rsp_status(struct ufs_hba *hba, > struct ufshcd_lrb *lrbp) > default: > result |= DID_ERROR << 16; > dev_err(hba->dev, > - "OCS error from controller = %x\n", ocs); > + "OCS error from controller = %x for tag > %d\n", > + ocs, lrbp->task_tag); > + ufshcd_print_host_regs(hba); > break; > } /* end of switch */ > > + if ((host_byte(result) != DID_OK) && !hba->silence_err_logs) { > + print_prdt = (ocs == OCS_INVALID_PRDT_ATTR || > + ocs == OCS_MISMATCH_DATA_BUF_SIZE); > + ufshcd_print_trs(hba, 1 << lrbp->task_tag, print_prdt); > + } > return result; > } > > @@ -3220,6 +3482,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"); > UFSHCD_UPDATE_TAG_STATS_COMPLETION(hba, cmd); > result = ufshcd_transfer_rsp_status(hba, lrbp); > scsi_dma_unmap(cmd); > @@ -3231,8 +3494,11 @@ static void ufshcd_transfer_req_compl(struct > ufs_hba *hba) > cmd->scsi_done(cmd); > __ufshcd_release(hba); > } else if (lrbp->command_type == UTP_CMD_TYPE_DEV_MANAGE) > { > - if (hba->dev_cmd.complete) > + if (hba->dev_cmd.complete) { > + ufshcd_cond_add_cmd_trace(hba, index, > + "dev_complete"); > complete(hba->dev_cmd.complete); > + } > } > } > > @@ -3328,6 +3594,7 @@ static int ufshcd_enable_auto_bkops(struct ufs_hba > *hba) > } > > hba->auto_bkops_enabled = true; > + trace_ufshcd_auto_bkops_state(dev_name(hba->dev), "Enabled"); > > /* No need of URGENT_BKOPS exception from the device */ > err = ufshcd_disable_ee(hba, MASK_EE_URGENT_BKOPS); > @@ -3378,6 +3645,7 @@ static int ufshcd_disable_auto_bkops(struct ufs_hba > *hba) > } > > hba->auto_bkops_enabled = false; > + trace_ufshcd_auto_bkops_state(dev_name(hba->dev), "Disabled"); > out: > return err; > } > @@ -3530,6 +3798,22 @@ static void ufshcd_err_handler(struct work_struct > *work) > /* Complete requests that have door-bell cleared by h/w */ > ufshcd_transfer_req_compl(hba); > ufshcd_tmc_handler(hba); > + > + /* > + * Dump controller state before resetting. Transfer requests state > + * will be dump as part of the request completion. > + */ > + if (hba->saved_err & (INT_FATAL_ERRORS | UIC_ERROR)) { > + dev_err(hba->dev, "%s: saved_err 0x%x saved_uic_err 0x%x", > + __func__, hba->saved_err, hba->saved_uic_err); > + if (!hba->silence_err_logs) { > + ufshcd_print_host_regs(hba); > + ufshcd_print_pwr_info(hba); > + ufshcd_print_tmrs(hba, hba->outstanding_tasks); > + } > + } > + > + > spin_unlock_irqrestore(hba->host->host_lock, flags); > > /* Clear pending transfer requests */ > @@ -3578,7 +3862,14 @@ static void ufshcd_err_handler(struct work_struct > *work) > scsi_report_bus_reset(hba->host, 0); > hba->saved_err = 0; > hba->saved_uic_err = 0; > + } else { > + hba->ufshcd_state = UFSHCD_STATE_OPERATIONAL; > + if (hba->saved_err || hba->saved_uic_err) > + dev_err_ratelimited(hba->dev, "%s: exit: saved_err > 0x%x saved_uic_err 0x%x", > + __func__, hba->saved_err, hba->saved_uic_err); > } > + > + hba->silence_err_logs = false; > ufshcd_clear_eh_in_progress(hba); > > out: > @@ -3587,6 +3878,14 @@ out: > pm_runtime_put_sync(hba->dev); > } > > +static void ufshcd_update_uic_reg_hist(struct ufs_uic_err_reg_hist > *reg_hist, > + u32 reg) > +{ > + reg_hist->reg[reg_hist->pos] = reg; > + reg_hist->tstamp[reg_hist->pos] = ktime_get(); > + reg_hist->pos = (reg_hist->pos + 1) % UIC_ERR_REG_HIST_LENGTH; > +} > + > /** > * ufshcd_update_uic_error - check and set fatal UIC error flags. > * @hba: per-adapter instance > @@ -3595,23 +3894,46 @@ static void ufshcd_update_uic_error(struct ufs_hba > *hba) > { > u32 reg; > > + /* PHY layer lane error */ > + reg = ufshcd_readl(hba, REG_UIC_ERROR_CODE_PHY_ADAPTER_LAYER); > + /* Ignore LINERESET indication, as this is not an error */ > + if ((reg & UIC_PHY_ADAPTER_LAYER_ERROR) && > + (reg & UIC_PHY_ADAPTER_LAYER_LANE_ERR_MASK)) { > + /* > + * To know whether this error is fatal or not, DB timeout > + * must be checked but this error is handled separately. > + */ > + dev_dbg(hba->dev, "%s: UIC Lane error reported, reg > 0x%x\n", > + __func__, reg); > + ufshcd_update_uic_reg_hist(&hba->ufs_stats.pa_err, reg); > + } > + > /* PA_INIT_ERROR is fatal and needs UIC reset */ > reg = ufshcd_readl(hba, REG_UIC_ERROR_CODE_DATA_LINK_LAYER); > + if (reg) > + ufshcd_update_uic_reg_hist(&hba->ufs_stats.dl_err, reg); > + > if (reg & UIC_DATA_LINK_LAYER_ERROR_PA_INIT) > hba->uic_error |= UFSHCD_UIC_DL_PA_INIT_ERROR; > > /* UIC NL/TL/DME errors needs software retry */ > reg = ufshcd_readl(hba, REG_UIC_ERROR_CODE_NETWORK_LAYER); > - if (reg) > + if (reg) { > + ufshcd_update_uic_reg_hist(&hba->ufs_stats.nl_err, reg); > hba->uic_error |= UFSHCD_UIC_NL_ERROR; > + } > > reg = ufshcd_readl(hba, REG_UIC_ERROR_CODE_TRANSPORT_LAYER); > - if (reg) > + if (reg) { > + ufshcd_update_uic_reg_hist(&hba->ufs_stats.tl_err, reg); > hba->uic_error |= UFSHCD_UIC_TL_ERROR; > + } > > reg = ufshcd_readl(hba, REG_UIC_ERROR_CODE_DME); > - if (reg) > + if (reg) { > + ufshcd_update_uic_reg_hist(&hba->ufs_stats.dme_err, reg); > hba->uic_error |= UFSHCD_UIC_DME_ERROR; > + } > > dev_dbg(hba->dev, "%s: UIC error flags = 0x%08x\n", > __func__, hba->uic_error); > @@ -3636,16 +3958,20 @@ static void ufshcd_check_errors(struct ufs_hba > *hba) > } > > if (queue_eh_work) { > + /* > + * update the transfer error masks to sticky bits, let's > do this > + * irrespective of current ufshcd_state. > + */ > + hba->saved_err |= hba->errors; > + hba->saved_uic_err |= hba->uic_error; > + > /* handle fatal errors only when link is functional */ > if (hba->ufshcd_state == UFSHCD_STATE_OPERATIONAL) { > /* block commands from scsi mid-layer */ > scsi_block_requests(hba->host); > > - /* transfer error masks to sticky bits */ > - hba->saved_err |= hba->errors; > - hba->saved_uic_err |= hba->uic_error; > - > hba->ufshcd_state = UFSHCD_STATE_ERROR; > + > schedule_work(&hba->eh_work); > } > } > @@ -3917,18 +4243,42 @@ static int ufshcd_abort(struct scsi_cmnd *cmd) > __func__, tag); > } > > + /* Print Transfer Request of aborted task */ > + dev_err(hba->dev, "%s: Device abort task at tag %d", __func__, > tag); > + > + /* > + * Print detailed info about aborted request. > + * As more than one request might get aborted at the same time, > + * print full information only for the first aborted request in > order > + * to reduce repeated printouts. For other aborted requests only > print > + * basic details. > + */ > + scsi_print_command(cmd); > + if (!hba->req_abort_count) { > + ufshcd_print_host_regs(hba); > + ufshcd_print_pwr_info(hba); > + ufshcd_print_trs(hba, 1 << tag, true); > + } else { > + ufshcd_print_trs(hba, 1 << tag, false); > + } > + hba->req_abort_count++; > + > lrbp = &hba->lrb[tag]; > for (poll_cnt = 100; poll_cnt; poll_cnt--) { > err = ufshcd_issue_tm_cmd(hba, lrbp->lun, lrbp->task_tag, > UFS_QUERY_TASK, &resp); > if (!err && resp == UPIU_TASK_MANAGEMENT_FUNC_SUCCEEDED) { > /* cmd pending in the device */ > + dev_err(hba->dev, "%s: cmd pending in the device. > tag = %d", > + __func__, tag); > break; > } else if (!err && resp == > UPIU_TASK_MANAGEMENT_FUNC_COMPL) { > /* > * cmd not pending in the device, check if it is > * in transition. > */ > + dev_err(hba->dev, "%s: cmd at tag %d not pending > in the device.", > + __func__, tag); > reg = ufshcd_readl(hba, > REG_UTP_TRANSFER_REQ_DOOR_BELL); > if (reg & (1 << tag)) { > /* sleep for max. 200us to stabilize */ > @@ -3936,8 +4286,13 @@ static int ufshcd_abort(struct scsi_cmnd *cmd) > continue; > } > /* command completed already */ > + dev_err(hba->dev, "%s: cmd at tag %d successfully > cleared from DB.", > + __func__, tag); > goto out; > } else { > + dev_err(hba->dev, > + "%s: no response from device. tag = %d, > err %d", > + __func__, tag, err); > if (!err) > err = resp; /* service response error */ > goto out; > @@ -3952,14 +4307,20 @@ static int ufshcd_abort(struct scsi_cmnd *cmd) > err = ufshcd_issue_tm_cmd(hba, lrbp->lun, lrbp->task_tag, > UFS_ABORT_TASK, &resp); > if (err || resp != UPIU_TASK_MANAGEMENT_FUNC_COMPL) { > - if (!err) > + if (!err) { > err = resp; /* service response error */ > + dev_err(hba->dev, "%s: issued. tag = %d, err %d", > + __func__, tag, err); > + } > goto out; > } > > err = ufshcd_clear_cmd(hba, tag); > - if (err) > + if (err) { > + dev_err(hba->dev, "%s: Failed clearing cmd at tag %d, err > %d", > + __func__, tag, err); > goto out; > + } > > scsi_dma_unmap(cmd); > > @@ -4292,6 +4653,22 @@ out: > return ret; > } > > +static void ufshcd_clear_dbg_ufs_stats(struct ufs_hba *hba) > +{ > + int err_reg_hist_size = sizeof(struct ufs_uic_err_reg_hist); > + > + hba->ufs_stats.hibern8_exit_cnt = 0; > + hba->ufs_stats.last_hibern8_exit_tstamp = ktime_set(0, 0); > + > + memset(&hba->ufs_stats.pa_err, 0, err_reg_hist_size); > + memset(&hba->ufs_stats.dl_err, 0, err_reg_hist_size); > + memset(&hba->ufs_stats.nl_err, 0, err_reg_hist_size); > + memset(&hba->ufs_stats.tl_err, 0, err_reg_hist_size); > + memset(&hba->ufs_stats.dme_err, 0, err_reg_hist_size); > + > + hba->req_abort_count = 0; > +} > + > /** > * ufshcd_probe_hba - probe hba to detect device and initialize > * @hba: per-adapter instance > @@ -4301,12 +4678,17 @@ out: > static int ufshcd_probe_hba(struct ufs_hba *hba) > { > int ret; > + ktime_t start = ktime_get(); > > ret = ufshcd_link_startup(hba); > if (ret) > goto out; > > + /* Debug counters initialization */ > + ufshcd_clear_dbg_ufs_stats(hba); > + > ufshcd_init_pwr_info(hba); > + ufshcd_print_pwr_info(hba); > > /* UniPro link is active now */ > ufshcd_set_link_active(hba); > @@ -4377,6 +4759,10 @@ out: > ufshcd_hba_exit(hba); > } > > + trace_ufshcd_init(dev_name(hba->dev), ret, > + ktime_to_us(ktime_sub(ktime_get(), start)), > + ufschd_ufs_dev_pwr_mode_to_string(hba->curr_dev_pwr_mode), > + ufschd_uic_link_state_to_string(hba->uic_link_state)); > return ret; > } > > @@ -4837,6 +5223,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; > @@ -4846,6 +5234,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) { > @@ -4873,8 +5262,17 @@ out: > } else if (on) { > spin_lock_irqsave(hba->host->host_lock, flags); > hba->clk_gating.state = CLKS_ON; > + trace_ufshcd_clk_gating(dev_name(hba->dev), > + ufschd_clk_gating_state_to_string( > + hba->clk_gating.state)); > + > 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; > } > > @@ -5361,6 +5759,8 @@ disable_clks: > __ufshcd_setup_clocks(hba, false, true); > > hba->clk_gating.state = CLKS_OFF; > + trace_ufshcd_clk_gating(dev_name(hba->dev), > + ufschd_clk_gating_state_to_string(hba->clk_gating.state)); > /* > * Disable the host irq as host controller as there won't be any > * host controller trasanction expected till resume. > @@ -5507,6 +5907,7 @@ out: > int ufshcd_system_suspend(struct ufs_hba *hba) > { > int ret = 0; > + ktime_t start = ktime_get(); > > if (!hba || !hba->is_powered) > return 0; > @@ -5536,6 +5937,10 @@ int ufshcd_system_suspend(struct ufs_hba *hba) > > ret = ufshcd_suspend(hba, UFS_SYSTEM_PM); > out: > + trace_ufshcd_system_suspend(dev_name(hba->dev), ret, > + ktime_to_us(ktime_sub(ktime_get(), start)), > + ufschd_ufs_dev_pwr_mode_to_string(hba->curr_dev_pwr_mode), > + ufschd_uic_link_state_to_string(hba->uic_link_state)); > if (!ret) > hba->is_sys_suspended = true; > return ret; > @@ -5551,14 +5956,23 @@ EXPORT_SYMBOL(ufshcd_system_suspend); > > int ufshcd_system_resume(struct ufs_hba *hba) > { > + int ret = 0; > + ktime_t start = ktime_get(); > + > if (!hba || !hba->is_powered || pm_runtime_suspended(hba->dev)) > /* > * Let the runtime resume take care of resuming > * if runtime suspended. > */ > - return 0; > - > - return ufshcd_resume(hba, UFS_SYSTEM_PM); > + goto out; > + else > + ret = ufshcd_resume(hba, UFS_SYSTEM_PM); > +out: > + trace_ufshcd_system_resume(dev_name(hba->dev), ret, > + ktime_to_us(ktime_sub(ktime_get(), start)), > + ufschd_ufs_dev_pwr_mode_to_string(hba->curr_dev_pwr_mode), > + ufschd_uic_link_state_to_string(hba->uic_link_state)); > + return ret; > } > EXPORT_SYMBOL(ufshcd_system_resume); > > @@ -5572,10 +5986,19 @@ EXPORT_SYMBOL(ufshcd_system_resume); > */ > int ufshcd_runtime_suspend(struct ufs_hba *hba) > { > - if (!hba || !hba->is_powered) > - return 0; > + int ret = 0; > + ktime_t start = ktime_get(); > > - return ufshcd_suspend(hba, UFS_RUNTIME_PM); > + if (!hba || !hba->is_powered) > + goto out; > + else > + ret = ufshcd_suspend(hba, UFS_RUNTIME_PM); > +out: > + trace_ufshcd_runtime_suspend(dev_name(hba->dev), ret, > + ktime_to_us(ktime_sub(ktime_get(), start)), > + ufschd_ufs_dev_pwr_mode_to_string(hba->curr_dev_pwr_mode), > + ufschd_uic_link_state_to_string(hba->uic_link_state)); > + return ret; > } > EXPORT_SYMBOL(ufshcd_runtime_suspend); > > @@ -5602,10 +6025,19 @@ EXPORT_SYMBOL(ufshcd_runtime_suspend); > */ > int ufshcd_runtime_resume(struct ufs_hba *hba) > { > + int ret = 0; > + ktime_t start = ktime_get(); > + > if (!hba || !hba->is_powered) > - return 0; > + goto out; > else > - return ufshcd_resume(hba, UFS_RUNTIME_PM); > + ret = ufshcd_resume(hba, UFS_RUNTIME_PM); > +out: > + trace_ufshcd_runtime_resume(dev_name(hba->dev), ret, > + ktime_to_us(ktime_sub(ktime_get(), start)), > + ufschd_ufs_dev_pwr_mode_to_string(hba->curr_dev_pwr_mode), > + ufschd_uic_link_state_to_string(hba->uic_link_state)); > + return ret; > } > EXPORT_SYMBOL(ufshcd_runtime_resume); > > @@ -5724,6 +6156,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; > @@ -5733,6 +6167,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", > @@ -5740,11 +6176,17 @@ static int ufshcd_scale_clks(struct ufs_hba *hba, > bool scale_up) > clki->max_freq, ret); > break; > } > + > trace_ufshcd_clk_scaling(dev_name(hba->dev), > + "scaled up", clki->name, > + clki->curr_freq, > + clki->max_freq); > clki->curr_freq = clki->max_freq; > > } 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", > @@ -5752,6 +6194,10 @@ static int ufshcd_scale_clks(struct ufs_hba *hba, > bool scale_up) > clki->min_freq, ret); > break; > } > + > trace_ufshcd_clk_scaling(dev_name(hba->dev), > + "scaled down", clki->name, > + clki->curr_freq, > + clki->min_freq); > clki->curr_freq = clki->min_freq; > } > } > @@ -5761,6 +6207,10 @@ static int ufshcd_scale_clks(struct ufs_hba *hba, > bool scale_up) > if (hba->vops->clk_scale_notify) > hba->vops->clk_scale_notify(hba); > 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; > } > > @@ -5931,6 +6381,7 @@ int ufshcd_init(struct ufs_hba *hba, void __iomem > *mmio_base, unsigned int irq) > err = ufshcd_hba_enable(hba); > if (err) { > dev_err(hba->dev, "Host controller enable failed\n"); > + ufshcd_print_host_regs(hba); > goto out_remove_scsi_host; > } > > diff --git a/drivers/scsi/ufs/ufshcd.h b/drivers/scsi/ufs/ufshcd.h > index d9b1251..d9eb2ca 100644 > --- a/drivers/scsi/ufs/ufshcd.h > +++ b/drivers/scsi/ufs/ufshcd.h > @@ -178,6 +178,7 @@ struct ufs_pm_lvl_states { > * @task_tag: Task tag of the command > * @lun: LUN of the command > * @intr_cmd: Interrupt command (doesn't participate in interrupt > aggregation) > + * @issue_time_stamp: time stamp for debug purposes > */ > struct ufshcd_lrb { > struct utp_transfer_req_desc *utr_descriptor_ptr; > @@ -194,6 +195,7 @@ struct ufshcd_lrb { > int task_tag; > u8 lun; /* UPIU LUN id field is only 8-bit wide */ > bool intr_cmd; > + ktime_t issue_time_stamp; > }; > > /** > @@ -223,14 +225,52 @@ struct ufs_dev_cmd { > struct ufs_query query; > }; > > -#ifdef CONFIG_DEBUG_FS > +#define UIC_ERR_REG_HIST_LENGTH 8 > +/** > + * struct ufs_uic_err_reg_hist - keeps history of uic errors > + * @pos: index to indicate cyclic buffer position > + * @reg: cyclic buffer for registers value > + * @tstamp: cyclic buffer for time stamp > + */ > +struct ufs_uic_err_reg_hist { > + int pos; > + u32 reg[UIC_ERR_REG_HIST_LENGTH]; > + ktime_t tstamp[UIC_ERR_REG_HIST_LENGTH]; > +}; > + > +/** > + * struct ufs_stats - keeps usage/err statistics > + * @enabled: enable tagstats for debugfs > + * @tag_stats: pointer to tag statistic counters > + * @q_depth: current amount of busy slots > + * @err_stats: counters to keep track of various errors > + * @hibern8_exit_cnt: Counter to keep track of number of exits, > + * reset this after link-startup. > + * @last_hibern8_exit_tstamp: Set time after the hibern8 exit. > + * Clear after the first successful command completion. > + * @pa_err: tracks pa-uic errors > + * @dl_err: tracks dl-uic errors > + * @nl_err: tracks nl-uic errors > + * @tl_err: tracks tl-uic errors > + * @dme_err: tracks dme errors > + */ > struct ufs_stats { > +#ifdef CONFIG_DEBUG_FS > bool enabled; > u64 **tag_stats; > int q_depth; > int err_stats[UFS_ERR_MAX]; > +#endif > + u32 hibern8_exit_cnt; > + ktime_t last_hibern8_exit_tstamp; > + struct ufs_uic_err_reg_hist pa_err; > + struct ufs_uic_err_reg_hist dl_err; > + struct ufs_uic_err_reg_hist nl_err; > + struct ufs_uic_err_reg_hist tl_err; > + struct ufs_uic_err_reg_hist dme_err; > }; > > +#ifdef CONFIG_DEBUG_FS > struct debugfs_files { > struct dentry *debugfs_root; > struct dentry *tag_stats; > @@ -326,6 +366,7 @@ struct ufs_hba_variant_ops { > struct ufs_pa_layer_attr *); > int (*suspend)(struct ufs_hba *, enum ufs_pm_op); > int (*resume)(struct ufs_hba *, enum ufs_pm_op); > + void (*dbg_register_dump)(struct ufs_hba *hba); > }; > > /* clock gating state */ > @@ -498,6 +539,7 @@ struct ufs_hba { > u32 uic_error; > u32 saved_err; > u32 saved_uic_err; > + bool silence_err_logs; > > /* Device management request data */ > struct ufs_dev_cmd dev_cmd; > @@ -528,10 +570,13 @@ struct ufs_hba { > struct devfreq *devfreq; > struct ufs_clk_scaling clk_scaling; > bool is_sys_suspended; > -#ifdef CONFIG_DEBUG_FS > struct ufs_stats ufs_stats; > +#ifdef CONFIG_DEBUG_FS > struct debugfs_files debugfs_files; > #endif > + > + /* Number of requests aborts */ > + int req_abort_count; > }; > > /* Returns true if clocks can be gated. Otherwise false */ > diff --git a/drivers/scsi/ufs/ufshci.h b/drivers/scsi/ufs/ufshci.h > index c8b178f..c5a0d19 100644 > --- a/drivers/scsi/ufs/ufshci.h > +++ b/drivers/scsi/ufs/ufshci.h > @@ -166,6 +166,7 @@ enum { > /* UECPA - Host UIC Error Code PHY Adapter Layer 38h */ > #define UIC_PHY_ADAPTER_LAYER_ERROR UFS_BIT(31) > #define UIC_PHY_ADAPTER_LAYER_ERROR_CODE_MASK 0x1F > +#define UIC_PHY_ADAPTER_LAYER_LANE_ERR_MASK 0xF > > /* UECDL - Host UIC Error Code Data Link Layer 3Ch */ > #define UIC_DATA_LINK_LAYER_ERROR UFS_BIT(31) > diff --git a/include/trace/events/ufs.h b/include/trace/events/ufs.h > new file mode 100644 > index 0000000..045c6b5 > --- /dev/null > +++ b/include/trace/events/ufs.h > @@ -0,0 +1,227 @@ > +/* > + * Copyright (c) 2013-2015, 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 > + > +TRACE_EVENT(ufshcd_clk_gating, > + > + 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: gating state changed to %s", > + __get_str(dev_name), __get_str(state)) > +); > + > +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_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, > + const char *dev_state, const char *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) > + __string(dev_state, dev_state) > + __string(link_state, link_state) > + ), > + > + TP_fast_assign( > + __entry->usecs = usecs; > + __entry->err = err; > + __assign_str(dev_name, dev_name); > + __assign_str(dev_state, dev_state); > + __assign_str(link_state, link_state); > + ), > + > + TP_printk( > + "%s: took %lld usecs, dev_state: %s, link_state: %s, err > %d", > + __get_str(dev_name), > + __entry->usecs, > + __get_str(dev_state), > + __get_str(link_state), > + __entry->err > + ) > +); > + > +DEFINE_EVENT(ufshcd_template, ufshcd_system_suspend, > + 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)); > + > +DEFINE_EVENT(ufshcd_template, ufshcd_system_resume, > + 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)); > + > +DEFINE_EVENT(ufshcd_template, ufshcd_runtime_suspend, > + 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)); > + > +DEFINE_EVENT(ufshcd_template, ufshcd_runtime_resume, > + 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)); > + > +DEFINE_EVENT(ufshcd_template, ufshcd_init, > + 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 */ > +#include > -- > Qualcomm Israel, on behalf of Qualcomm Innovation Center, Inc. > The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum, > a Linux Foundation Collaborative Project > > -- > To unsubscribe from this list: send the line "unsubscribe linux-scsi" in > the body of a message to majordomo@vger.kernel.org > More majordomo info at http://vger.kernel.org/majordomo-info.html > Reviewed-by: Dov Levenglick QUALCOMM ISRAEL, on behalf of Qualcomm Innovation Center, Inc. The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum, a Linux Foundation Collaborative Project -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/