[PATCH v1 1/1] scsi: ufs: Add command logging infrastructure

Can Guo
2019-10-23T05:29:46Z

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 <cang@codeaurora.org>
---
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