From 3c0960d0f11f70d22d155e30ebdfdd7805a1d43d Mon Sep 17 00:00:00 2001 From: Dolev Raviv Date: Tue, 28 Oct 2014 10:12:10 +0200 Subject: [PATCH] scsi: ufs: Improve fatal error logs Errors such as UIC error, illegal OCS values, and others may require more information for debugging. Such information could be hibern8 events, events sequences, recoverable errors, error history, and more. This patch improves tracking of important errors and events in debug level to be enabled when debugging a such issues. It includes: * UIC error history * Successful hibern8 events * Successful command after hibern8 exit * Clk-freq info * Failed device command * Infrastructure for dumping host controller debug information Change-Id: If3b38b86caeec4ffc669d001b452050a4a6b5173 Signed-off-by: Dolev Raviv [subhashj@codeaurora.org: resolved trivial merge conflicts] Signed-off-by: Subhash Jadavani --- drivers/scsi/ufs/ufshcd.c | 215 +++++++++++++++++++++++++------- include/linux/scsi/ufs/ufshcd.h | 55 +++++++- 2 files changed, 224 insertions(+), 46 deletions(-) diff --git a/drivers/scsi/ufs/ufshcd.c b/drivers/scsi/ufs/ufshcd.c index 764442247c08..9afcce56f842 100644 --- a/drivers/scsi/ufs/ufshcd.c +++ b/drivers/scsi/ufs/ufshcd.c @@ -382,6 +382,37 @@ static inline void ufshcd_cond_add_cmd_trace(struct ufs_hba *hba, } #endif +static void ufshcd_print_clk_freqs(struct ufs_hba *hba) +{ + struct ufs_clk_info *clki; + struct list_head *head = &hba->clk_list_head; + + if (!head || list_empty(head)) + return; + + list_for_each_entry(clki, head, list) { + if (!IS_ERR_OR_NULL(clki->clk) && clki->min_freq && + clki->max_freq) + dev_err(hba->dev, "clk: %s, rate: %u\n", + clki->name, clki->curr_freq); + } +} + +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) { /* @@ -398,6 +429,21 @@ static void ufshcd_print_host_regs(struct ufs_hba *hba) 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"); + + ufshcd_print_clk_freqs(hba); + + if (hba->vops && hba->vops->dbg_register_dump) + hba->vops->dbg_register_dump(hba); } static @@ -409,22 +455,29 @@ void ufshcd_print_trs(struct ufs_hba *hba, unsigned long bitmap, bool pr_prdt) for_each_set_bit(tag, &bitmap, hba->nutrs) { lrbp = &hba->lrb[tag]; - dev_err(hba->dev, "UPIU[%d] - Transfer Request Descriptor", - 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 phys@0x%llx", + tag, (u64)lrbp->utrd_dma_addr); ufshcd_hex_dump("UPIU TRD: ", lrbp->utr_descriptor_ptr, sizeof(struct utp_transfer_req_desc)); - dev_err(hba->dev, "UPIU[%d] - Request UPIU", tag); + dev_err(hba->dev, "UPIU[%d] - Request UPIU phys@0x%llx", tag, + (u64)lrbp->ucd_req_dma_addr); ufshcd_hex_dump("UPIU REQ: ", lrbp->ucd_req_ptr, sizeof(struct utp_upiu_req)); - dev_err(hba->dev, "UPIU[%d] - Response UPIU", tag); + dev_err(hba->dev, "UPIU[%d] - Response UPIU phys@0x%llx", tag, + (u64)lrbp->ucd_rsp_dma_addr); ufshcd_hex_dump("UPIU RSP: ", lrbp->ucd_rsp_ptr, sizeof(struct utp_upiu_rsp)); if (pr_prdt) { int prdt_length = le16_to_cpu( lrbp->utr_descriptor_ptr->prd_table_length); - dev_err(hba->dev, "UPIU[%d] - PRDT - %d entries", tag, - prdt_length); + dev_err(hba->dev, + "UPIU[%d] - PRDT - %d entries phys@0x%llx", + tag, prdt_length, + (u64)lrbp->ucd_prdt_dma_addr); ufshcd_hex_dump("UPIU PRDT: ", lrbp->ucd_prdt_ptr, sizeof(struct ufshcd_sg_entry) * prdt_length); @@ -453,6 +506,32 @@ static void ufshcd_print_tmrs(struct ufs_hba *hba, unsigned long bitmap) } } +/** + * 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) +{ + char *names[] = { + "INVALID MODE", + "FAST MODE", + "SLOW_MODE", + "INVALID MODE", + "FASTAUTO_MODE", + "SLOWAUTO_MODE", + "INVALID MODE", + }; + + dev_err(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_wait_for_register - wait for register value to change * @hba - per-adapter interface @@ -1696,6 +1775,8 @@ int ufshcd_send_command(struct ufs_hba *hba, unsigned int task_tag) return ret; } } + + 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); @@ -2377,6 +2458,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) { @@ -2429,6 +2511,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; @@ -2709,8 +2793,8 @@ int ufshcd_query_attr_retry(struct ufs_hba *hba, enum query_opcode opcode, ret = ufshcd_query_attr(hba, opcode, idn, index, selector, attr_val); if (ret) - dev_dbg(hba->dev, "%s: failed with error %d\n", - __func__, ret); + dev_dbg(hba->dev, "%s: failed with error %d, retries %d\n", + __func__, ret, retries); else break; } @@ -3124,32 +3208,6 @@ out: return -ENOMEM; } - /** - * 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) -{ - char *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_host_memory_configure - configure local reference block with * memory offsets @@ -3203,12 +3261,19 @@ static void ufshcd_host_memory_configure(struct ufs_hba *hba) cpu_to_le16(ALIGNED_UPIU_SIZE >> 2); hba->lrb[i].utr_descriptor_ptr = (utrdlp + i); + hba->lrb[i].utrd_dma_addr = hba->utrdl_dma_addr + + (i * sizeof(struct utp_transfer_req_desc)); hba->lrb[i].ucd_req_ptr = (struct utp_upiu_req *)(cmd_descp + i); + hba->lrb[i].ucd_req_dma_addr = cmd_desc_element_addr; hba->lrb[i].ucd_rsp_ptr = (struct utp_upiu_rsp *)cmd_descp[i].response_upiu; + hba->lrb[i].ucd_rsp_dma_addr = cmd_desc_element_addr + + response_offset; hba->lrb[i].ucd_prdt_ptr = (struct ufshcd_sg_entry *)cmd_descp[i].prd_table; + hba->lrb[i].ucd_prdt_dma_addr = cmd_desc_element_addr + + prdt_offset; } } @@ -3232,7 +3297,7 @@ static int ufshcd_dme_link_startup(struct ufs_hba *hba) ret = ufshcd_send_uic_cmd(hba, &uic_cmd); if (ret) - dev_err(hba->dev, + dev_dbg(hba->dev, "dme-link-startup: error code %d\n", ret); return ret; } @@ -3559,6 +3624,9 @@ static int ufshcd_uic_hibern8_enter(struct ufs_hba *hba) 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; @@ -3581,6 +3649,11 @@ static int ufshcd_uic_hibern8_exit(struct ufs_hba *hba) 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; @@ -4370,7 +4443,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: /* @@ -4418,7 +4491,9 @@ 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 */ @@ -4924,6 +4999,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 @@ -4936,30 +5019,42 @@ static void ufshcd_update_uic_error(struct ufs_hba *hba) 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)) + (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\n", __func__); + 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); @@ -5298,12 +5393,16 @@ static int ufshcd_abort(struct scsi_cmnd *cmd) 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 */ @@ -5311,8 +5410,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; @@ -5327,14 +5431,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); @@ -5776,6 +5886,20 @@ static void ufshcd_tune_unipro_params(struct ufs_hba *hba) } } +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); +} + /** * ufshcd_probe_hba - probe hba to detect device and initialize * @hba: per-adapter instance @@ -5791,6 +5915,9 @@ static int ufshcd_probe_hba(struct ufs_hba *hba) if (ret) goto out; + /* Debug counters initialization */ + ufshcd_clear_dbg_ufs_stats(hba); + /* UniPro link is active now */ ufshcd_set_link_active(hba); diff --git a/include/linux/scsi/ufs/ufshcd.h b/include/linux/scsi/ufs/ufshcd.h index 18a4ec1509d9..4d877170d268 100644 --- a/include/linux/scsi/ufs/ufshcd.h +++ b/include/linux/scsi/ufs/ufshcd.h @@ -171,6 +171,10 @@ struct ufs_pm_lvl_states { * @ucd_req_ptr: UCD address of the command * @ucd_rsp_ptr: Response UPIU address for this command * @ucd_prdt_ptr: PRDT address of the command + * @utrd_dma_addr: UTRD dma address for debug + * @ucd_prdt_dma_addr: PRDT dma address for debug + * @ucd_rsp_dma_addr: UPIU response dma address for debug + * @ucd_req_dma_addr: UPIU request dma address for debug * @cmd: pointer to SCSI command * @sense_buffer: pointer to sense buffer address of the SCSI command * @sense_bufflen: Length of the sense buffer @@ -179,6 +183,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; @@ -186,6 +191,11 @@ struct ufshcd_lrb { struct utp_upiu_rsp *ucd_rsp_ptr; struct ufshcd_sg_entry *ucd_prdt_ptr; + dma_addr_t utrd_dma_addr; + dma_addr_t ucd_req_dma_addr; + dma_addr_t ucd_rsp_dma_addr; + dma_addr_t ucd_prdt_dma_addr; + struct scsi_cmnd *cmd; u8 *sense_buffer; unsigned int sense_bufflen; @@ -195,6 +205,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; }; /** @@ -294,6 +305,7 @@ struct ufs_pwr_mode_info { * should be reset. * @crypto_engine_reset_err: resets the saved error status of * the cryptographic engine + * @dbg_register_dump: used to dump controller debug information */ struct ufs_hba_variant_ops { const char *name; @@ -320,6 +332,7 @@ struct ufs_hba_variant_ops { int (*crypto_engine_eh)(struct ufs_hba *); int (*crypto_engine_get_err)(struct ufs_hba *); void (*crypto_engine_reset_err)(struct ufs_hba *); + void (*dbg_register_dump)(struct ufs_hba *hba); }; /* clock gating state */ @@ -411,14 +424,52 @@ struct ufs_init_prefetch { u32 icc_level; }; -#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; @@ -660,8 +711,8 @@ struct ufs_hba { struct ufs_dev_info dev_info; bool auto_bkops_enabled; -#ifdef CONFIG_DEBUG_FS struct ufs_stats ufs_stats; +#ifdef CONFIG_DEBUG_FS struct debugfs_files debugfs_files; #endif