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

["Winkler, Tomas" <tomas.winkler@intel.com>]

> 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.

Why not use tracepoints, for that?
Thanks
Tomas

> 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