Add the necessary infrastructure to keep timestamp history of commands, events and other useful info for debugging complex issues. This helps in diagnosing events leading upto failure.
Signed-off-by: Can Guo <[email protected]> --- drivers/scsi/ufs/Kconfig | 12 +++ drivers/scsi/ufs/ufshcd.c | 214 +++++++++++++++++++++++++++++++++++++++------- drivers/scsi/ufs/ufshcd.h | 24 +++++- 3 files changed, 218 insertions(+), 32 deletions(-) diff --git a/drivers/scsi/ufs/Kconfig b/drivers/scsi/ufs/Kconfig index 0b845ab..afc70cb 100644 --- a/drivers/scsi/ufs/Kconfig +++ b/drivers/scsi/ufs/Kconfig @@ -50,6 +50,18 @@ config SCSI_UFSHCD However, do not compile this as a module if your root file system (the one containing the directory /) is located on a UFS device. +config SCSI_UFSHCD_CMD_LOGGING + bool "Universal Flash Storage host controller driver layer command logging support" + depends on SCSI_UFSHCD + help + This selects the UFS host controller driver layer command logging. + UFS host controller driver layer command logging records all the + command information sent from UFS host controller for debugging + purpose. + + Select this if you want above mentioned debug information captured. + If unsure, say N. + config SCSI_UFSHCD_PCI tristate "PCI bus based UFS Controller support" depends on SCSI_UFSHCD && PCI diff --git a/drivers/scsi/ufs/ufshcd.c b/drivers/scsi/ufs/ufshcd.c index c28c144..f3faa85 100644 --- a/drivers/scsi/ufs/ufshcd.c +++ b/drivers/scsi/ufs/ufshcd.c @@ -91,6 +91,9 @@ /* default delay of autosuspend: 2000 ms */ #define RPM_AUTOSUSPEND_DELAY_MS 2000 +/* Maximum command logging entries */ +#define UFSHCD_MAX_CMD_LOGGING 20 + #define ufshcd_toggle_vreg(_dev, _vreg, _on) \ ({ \ int _ret; \ @@ -328,14 +331,135 @@ static void ufshcd_add_tm_upiu_trace(struct ufs_hba *hba, unsigned int tag, &descp->input_param1); } -static void ufshcd_add_command_trace(struct ufs_hba *hba, - unsigned int tag, const char *str) +static inline void ufshcd_add_command_trace(struct ufs_hba *hba, + struct ufshcd_cmd_log_entry *entry) +{ + if (trace_ufshcd_command_enabled()) { + u32 intr = ufshcd_readl(hba, REG_INTERRUPT_STATUS); + + trace_ufshcd_command(dev_name(hba->dev), entry->str, entry->tag, + entry->doorbell, entry->transfer_len, intr, + entry->lba, entry->cmd_id); + } +} + +#ifdef CONFIG_SCSI_UFSHCD_CMD_LOGGING +static void ufshcd_cmd_log_init(struct ufs_hba *hba) +{ + /* Allocate log entries */ + if (!hba->cmd_log.entries) { + hba->cmd_log.entries = kcalloc(UFSHCD_MAX_CMD_LOGGING, + sizeof(struct ufshcd_cmd_log_entry), GFP_KERNEL); + if (!hba->cmd_log.entries) + return; + dev_dbg(hba->dev, "%s: cmd_log.entries initialized\n", + __func__); + } +} + +static void __ufshcd_cmd_log(struct ufs_hba *hba, char *str, char *cmd_type, + unsigned int tag, u8 cmd_id, u8 idn, u8 lun, + sector_t lba, int transfer_len) +{ + struct ufshcd_cmd_log_entry *entry; + + if (!hba->cmd_log.entries) + return; + + entry = &hba->cmd_log.entries[hba->cmd_log.pos]; + entry->lun = lun; + entry->str = str; + entry->cmd_type = cmd_type; + entry->cmd_id = cmd_id; + entry->lba = lba; + entry->transfer_len = transfer_len; + entry->idn = idn; + entry->doorbell = ufshcd_readl(hba, REG_UTP_TRANSFER_REQ_DOOR_BELL); + entry->tag = tag; + entry->tstamp = ktime_get(); + entry->outstanding_reqs = hba->outstanding_reqs; + entry->seq_num = hba->cmd_log.seq_num; + hba->cmd_log.seq_num++; + hba->cmd_log.pos = (hba->cmd_log.pos + 1) % UFSHCD_MAX_CMD_LOGGING; + + ufshcd_add_command_trace(hba, entry); +} + +static void ufshcd_cmd_log(struct ufs_hba *hba, char *str, char *cmd_type, + unsigned int tag, u8 cmd_id, u8 idn) +{ + __ufshcd_cmd_log(hba, str, cmd_type, tag, cmd_id, idn, 0, 0, 0); +} + +static void ufshcd_dme_cmd_log(struct ufs_hba *hba, char *str, u8 cmd_id) +{ + ufshcd_cmd_log(hba, str, "dme", 0, cmd_id, 0); +} + +static void ufshcd_print_cmd_log(struct ufs_hba *hba) +{ + int i; + int pos; + struct ufshcd_cmd_log_entry *p; + + if (!hba->cmd_log.entries) + return; + + pos = hba->cmd_log.pos; + for (i = 0; i < UFSHCD_MAX_CMD_LOGGING; i++) { + p = &hba->cmd_log.entries[pos]; + pos = (pos + 1) % UFSHCD_MAX_CMD_LOGGING; + + if (ktime_to_us(p->tstamp)) { + pr_err("%s: %s: seq_no=%u lun=0x%x cmd_id=0x%02x lba=0x%llx txfer_len=%d tag=%u, doorbell=0x%x outstanding=0x%x idn=%d time=%lld us\n", + p->cmd_type, p->str, p->seq_num, + p->lun, p->cmd_id, (unsigned long long)p->lba, + p->transfer_len, p->tag, p->doorbell, + p->outstanding_reqs, p->idn, + ktime_to_us(p->tstamp)); + usleep_range(1000, 1100); + } + } +} +#else +static void ufshcd_cmd_log_init(struct ufs_hba *hba) +{ +} + +static void __ufshcd_cmd_log(struct ufs_hba *hba, char *str, char *cmd_type, + unsigned int tag, u8 cmd_id, u8 idn, u8 lun, + sector_t lba, int transfer_len) +{ + struct ufshcd_cmd_log_entry entry; + + entry.str = str; + entry.lba = lba; + entry.cmd_id = cmd_id; + entry.transfer_len = transfer_len; + entry.doorbell = ufshcd_readl(hba, REG_UTP_TRANSFER_REQ_DOOR_BELL); + entry.tag = tag; + + ufshcd_add_command_trace(hba, &entry); +} + +static void ufshcd_dme_cmd_log(struct ufs_hba *hba, char *str, u8 cmd_id) +{ +} + +static void ufshcd_print_cmd_log(struct ufs_hba *hba) +{ +} +#endif + +static inline void ufshcd_cond_add_cmd_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 = &hba->lrb[tag]; - int transfer_len = -1; + char *cmd_type = NULL; + u8 opcode = 0; + u8 cmd_id = 0, idn = 0; + sector_t lba = 0; + int transfer_len = 0; if (!trace_ufshcd_command_enabled()) { /* trace UPIU W/O tracing command */ @@ -361,10 +485,23 @@ static void ufshcd_add_command_trace(struct ufs_hba *hba, } } - 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); + if (lrbp->cmd && ((lrbp->command_type == UTP_CMD_TYPE_SCSI) || + (lrbp->command_type == UTP_CMD_TYPE_UFS_STORAGE))) { + cmd_type = "scsi"; + cmd_id = (u8)(*lrbp->cmd->cmnd); + } else if (lrbp->command_type == UTP_CMD_TYPE_DEV_MANAGE) { + if (hba->dev_cmd.type == DEV_CMD_TYPE_NOP) { + cmd_type = "nop"; + cmd_id = 0; + } else if (hba->dev_cmd.type == DEV_CMD_TYPE_QUERY) { + cmd_type = "query"; + cmd_id = hba->dev_cmd.query.request.upiu_req.opcode; + idn = hba->dev_cmd.query.request.upiu_req.idn; + } + } + + __ufshcd_cmd_log(hba, (char *) str, cmd_type, tag, cmd_id, idn, + lrbp->lun, lba, transfer_len); } static void ufshcd_print_clk_freqs(struct ufs_hba *hba) @@ -1886,7 +2023,8 @@ 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"); + ufshcd_cond_add_cmd_trace(hba, task_tag, + hba->lrb[task_tag].cmd ? "scsi_send" : "dev_cmd_send"); } /** @@ -2001,6 +2139,7 @@ static inline u8 ufshcd_get_upmcrs(struct ufs_hba *hba) hba->active_uic_cmd = uic_cmd; + ufshcd_dme_cmd_log(hba, "dme_send", hba->active_uic_cmd->command); /* Write Args */ ufshcd_writel(hba, uic_cmd->argument1, REG_UIC_COMMAND_ARG_1); ufshcd_writel(hba, uic_cmd->argument2, REG_UIC_COMMAND_ARG_2); @@ -2031,6 +2170,8 @@ static inline u8 ufshcd_get_upmcrs(struct ufs_hba *hba) else ret = -ETIMEDOUT; + ufshcd_dme_cmd_log(hba, "dme_cmpl_1", hba->active_uic_cmd->command); + spin_lock_irqsave(hba->host->host_lock, flags); hba->active_uic_cmd = NULL; spin_unlock_irqrestore(hba->host->host_lock, flags); @@ -3797,11 +3938,14 @@ static int ufshcd_uic_pwr_ctrl(struct ufs_hba *hba, struct uic_command *cmd) cmd->command, status); ret = (status != PWR_OK) ? status : -1; } + ufshcd_dme_cmd_log(hba, "dme_cmpl_2", hba->active_uic_cmd->command); + out: if (ret) { ufshcd_print_host_state(hba); ufshcd_print_pwr_info(hba); ufshcd_print_host_regs(hba); + ufshcd_print_cmd_log(hba); } spin_lock_irqsave(hba->host->host_lock, flags); @@ -4712,6 +4856,7 @@ static void ufshcd_slave_destroy(struct scsi_device *sdev) int result = 0; int scsi_status; int ocs; + bool print_prdt; /* overall command status of utrd */ ocs = ufshcd_get_tr_ocs(lrbp); @@ -4787,8 +4932,11 @@ static void ufshcd_slave_destroy(struct scsi_device *sdev) break; } /* end of switch */ - if (host_byte(result) != DID_OK) - ufshcd_print_trs(hba, 1 << lrbp->task_tag, true); + if (host_byte(result) != DID_OK) { + 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; } @@ -4828,7 +4976,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"); + ufshcd_cond_add_cmd_trace(hba, index, "scsi_cmpl"); result = ufshcd_transfer_rsp_status(hba, lrbp); scsi_dma_unmap(cmd); cmd->result = result; @@ -4841,8 +4989,8 @@ static void __ufshcd_transfer_req_compl(struct ufs_hba *hba, } else if (lrbp->command_type == UTP_CMD_TYPE_DEV_MANAGE || lrbp->command_type == UTP_CMD_TYPE_UFS_STORAGE) { if (hba->dev_cmd.complete) { - ufshcd_add_command_trace(hba, index, - "dev_complete"); + ufshcd_cond_add_cmd_trace(hba, index, + "dev_cmd_cmpl"); complete(hba->dev_cmd.complete); } } @@ -5307,6 +5455,23 @@ static void ufshcd_err_handler(struct work_struct *work) if (!ret) goto skip_err_handling; } + + /* + * 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\n", + __func__, hba->saved_err, hba->saved_uic_err); + spin_unlock_irqrestore(hba->host->host_lock, flags); + ufshcd_print_host_regs(hba); + ufshcd_print_host_state(hba); + ufshcd_print_pwr_info(hba); + ufshcd_print_tmrs(hba, hba->outstanding_tasks); + ufshcd_print_cmd_log(hba); + spin_lock_irqsave(hba->host->host_lock, flags); + } + if ((hba->saved_err & INT_FATAL_ERRORS) || (hba->saved_err & UFSHCD_UIC_HIBERN8_MASK) || ((hba->saved_err & UIC_ERROR) && @@ -5523,21 +5688,6 @@ static void ufshcd_check_errors(struct ufs_hba *hba) hba->ufshcd_state = UFSHCD_STATE_EH_SCHEDULED; - /* dump controller state before resetting */ - if (hba->saved_err & (INT_FATAL_ERRORS | UIC_ERROR)) { - bool pr_prdt = !!(hba->saved_err & - SYSTEM_BUS_FATAL_ERROR); - - dev_err(hba->dev, "%s: saved_err 0x%x saved_uic_err 0x%x\n", - __func__, hba->saved_err, - hba->saved_uic_err); - - ufshcd_print_host_regs(hba); - ufshcd_print_pwr_info(hba); - ufshcd_print_tmrs(hba, hba->outstanding_tasks); - ufshcd_print_trs(hba, hba->outstanding_reqs, - pr_prdt); - } schedule_work(&hba->eh_work); } } @@ -8425,6 +8575,8 @@ int ufshcd_init(struct ufs_hba *hba, void __iomem *mmio_base, unsigned int irq) */ ufshcd_set_ufs_dev_active(hba); + ufshcd_cmd_log_init(hba); + async_schedule(ufshcd_async_scan, hba); ufs_sysfs_add_nodes(hba->dev); diff --git a/drivers/scsi/ufs/ufshcd.h b/drivers/scsi/ufs/ufshcd.h index e0fe247..97cc5b0 100644 --- a/drivers/scsi/ufs/ufshcd.h +++ b/drivers/scsi/ufs/ufshcd.h @@ -414,7 +414,7 @@ struct ufs_init_prefetch { u32 icc_level; }; -#define UFS_ERR_REG_HIST_LENGTH 8 +#define UIC_ERR_REG_HIST_LENGTH 20 /** * struct ufs_err_reg_hist - keeps history of errors * @pos: index to indicate cyclic buffer position @@ -471,6 +471,27 @@ struct ufs_stats { struct ufs_err_reg_hist task_abort; }; +struct ufshcd_cmd_log_entry { + char *str; /* context like "send", "complete" */ + char *cmd_type; /* "scsi", "query", "nop", "dme" */ + u8 lun; + u8 cmd_id; + sector_t lba; + int transfer_len; + u8 idn; /* used only for query idn */ + u32 doorbell; + u32 outstanding_reqs; + u32 seq_num; + unsigned int tag; + ktime_t tstamp; +}; + +struct ufshcd_cmd_log { + struct ufshcd_cmd_log_entry *entries; + int pos; + u32 seq_num; +}; + /** * struct ufs_hba - per adapter private structure * @mmio_base: UFSHCI base register address @@ -692,6 +713,7 @@ struct ufs_hba { struct ufs_pwr_mode_info max_pwr_info; struct ufs_clk_gating clk_gating; + struct ufshcd_cmd_log cmd_log; /* Control to enable/disable host capabilities */ u32 caps; /* Allow dynamic clk gating */ -- The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum, a Linux Foundation Collaborative Project
