[PATCH v4 0/2] UFS bug fixes

[PATCH v4 0/2] UFS bug fixes

[Jaegeuk Kim]

Change log from v3:
 - move ufshcd_clear_ua_wluns() after ufshcd_scsi_add_wlus()
 - remove BLK_MQ_REQ_RESERVED for tm tag
 - move IO wait to cover all the non-fatal errors

[PATCH v4 1/2] scsi: ufs: fix livelock of ufshcd_clear_ua_wluns

[Jaegeuk Kim]

When gate_work/ungate_work gets an error during hibern8_enter or exit,
 ufshcd_err_handler()
   ufshcd_scsi_block_requests()
   ufshcd_reset_and_restore()
     ufshcd_clear_ua_wluns() -> stuck
   ufshcd_scsi_unblock_requests()

In order to avoid it, ufshcd_clear_ua_wluns() can be called per recovery flows
such as suspend/resume, link_recovery, and error_handler.

Fixes: 1918651f2d7e ("scsi: ufs: Clear UAC for RPMB after ufshcd resets")
Signed-off-by: Jaegeuk Kim <jaegeuk@kernel.org>
---
 drivers/scsi/ufs/ufshcd.c | 19 ++++++++++++-------
 1 file changed, 12 insertions(+), 7 deletions(-)

diff --git a/drivers/scsi/ufs/ufshcd.c b/drivers/scsi/ufs/ufshcd.c
index bedb822a40a3..e6e7bdf99cd7 100644
--- a/drivers/scsi/ufs/ufshcd.c
+++ b/drivers/scsi/ufs/ufshcd.c
@@ -3996,6 +3996,8 @@ int ufshcd_link_recovery(struct ufs_hba *hba)
 	if (ret)
 		dev_err(hba->dev, "%s: link recovery failed, err %d",
 			__func__, ret);
+	else
+		ufshcd_clear_ua_wluns(hba);
 
 	return ret;
 }
@@ -6003,6 +6005,9 @@ static void ufshcd_err_handler(struct work_struct *work)
 	ufshcd_scsi_unblock_requests(hba);
 	ufshcd_err_handling_unprepare(hba);
 	up(&hba->eh_sem);
+
+	if (!err && needs_reset)
+		ufshcd_clear_ua_wluns(hba);
 }
 
 /**
@@ -6940,14 +6945,11 @@ static int ufshcd_host_reset_and_restore(struct ufs_hba *hba)
 	ufshcd_set_clk_freq(hba, true);
 
 	err = ufshcd_hba_enable(hba);
-	if (err)
-		goto out;
 
 	/* Establish the link again and restore the device */
-	err = ufshcd_probe_hba(hba, false);
 	if (!err)
-		ufshcd_clear_ua_wluns(hba);
-out:
+		err = ufshcd_probe_hba(hba, false);
+
 	if (err)
 		dev_err(hba->dev, "%s: Host init failed %d\n", __func__, err);
 	ufshcd_update_evt_hist(hba, UFS_EVT_HOST_RESET, (u32)err);
@@ -7718,6 +7720,8 @@ static int ufshcd_add_lus(struct ufs_hba *hba)
 	if (ret)
 		goto out;
 
+	ufshcd_clear_ua_wluns(hba);
+
 	/* Initialize devfreq after UFS device is detected */
 	if (ufshcd_is_clkscaling_supported(hba)) {
 		memcpy(&hba->clk_scaling.saved_pwr_info.info,
@@ -7919,8 +7923,6 @@ static void ufshcd_async_scan(void *data, async_cookie_t cookie)
 		pm_runtime_put_sync(hba->dev);
 		ufshcd_exit_clk_scaling(hba);
 		ufshcd_hba_exit(hba);
-	} else {
-		ufshcd_clear_ua_wluns(hba);
 	}
 }
 
@@ -8777,6 +8779,7 @@ static int ufshcd_suspend(struct ufs_hba *hba, enum ufs_pm_op pm_op)
 		ufshcd_resume_clkscaling(hba);
 	hba->clk_gating.is_suspended = false;
 	hba->dev_info.b_rpm_dev_flush_capable = false;
+	ufshcd_clear_ua_wluns(hba);
 	ufshcd_release(hba);
 out:
 	if (hba->dev_info.b_rpm_dev_flush_capable) {
@@ -8887,6 +8890,8 @@ static int ufshcd_resume(struct ufs_hba *hba, enum ufs_pm_op pm_op)
 		cancel_delayed_work(&hba->rpm_dev_flush_recheck_work);
 	}
 
+	ufshcd_clear_ua_wluns(hba);
+
 	/* Schedule clock gating in case of no access to UFS device yet */
 	ufshcd_release(hba);
 
-- 
2.29.2.729.g45daf8777d-goog

[PATCH v4 2/2] scsi: ufs: handle LINERESET with correct tm_cmd

[Jaegeuk Kim]

From: Jaegeuk Kim <jaegeuk@google.com>

This fixes a warning caused by wrong reserve tag usage in __ufshcd_issue_tm_cmd.

WARNING: CPU: 7 PID: 7 at block/blk-core.c:630 blk_get_request+0x68/0x70
WARNING: CPU: 4 PID: 157 at block/blk-mq-tag.c:82 blk_mq_get_tag+0x438/0x46c

And, in ufshcd_err_handler(), we can avoid to send tm_cmd before aborting
outstanding commands by waiting a bit for IO completion like this.

__ufshcd_issue_tm_cmd: task management cmd 0x80 timed-out

Fixes: 69a6c269c097 ("scsi: ufs: Use blk_{get,put}_request() to allocate and free TMFs")
Fixes: 2355b66ed20c ("scsi: ufs: Handle LINERESET indication in err handler")
Signed-off-by: Jaegeuk Kim <jaegeuk@kernel.org>
---
 drivers/scsi/ufs/ufshcd.c | 35 +++++++++++++++++++++++++++++++----
 1 file changed, 31 insertions(+), 4 deletions(-)

diff --git a/drivers/scsi/ufs/ufshcd.c b/drivers/scsi/ufs/ufshcd.c
index e6e7bdf99cd7..340dd5e515dd 100644
--- a/drivers/scsi/ufs/ufshcd.c
+++ b/drivers/scsi/ufs/ufshcd.c
@@ -44,6 +44,9 @@
 /* Query request timeout */
 #define QUERY_REQ_TIMEOUT 1500 /* 1.5 seconds */
 
+/* LINERESET TIME OUT */
+#define LINERESET_IO_TIMEOUT_MS			(30000) /* 30 sec */
+
 /* Task management command timeout */
 #define TM_CMD_TIMEOUT	100 /* msecs */
 
@@ -5826,6 +5829,7 @@ static void ufshcd_err_handler(struct work_struct *work)
 	int err = 0, pmc_err;
 	int tag;
 	bool needs_reset = false, needs_restore = false;
+	ktime_t start;
 
 	hba = container_of(work, struct ufs_hba, eh_work);
 
@@ -5911,6 +5915,22 @@ static void ufshcd_err_handler(struct work_struct *work)
 	}
 
 	hba->silence_err_logs = true;
+
+	/* Wait for IO completion for non-fatal errors to avoid aborting IOs */
+	start = ktime_get();
+	while (hba->outstanding_reqs) {
+		ufshcd_complete_requests(hba);
+		spin_unlock_irqrestore(hba->host->host_lock, flags);
+		schedule();
+		spin_lock_irqsave(hba->host->host_lock, flags);
+		if (ktime_to_ms(ktime_sub(ktime_get(), start)) >
+						LINERESET_IO_TIMEOUT_MS) {
+			dev_err(hba->dev, "%s: timeout, outstanding=0x%lx\n",
+					__func__, hba->outstanding_reqs);
+			break;
+		}
+	}
+
 	/* release lock as clear command might sleep */
 	spin_unlock_irqrestore(hba->host->host_lock, flags);
 	/* Clear pending transfer requests */
@@ -6302,9 +6322,13 @@ static irqreturn_t ufshcd_intr(int irq, void *__hba)
 		intr_status = ufshcd_readl(hba, REG_INTERRUPT_STATUS);
 	}
 
-	if (enabled_intr_status && retval == IRQ_NONE) {
-		dev_err(hba->dev, "%s: Unhandled interrupt 0x%08x\n",
-					__func__, intr_status);
+	if (enabled_intr_status && retval == IRQ_NONE &&
+				!ufshcd_eh_in_progress(hba)) {
+		dev_err(hba->dev, "%s: Unhandled interrupt 0x%08x (0x%08x, 0x%08x)\n",
+					__func__,
+					intr_status,
+					hba->ufs_stats.last_intr_status,
+					enabled_intr_status);
 		ufshcd_dump_regs(hba, 0, UFSHCI_REG_SPACE_SIZE, "host_regs: ");
 	}
 
@@ -6348,7 +6372,10 @@ static int __ufshcd_issue_tm_cmd(struct ufs_hba *hba,
 	 * Even though we use wait_event() which sleeps indefinitely,
 	 * the maximum wait time is bounded by %TM_CMD_TIMEOUT.
 	 */
-	req = blk_get_request(q, REQ_OP_DRV_OUT, BLK_MQ_REQ_RESERVED);
+	req = blk_get_request(q, REQ_OP_DRV_OUT, 0);
+	if (IS_ERR(req))
+		return PTR_ERR(req);
+
 	req->end_io_data = &wait;
 	free_slot = req->tag;
 	WARN_ON_ONCE(free_slot < 0 || free_slot >= hba->nutmrs);
-- 
2.29.2.729.g45daf8777d-goog

Re: [PATCH v4 1/2] scsi: ufs: fix livelock of ufshcd_clear_ua_wluns

[Can Guo]

On 2021-01-07 15:47, Jaegeuk Kim wrote:
> When gate_work/ungate_work gets an error during hibern8_enter or exit,
>  ufshcd_err_handler()
>    ufshcd_scsi_block_requests()
>    ufshcd_reset_and_restore()
>      ufshcd_clear_ua_wluns() -> stuck
>    ufshcd_scsi_unblock_requests()
> 
> In order to avoid it, ufshcd_clear_ua_wluns() can be called per 
> recovery flows
> such as suspend/resume, link_recovery, and error_handler.
> 
> Fixes: 1918651f2d7e ("scsi: ufs: Clear UAC for RPMB after ufshcd 
> resets")
> Signed-off-by: Jaegeuk Kim <jaegeuk@kernel.org>
> ---
>  drivers/scsi/ufs/ufshcd.c | 19 ++++++++++++-------
>  1 file changed, 12 insertions(+), 7 deletions(-)
> 
> diff --git a/drivers/scsi/ufs/ufshcd.c b/drivers/scsi/ufs/ufshcd.c
> index bedb822a40a3..e6e7bdf99cd7 100644
> --- a/drivers/scsi/ufs/ufshcd.c
> +++ b/drivers/scsi/ufs/ufshcd.c
> @@ -3996,6 +3996,8 @@ int ufshcd_link_recovery(struct ufs_hba *hba)
>  	if (ret)
>  		dev_err(hba->dev, "%s: link recovery failed, err %d",
>  			__func__, ret);
> +	else
> +		ufshcd_clear_ua_wluns(hba);
> 
>  	return ret;
>  }
> @@ -6003,6 +6005,9 @@ static void ufshcd_err_handler(struct work_struct 
> *work)
>  	ufshcd_scsi_unblock_requests(hba);
>  	ufshcd_err_handling_unprepare(hba);
>  	up(&hba->eh_sem);
> +
> +	if (!err && needs_reset)
> +		ufshcd_clear_ua_wluns(hba);
>  }
> 
>  /**
> @@ -6940,14 +6945,11 @@ static int
> ufshcd_host_reset_and_restore(struct ufs_hba *hba)
>  	ufshcd_set_clk_freq(hba, true);
> 
>  	err = ufshcd_hba_enable(hba);
> -	if (err)
> -		goto out;
> 
>  	/* Establish the link again and restore the device */
> -	err = ufshcd_probe_hba(hba, false);
>  	if (!err)
> -		ufshcd_clear_ua_wluns(hba);
> -out:
> +		err = ufshcd_probe_hba(hba, false);
> +
>  	if (err)
>  		dev_err(hba->dev, "%s: Host init failed %d\n", __func__, err);
>  	ufshcd_update_evt_hist(hba, UFS_EVT_HOST_RESET, (u32)err);
> @@ -7718,6 +7720,8 @@ static int ufshcd_add_lus(struct ufs_hba *hba)
>  	if (ret)
>  		goto out;
> 
> +	ufshcd_clear_ua_wluns(hba);
> +
>  	/* Initialize devfreq after UFS device is detected */
>  	if (ufshcd_is_clkscaling_supported(hba)) {
>  		memcpy(&hba->clk_scaling.saved_pwr_info.info,
> @@ -7919,8 +7923,6 @@ static void ufshcd_async_scan(void *data,
> async_cookie_t cookie)
>  		pm_runtime_put_sync(hba->dev);
>  		ufshcd_exit_clk_scaling(hba);
>  		ufshcd_hba_exit(hba);
> -	} else {
> -		ufshcd_clear_ua_wluns(hba);
>  	}
>  }
> 
> @@ -8777,6 +8779,7 @@ static int ufshcd_suspend(struct ufs_hba *hba,
> enum ufs_pm_op pm_op)
>  		ufshcd_resume_clkscaling(hba);
>  	hba->clk_gating.is_suspended = false;
>  	hba->dev_info.b_rpm_dev_flush_capable = false;
> +	ufshcd_clear_ua_wluns(hba);
>  	ufshcd_release(hba);
>  out:
>  	if (hba->dev_info.b_rpm_dev_flush_capable) {
> @@ -8887,6 +8890,8 @@ static int ufshcd_resume(struct ufs_hba *hba,
> enum ufs_pm_op pm_op)
>  		cancel_delayed_work(&hba->rpm_dev_flush_recheck_work);
>  	}
> 
> +	ufshcd_clear_ua_wluns(hba);
> +
>  	/* Schedule clock gating in case of no access to UFS device yet */
>  	ufshcd_release(hba);

Reviewed-by: Can Guo <cang@codeaurora.org>

Re: [PATCH v4 2/2] scsi: ufs: handle LINERESET with correct tm_cmd

[Can Guo]

On 2021-01-07 15:47, Jaegeuk Kim wrote:
> From: Jaegeuk Kim <jaegeuk@google.com>
> 
> This fixes a warning caused by wrong reserve tag usage in 
> __ufshcd_issue_tm_cmd.
> 
> WARNING: CPU: 7 PID: 7 at block/blk-core.c:630 
> blk_get_request+0x68/0x70
> WARNING: CPU: 4 PID: 157 at block/blk-mq-tag.c:82 
> blk_mq_get_tag+0x438/0x46c
> 
> And, in ufshcd_err_handler(), we can avoid to send tm_cmd before 
> aborting
> outstanding commands by waiting a bit for IO completion like this.
> 
> __ufshcd_issue_tm_cmd: task management cmd 0x80 timed-out
> 
> Fixes: 69a6c269c097 ("scsi: ufs: Use blk_{get,put}_request() to
> allocate and free TMFs")
> Fixes: 2355b66ed20c ("scsi: ufs: Handle LINERESET indication in err 
> handler")

Hi Jaegeuk,

Sorry, what is wrong with commit 2355b66ed20c? Clearing pending I/O
reqs is a general procedure for handling all non-fatal errors.

Thanks,
Can Guo.

> Signed-off-by: Jaegeuk Kim <jaegeuk@kernel.org>
> ---
>  drivers/scsi/ufs/ufshcd.c | 35 +++++++++++++++++++++++++++++++----
>  1 file changed, 31 insertions(+), 4 deletions(-)
> 
> diff --git a/drivers/scsi/ufs/ufshcd.c b/drivers/scsi/ufs/ufshcd.c
> index e6e7bdf99cd7..340dd5e515dd 100644
> --- a/drivers/scsi/ufs/ufshcd.c
> +++ b/drivers/scsi/ufs/ufshcd.c
> @@ -44,6 +44,9 @@
>  /* Query request timeout */
>  #define QUERY_REQ_TIMEOUT 1500 /* 1.5 seconds */
> 
> +/* LINERESET TIME OUT */
> +#define LINERESET_IO_TIMEOUT_MS			(30000) /* 30 sec */
> +
>  /* Task management command timeout */
>  #define TM_CMD_TIMEOUT	100 /* msecs */
> 
> @@ -5826,6 +5829,7 @@ static void ufshcd_err_handler(struct work_struct 
> *work)
>  	int err = 0, pmc_err;
>  	int tag;
>  	bool needs_reset = false, needs_restore = false;
> +	ktime_t start;
> 
>  	hba = container_of(work, struct ufs_hba, eh_work);
> 
> @@ -5911,6 +5915,22 @@ static void ufshcd_err_handler(struct 
> work_struct *work)
>  	}
> 
>  	hba->silence_err_logs = true;
> +
> +	/* Wait for IO completion for non-fatal errors to avoid aborting IOs 
> */
> +	start = ktime_get();
> +	while (hba->outstanding_reqs) {
> +		ufshcd_complete_requests(hba);
> +		spin_unlock_irqrestore(hba->host->host_lock, flags);
> +		schedule();
> +		spin_lock_irqsave(hba->host->host_lock, flags);
> +		if (ktime_to_ms(ktime_sub(ktime_get(), start)) >
> +						LINERESET_IO_TIMEOUT_MS) {
> +			dev_err(hba->dev, "%s: timeout, outstanding=0x%lx\n",
> +					__func__, hba->outstanding_reqs);
> +			break;
> +		}
> +	}
> +
>  	/* release lock as clear command might sleep */
>  	spin_unlock_irqrestore(hba->host->host_lock, flags);
>  	/* Clear pending transfer requests */
> @@ -6302,9 +6322,13 @@ static irqreturn_t ufshcd_intr(int irq, void 
> *__hba)
>  		intr_status = ufshcd_readl(hba, REG_INTERRUPT_STATUS);
>  	}
> 
> -	if (enabled_intr_status && retval == IRQ_NONE) {
> -		dev_err(hba->dev, "%s: Unhandled interrupt 0x%08x\n",
> -					__func__, intr_status);
> +	if (enabled_intr_status && retval == IRQ_NONE &&
> +				!ufshcd_eh_in_progress(hba)) {
> +		dev_err(hba->dev, "%s: Unhandled interrupt 0x%08x (0x%08x, 
> 0x%08x)\n",
> +					__func__,
> +					intr_status,
> +					hba->ufs_stats.last_intr_status,
> +					enabled_intr_status);
>  		ufshcd_dump_regs(hba, 0, UFSHCI_REG_SPACE_SIZE, "host_regs: ");
>  	}
> 
> @@ -6348,7 +6372,10 @@ static int __ufshcd_issue_tm_cmd(struct ufs_hba 
> *hba,
>  	 * Even though we use wait_event() which sleeps indefinitely,
>  	 * the maximum wait time is bounded by %TM_CMD_TIMEOUT.
>  	 */
> -	req = blk_get_request(q, REQ_OP_DRV_OUT, BLK_MQ_REQ_RESERVED);
> +	req = blk_get_request(q, REQ_OP_DRV_OUT, 0);
> +	if (IS_ERR(req))
> +		return PTR_ERR(req);
> +
>  	req->end_io_data = &wait;
>  	free_slot = req->tag;
>  	WARN_ON_ONCE(free_slot < 0 || free_slot >= hba->nutmrs);

Re: [PATCH v4 2/2] scsi: ufs: handle LINERESET with correct tm_cmd

[Jaegeuk Kim]

On 01/07, Can Guo wrote:
> On 2021-01-07 15:47, Jaegeuk Kim wrote:
> > From: Jaegeuk Kim <jaegeuk@google.com>
> > 
> > This fixes a warning caused by wrong reserve tag usage in
> > __ufshcd_issue_tm_cmd.
> > 
> > WARNING: CPU: 7 PID: 7 at block/blk-core.c:630 blk_get_request+0x68/0x70
> > WARNING: CPU: 4 PID: 157 at block/blk-mq-tag.c:82
> > blk_mq_get_tag+0x438/0x46c
> > 
> > And, in ufshcd_err_handler(), we can avoid to send tm_cmd before
> > aborting
> > outstanding commands by waiting a bit for IO completion like this.
> > 
> > __ufshcd_issue_tm_cmd: task management cmd 0x80 timed-out
> > 
> > Fixes: 69a6c269c097 ("scsi: ufs: Use blk_{get,put}_request() to
> > allocate and free TMFs")
> > Fixes: 2355b66ed20c ("scsi: ufs: Handle LINERESET indication in err
> > handler")
> 
> Hi Jaegeuk,
> 
> Sorry, what is wrong with commit 2355b66ed20c? Clearing pending I/O
> reqs is a general procedure for handling all non-fatal errors.

Without waiting IOs, I hit the below timeout all the time from LINERESET, which
causes UFS stuck permanently, as mentioned in the description.

"__ufshcd_issue_tm_cmd: task management cmd 0x80 timed-out"

> 
> Thanks,
> Can Guo.
> 
> > Signed-off-by: Jaegeuk Kim <jaegeuk@kernel.org>
> > ---
> >  drivers/scsi/ufs/ufshcd.c | 35 +++++++++++++++++++++++++++++++----
> >  1 file changed, 31 insertions(+), 4 deletions(-)
> > 
> > diff --git a/drivers/scsi/ufs/ufshcd.c b/drivers/scsi/ufs/ufshcd.c
> > index e6e7bdf99cd7..340dd5e515dd 100644
> > --- a/drivers/scsi/ufs/ufshcd.c
> > +++ b/drivers/scsi/ufs/ufshcd.c
> > @@ -44,6 +44,9 @@
> >  /* Query request timeout */
> >  #define QUERY_REQ_TIMEOUT 1500 /* 1.5 seconds */
> > 
> > +/* LINERESET TIME OUT */
> > +#define LINERESET_IO_TIMEOUT_MS			(30000) /* 30 sec */
> > +
> >  /* Task management command timeout */
> >  #define TM_CMD_TIMEOUT	100 /* msecs */
> > 
> > @@ -5826,6 +5829,7 @@ static void ufshcd_err_handler(struct work_struct
> > *work)
> >  	int err = 0, pmc_err;
> >  	int tag;
> >  	bool needs_reset = false, needs_restore = false;
> > +	ktime_t start;
> > 
> >  	hba = container_of(work, struct ufs_hba, eh_work);
> > 
> > @@ -5911,6 +5915,22 @@ static void ufshcd_err_handler(struct work_struct
> > *work)
> >  	}
> > 
> >  	hba->silence_err_logs = true;
> > +
> > +	/* Wait for IO completion for non-fatal errors to avoid aborting IOs
> > */
> > +	start = ktime_get();
> > +	while (hba->outstanding_reqs) {
> > +		ufshcd_complete_requests(hba);
> > +		spin_unlock_irqrestore(hba->host->host_lock, flags);
> > +		schedule();
> > +		spin_lock_irqsave(hba->host->host_lock, flags);
> > +		if (ktime_to_ms(ktime_sub(ktime_get(), start)) >
> > +						LINERESET_IO_TIMEOUT_MS) {
> > +			dev_err(hba->dev, "%s: timeout, outstanding=0x%lx\n",
> > +					__func__, hba->outstanding_reqs);
> > +			break;
> > +		}
> > +	}
> > +
> >  	/* release lock as clear command might sleep */
> >  	spin_unlock_irqrestore(hba->host->host_lock, flags);
> >  	/* Clear pending transfer requests */
> > @@ -6302,9 +6322,13 @@ static irqreturn_t ufshcd_intr(int irq, void
> > *__hba)
> >  		intr_status = ufshcd_readl(hba, REG_INTERRUPT_STATUS);
> >  	}
> > 
> > -	if (enabled_intr_status && retval == IRQ_NONE) {
> > -		dev_err(hba->dev, "%s: Unhandled interrupt 0x%08x\n",
> > -					__func__, intr_status);
> > +	if (enabled_intr_status && retval == IRQ_NONE &&
> > +				!ufshcd_eh_in_progress(hba)) {
> > +		dev_err(hba->dev, "%s: Unhandled interrupt 0x%08x (0x%08x,
> > 0x%08x)\n",
> > +					__func__,
> > +					intr_status,
> > +					hba->ufs_stats.last_intr_status,
> > +					enabled_intr_status);
> >  		ufshcd_dump_regs(hba, 0, UFSHCI_REG_SPACE_SIZE, "host_regs: ");
> >  	}
> > 
> > @@ -6348,7 +6372,10 @@ static int __ufshcd_issue_tm_cmd(struct ufs_hba
> > *hba,
> >  	 * Even though we use wait_event() which sleeps indefinitely,
> >  	 * the maximum wait time is bounded by %TM_CMD_TIMEOUT.
> >  	 */
> > -	req = blk_get_request(q, REQ_OP_DRV_OUT, BLK_MQ_REQ_RESERVED);
> > +	req = blk_get_request(q, REQ_OP_DRV_OUT, 0);
> > +	if (IS_ERR(req))
> > +		return PTR_ERR(req);
> > +
> >  	req->end_io_data = &wait;
> >  	free_slot = req->tag;
> >  	WARN_ON_ONCE(free_slot < 0 || free_slot >= hba->nutmrs);

Re: [PATCH v4 2/2] scsi: ufs: handle LINERESET with correct tm_cmd

[Can Guo]

On 2021-01-07 16:07, Jaegeuk Kim wrote:
> On 01/07, Can Guo wrote:
>> On 2021-01-07 15:47, Jaegeuk Kim wrote:
>> > From: Jaegeuk Kim <jaegeuk@google.com>
>> >
>> > This fixes a warning caused by wrong reserve tag usage in
>> > __ufshcd_issue_tm_cmd.
>> >
>> > WARNING: CPU: 7 PID: 7 at block/blk-core.c:630 blk_get_request+0x68/0x70
>> > WARNING: CPU: 4 PID: 157 at block/blk-mq-tag.c:82
>> > blk_mq_get_tag+0x438/0x46c
>> >
>> > And, in ufshcd_err_handler(), we can avoid to send tm_cmd before
>> > aborting
>> > outstanding commands by waiting a bit for IO completion like this.
>> >
>> > __ufshcd_issue_tm_cmd: task management cmd 0x80 timed-out
>> >
>> > Fixes: 69a6c269c097 ("scsi: ufs: Use blk_{get,put}_request() to
>> > allocate and free TMFs")
>> > Fixes: 2355b66ed20c ("scsi: ufs: Handle LINERESET indication in err
>> > handler")
>> 
>> Hi Jaegeuk,
>> 
>> Sorry, what is wrong with commit 2355b66ed20c? Clearing pending I/O
>> reqs is a general procedure for handling all non-fatal errors.
> 
> Without waiting IOs, I hit the below timeout all the time from 
> LINERESET, which
> causes UFS stuck permanently, as mentioned in the description.
> 
> "__ufshcd_issue_tm_cmd: task management cmd 0x80 timed-out"

In that case, ufshcd_try_to_abort_task(), the caller of 
__ufshcd_issue_tm_cmd(),
should return -ETIMEOUT, then err_handler would jump to do a full reset, 
then bail.
I am not sure what gets UFS stuck permanently. Could you please share 
the callstack
if possible? I really want to know what is happening. Thanks.

Regards,
Can Guo.

> 
>> 
>> Thanks,
>> Can Guo.
>> 
>> > Signed-off-by: Jaegeuk Kim <jaegeuk@kernel.org>
>> > ---
>> >  drivers/scsi/ufs/ufshcd.c | 35 +++++++++++++++++++++++++++++++----
>> >  1 file changed, 31 insertions(+), 4 deletions(-)
>> >
>> > diff --git a/drivers/scsi/ufs/ufshcd.c b/drivers/scsi/ufs/ufshcd.c
>> > index e6e7bdf99cd7..340dd5e515dd 100644
>> > --- a/drivers/scsi/ufs/ufshcd.c
>> > +++ b/drivers/scsi/ufs/ufshcd.c
>> > @@ -44,6 +44,9 @@
>> >  /* Query request timeout */
>> >  #define QUERY_REQ_TIMEOUT 1500 /* 1.5 seconds */
>> >
>> > +/* LINERESET TIME OUT */
>> > +#define LINERESET_IO_TIMEOUT_MS			(30000) /* 30 sec */
>> > +
>> >  /* Task management command timeout */
>> >  #define TM_CMD_TIMEOUT	100 /* msecs */
>> >
>> > @@ -5826,6 +5829,7 @@ static void ufshcd_err_handler(struct work_struct
>> > *work)
>> >  	int err = 0, pmc_err;
>> >  	int tag;
>> >  	bool needs_reset = false, needs_restore = false;
>> > +	ktime_t start;
>> >
>> >  	hba = container_of(work, struct ufs_hba, eh_work);
>> >
>> > @@ -5911,6 +5915,22 @@ static void ufshcd_err_handler(struct work_struct
>> > *work)
>> >  	}
>> >
>> >  	hba->silence_err_logs = true;
>> > +
>> > +	/* Wait for IO completion for non-fatal errors to avoid aborting IOs
>> > */
>> > +	start = ktime_get();
>> > +	while (hba->outstanding_reqs) {
>> > +		ufshcd_complete_requests(hba);
>> > +		spin_unlock_irqrestore(hba->host->host_lock, flags);
>> > +		schedule();
>> > +		spin_lock_irqsave(hba->host->host_lock, flags);
>> > +		if (ktime_to_ms(ktime_sub(ktime_get(), start)) >
>> > +						LINERESET_IO_TIMEOUT_MS) {
>> > +			dev_err(hba->dev, "%s: timeout, outstanding=0x%lx\n",
>> > +					__func__, hba->outstanding_reqs);
>> > +			break;
>> > +		}
>> > +	}
>> > +
>> >  	/* release lock as clear command might sleep */
>> >  	spin_unlock_irqrestore(hba->host->host_lock, flags);
>> >  	/* Clear pending transfer requests */
>> > @@ -6302,9 +6322,13 @@ static irqreturn_t ufshcd_intr(int irq, void
>> > *__hba)
>> >  		intr_status = ufshcd_readl(hba, REG_INTERRUPT_STATUS);
>> >  	}
>> >
>> > -	if (enabled_intr_status && retval == IRQ_NONE) {
>> > -		dev_err(hba->dev, "%s: Unhandled interrupt 0x%08x\n",
>> > -					__func__, intr_status);
>> > +	if (enabled_intr_status && retval == IRQ_NONE &&
>> > +				!ufshcd_eh_in_progress(hba)) {
>> > +		dev_err(hba->dev, "%s: Unhandled interrupt 0x%08x (0x%08x,
>> > 0x%08x)\n",
>> > +					__func__,
>> > +					intr_status,
>> > +					hba->ufs_stats.last_intr_status,
>> > +					enabled_intr_status);
>> >  		ufshcd_dump_regs(hba, 0, UFSHCI_REG_SPACE_SIZE, "host_regs: ");
>> >  	}
>> >
>> > @@ -6348,7 +6372,10 @@ static int __ufshcd_issue_tm_cmd(struct ufs_hba
>> > *hba,
>> >  	 * Even though we use wait_event() which sleeps indefinitely,
>> >  	 * the maximum wait time is bounded by %TM_CMD_TIMEOUT.
>> >  	 */
>> > -	req = blk_get_request(q, REQ_OP_DRV_OUT, BLK_MQ_REQ_RESERVED);
>> > +	req = blk_get_request(q, REQ_OP_DRV_OUT, 0);
>> > +	if (IS_ERR(req))
>> > +		return PTR_ERR(req);
>> > +
>> >  	req->end_io_data = &wait;
>> >  	free_slot = req->tag;
>> >  	WARN_ON_ONCE(free_slot < 0 || free_slot >= hba->nutmrs);

Re: [PATCH v4 2/2] scsi: ufs: handle LINERESET with correct tm_cmd

[Jaegeuk Kim]

On 01/07, Can Guo wrote:
> On 2021-01-07 16:07, Jaegeuk Kim wrote:
> > On 01/07, Can Guo wrote:
> > > On 2021-01-07 15:47, Jaegeuk Kim wrote:
> > > > From: Jaegeuk Kim <jaegeuk@google.com>
> > > >
> > > > This fixes a warning caused by wrong reserve tag usage in
> > > > __ufshcd_issue_tm_cmd.
> > > >
> > > > WARNING: CPU: 7 PID: 7 at block/blk-core.c:630 blk_get_request+0x68/0x70
> > > > WARNING: CPU: 4 PID: 157 at block/blk-mq-tag.c:82
> > > > blk_mq_get_tag+0x438/0x46c
> > > >
> > > > And, in ufshcd_err_handler(), we can avoid to send tm_cmd before
> > > > aborting
> > > > outstanding commands by waiting a bit for IO completion like this.
> > > >
> > > > __ufshcd_issue_tm_cmd: task management cmd 0x80 timed-out
> > > >
> > > > Fixes: 69a6c269c097 ("scsi: ufs: Use blk_{get,put}_request() to
> > > > allocate and free TMFs")
> > > > Fixes: 2355b66ed20c ("scsi: ufs: Handle LINERESET indication in err
> > > > handler")
> > > 
> > > Hi Jaegeuk,
> > > 
> > > Sorry, what is wrong with commit 2355b66ed20c? Clearing pending I/O
> > > reqs is a general procedure for handling all non-fatal errors.
> > 
> > Without waiting IOs, I hit the below timeout all the time from
> > LINERESET, which
> > causes UFS stuck permanently, as mentioned in the description.
> > 
> > "__ufshcd_issue_tm_cmd: task management cmd 0x80 timed-out"
> 
> In that case, ufshcd_try_to_abort_task(), the caller of
> __ufshcd_issue_tm_cmd(),
> should return -ETIMEOUT, then err_handler would jump to do a full reset,
> then bail.
> I am not sure what gets UFS stuck permanently. Could you please share the
> callstack
> if possible? I really want to know what is happening. Thanks.

I can't share all the log tho, it entered full reset. While printing out
whole registers, the device was hard reset. Thanks,

> 
> Regards,
> Can Guo.
> 
> > 
> > > 
> > > Thanks,
> > > Can Guo.
> > > 
> > > > Signed-off-by: Jaegeuk Kim <jaegeuk@kernel.org>
> > > > ---
> > > >  drivers/scsi/ufs/ufshcd.c | 35 +++++++++++++++++++++++++++++++----
> > > >  1 file changed, 31 insertions(+), 4 deletions(-)
> > > >
> > > > diff --git a/drivers/scsi/ufs/ufshcd.c b/drivers/scsi/ufs/ufshcd.c
> > > > index e6e7bdf99cd7..340dd5e515dd 100644
> > > > --- a/drivers/scsi/ufs/ufshcd.c
> > > > +++ b/drivers/scsi/ufs/ufshcd.c
> > > > @@ -44,6 +44,9 @@
> > > >  /* Query request timeout */
> > > >  #define QUERY_REQ_TIMEOUT 1500 /* 1.5 seconds */
> > > >
> > > > +/* LINERESET TIME OUT */
> > > > +#define LINERESET_IO_TIMEOUT_MS			(30000) /* 30 sec */
> > > > +
> > > >  /* Task management command timeout */
> > > >  #define TM_CMD_TIMEOUT	100 /* msecs */
> > > >
> > > > @@ -5826,6 +5829,7 @@ static void ufshcd_err_handler(struct work_struct
> > > > *work)
> > > >  	int err = 0, pmc_err;
> > > >  	int tag;
> > > >  	bool needs_reset = false, needs_restore = false;
> > > > +	ktime_t start;
> > > >
> > > >  	hba = container_of(work, struct ufs_hba, eh_work);
> > > >
> > > > @@ -5911,6 +5915,22 @@ static void ufshcd_err_handler(struct work_struct
> > > > *work)
> > > >  	}
> > > >
> > > >  	hba->silence_err_logs = true;
> > > > +
> > > > +	/* Wait for IO completion for non-fatal errors to avoid aborting IOs
> > > > */
> > > > +	start = ktime_get();
> > > > +	while (hba->outstanding_reqs) {
> > > > +		ufshcd_complete_requests(hba);
> > > > +		spin_unlock_irqrestore(hba->host->host_lock, flags);
> > > > +		schedule();
> > > > +		spin_lock_irqsave(hba->host->host_lock, flags);
> > > > +		if (ktime_to_ms(ktime_sub(ktime_get(), start)) >
> > > > +						LINERESET_IO_TIMEOUT_MS) {
> > > > +			dev_err(hba->dev, "%s: timeout, outstanding=0x%lx\n",
> > > > +					__func__, hba->outstanding_reqs);
> > > > +			break;
> > > > +		}
> > > > +	}
> > > > +
> > > >  	/* release lock as clear command might sleep */
> > > >  	spin_unlock_irqrestore(hba->host->host_lock, flags);
> > > >  	/* Clear pending transfer requests */
> > > > @@ -6302,9 +6322,13 @@ static irqreturn_t ufshcd_intr(int irq, void
> > > > *__hba)
> > > >  		intr_status = ufshcd_readl(hba, REG_INTERRUPT_STATUS);
> > > >  	}
> > > >
> > > > -	if (enabled_intr_status && retval == IRQ_NONE) {
> > > > -		dev_err(hba->dev, "%s: Unhandled interrupt 0x%08x\n",
> > > > -					__func__, intr_status);
> > > > +	if (enabled_intr_status && retval == IRQ_NONE &&
> > > > +				!ufshcd_eh_in_progress(hba)) {
> > > > +		dev_err(hba->dev, "%s: Unhandled interrupt 0x%08x (0x%08x,
> > > > 0x%08x)\n",
> > > > +					__func__,
> > > > +					intr_status,
> > > > +					hba->ufs_stats.last_intr_status,
> > > > +					enabled_intr_status);
> > > >  		ufshcd_dump_regs(hba, 0, UFSHCI_REG_SPACE_SIZE, "host_regs: ");
> > > >  	}
> > > >
> > > > @@ -6348,7 +6372,10 @@ static int __ufshcd_issue_tm_cmd(struct ufs_hba
> > > > *hba,
> > > >  	 * Even though we use wait_event() which sleeps indefinitely,
> > > >  	 * the maximum wait time is bounded by %TM_CMD_TIMEOUT.
> > > >  	 */
> > > > -	req = blk_get_request(q, REQ_OP_DRV_OUT, BLK_MQ_REQ_RESERVED);
> > > > +	req = blk_get_request(q, REQ_OP_DRV_OUT, 0);
> > > > +	if (IS_ERR(req))
> > > > +		return PTR_ERR(req);
> > > > +
> > > >  	req->end_io_data = &wait;
> > > >  	free_slot = req->tag;
> > > >  	WARN_ON_ONCE(free_slot < 0 || free_slot >= hba->nutmrs);

Re: [PATCH v4 2/2] scsi: ufs: handle LINERESET with correct tm_cmd

[Can Guo]

On 2021-01-07 16:46, Jaegeuk Kim wrote:
> On 01/07, Can Guo wrote:
>> On 2021-01-07 16:07, Jaegeuk Kim wrote:
>> > On 01/07, Can Guo wrote:
>> > > On 2021-01-07 15:47, Jaegeuk Kim wrote:
>> > > > From: Jaegeuk Kim <jaegeuk@google.com>
>> > > >
>> > > > This fixes a warning caused by wrong reserve tag usage in
>> > > > __ufshcd_issue_tm_cmd.
>> > > >
>> > > > WARNING: CPU: 7 PID: 7 at block/blk-core.c:630 blk_get_request+0x68/0x70
>> > > > WARNING: CPU: 4 PID: 157 at block/blk-mq-tag.c:82
>> > > > blk_mq_get_tag+0x438/0x46c
>> > > >
>> > > > And, in ufshcd_err_handler(), we can avoid to send tm_cmd before
>> > > > aborting
>> > > > outstanding commands by waiting a bit for IO completion like this.
>> > > >
>> > > > __ufshcd_issue_tm_cmd: task management cmd 0x80 timed-out
>> > > >
>> > > > Fixes: 69a6c269c097 ("scsi: ufs: Use blk_{get,put}_request() to
>> > > > allocate and free TMFs")
>> > > > Fixes: 2355b66ed20c ("scsi: ufs: Handle LINERESET indication in err
>> > > > handler")
>> > >
>> > > Hi Jaegeuk,
>> > >
>> > > Sorry, what is wrong with commit 2355b66ed20c? Clearing pending I/O
>> > > reqs is a general procedure for handling all non-fatal errors.
>> >
>> > Without waiting IOs, I hit the below timeout all the time from
>> > LINERESET, which
>> > causes UFS stuck permanently, as mentioned in the description.
>> >
>> > "__ufshcd_issue_tm_cmd: task management cmd 0x80 timed-out"
>> 
>> In that case, ufshcd_try_to_abort_task(), the caller of
>> __ufshcd_issue_tm_cmd(),
>> should return -ETIMEOUT, then err_handler would jump to do a full 
>> reset,
>> then bail.
>> I am not sure what gets UFS stuck permanently. Could you please share 
>> the
>> callstack
>> if possible? I really want to know what is happening. Thanks.
> 
> I can't share all the log tho, it entered full reset. While printing 
> out
> whole registers, the device was hard reset. Thanks,

Hi Jaegeuk,

Entering full reset is expected in this case, which is why I am saying
line-reset handling logic should not be penalized. I think we need to
find out what caused the hard reset but not just adding a delay before
clearing pending reqs, because let's say 3 sec expires and you hit the
same tm req timeout (maybe with a lower possibility), you may still end
up same at the hard reset. You don't need to share all the log, just the
last call stacks before hard reset. Is it a QCOM's platform used in your
case? Can you check the log/dump if NoC error happened?

Thanks.
Can Guo.

> 
>> 
>> Regards,
>> Can Guo.
>> 
>> >
>> > >
>> > > Thanks,
>> > > Can Guo.
>> > >
>> > > > Signed-off-by: Jaegeuk Kim <jaegeuk@kernel.org>
>> > > > ---
>> > > >  drivers/scsi/ufs/ufshcd.c | 35 +++++++++++++++++++++++++++++++----
>> > > >  1 file changed, 31 insertions(+), 4 deletions(-)
>> > > >
>> > > > diff --git a/drivers/scsi/ufs/ufshcd.c b/drivers/scsi/ufs/ufshcd.c
>> > > > index e6e7bdf99cd7..340dd5e515dd 100644
>> > > > --- a/drivers/scsi/ufs/ufshcd.c
>> > > > +++ b/drivers/scsi/ufs/ufshcd.c
>> > > > @@ -44,6 +44,9 @@
>> > > >  /* Query request timeout */
>> > > >  #define QUERY_REQ_TIMEOUT 1500 /* 1.5 seconds */
>> > > >
>> > > > +/* LINERESET TIME OUT */
>> > > > +#define LINERESET_IO_TIMEOUT_MS			(30000) /* 30 sec */
>> > > > +
>> > > >  /* Task management command timeout */
>> > > >  #define TM_CMD_TIMEOUT	100 /* msecs */
>> > > >
>> > > > @@ -5826,6 +5829,7 @@ static void ufshcd_err_handler(struct work_struct
>> > > > *work)
>> > > >  	int err = 0, pmc_err;
>> > > >  	int tag;
>> > > >  	bool needs_reset = false, needs_restore = false;
>> > > > +	ktime_t start;
>> > > >
>> > > >  	hba = container_of(work, struct ufs_hba, eh_work);
>> > > >
>> > > > @@ -5911,6 +5915,22 @@ static void ufshcd_err_handler(struct work_struct
>> > > > *work)
>> > > >  	}
>> > > >
>> > > >  	hba->silence_err_logs = true;
>> > > > +
>> > > > +	/* Wait for IO completion for non-fatal errors to avoid aborting IOs
>> > > > */
>> > > > +	start = ktime_get();
>> > > > +	while (hba->outstanding_reqs) {
>> > > > +		ufshcd_complete_requests(hba);
>> > > > +		spin_unlock_irqrestore(hba->host->host_lock, flags);
>> > > > +		schedule();
>> > > > +		spin_lock_irqsave(hba->host->host_lock, flags);
>> > > > +		if (ktime_to_ms(ktime_sub(ktime_get(), start)) >
>> > > > +						LINERESET_IO_TIMEOUT_MS) {
>> > > > +			dev_err(hba->dev, "%s: timeout, outstanding=0x%lx\n",
>> > > > +					__func__, hba->outstanding_reqs);
>> > > > +			break;
>> > > > +		}
>> > > > +	}
>> > > > +
>> > > >  	/* release lock as clear command might sleep */
>> > > >  	spin_unlock_irqrestore(hba->host->host_lock, flags);
>> > > >  	/* Clear pending transfer requests */
>> > > > @@ -6302,9 +6322,13 @@ static irqreturn_t ufshcd_intr(int irq, void
>> > > > *__hba)
>> > > >  		intr_status = ufshcd_readl(hba, REG_INTERRUPT_STATUS);
>> > > >  	}
>> > > >
>> > > > -	if (enabled_intr_status && retval == IRQ_NONE) {
>> > > > -		dev_err(hba->dev, "%s: Unhandled interrupt 0x%08x\n",
>> > > > -					__func__, intr_status);
>> > > > +	if (enabled_intr_status && retval == IRQ_NONE &&
>> > > > +				!ufshcd_eh_in_progress(hba)) {
>> > > > +		dev_err(hba->dev, "%s: Unhandled interrupt 0x%08x (0x%08x,
>> > > > 0x%08x)\n",
>> > > > +					__func__,
>> > > > +					intr_status,
>> > > > +					hba->ufs_stats.last_intr_status,
>> > > > +					enabled_intr_status);
>> > > >  		ufshcd_dump_regs(hba, 0, UFSHCI_REG_SPACE_SIZE, "host_regs: ");
>> > > >  	}
>> > > >
>> > > > @@ -6348,7 +6372,10 @@ static int __ufshcd_issue_tm_cmd(struct ufs_hba
>> > > > *hba,
>> > > >  	 * Even though we use wait_event() which sleeps indefinitely,
>> > > >  	 * the maximum wait time is bounded by %TM_CMD_TIMEOUT.
>> > > >  	 */
>> > > > -	req = blk_get_request(q, REQ_OP_DRV_OUT, BLK_MQ_REQ_RESERVED);
>> > > > +	req = blk_get_request(q, REQ_OP_DRV_OUT, 0);
>> > > > +	if (IS_ERR(req))
>> > > > +		return PTR_ERR(req);
>> > > > +
>> > > >  	req->end_io_data = &wait;
>> > > >  	free_slot = req->tag;
>> > > >  	WARN_ON_ONCE(free_slot < 0 || free_slot >= hba->nutmrs);

Re: [PATCH v4 2/2] scsi: ufs: handle LINERESET with correct tm_cmd

[Can Guo]

[-- Attachment #1: Type: text/plain, Size: 6415 bytes --]

On 2021-01-07 16:58, Can Guo wrote:
> On 2021-01-07 16:46, Jaegeuk Kim wrote:
>> On 01/07, Can Guo wrote:
>>> On 2021-01-07 16:07, Jaegeuk Kim wrote:
>>> > On 01/07, Can Guo wrote:
>>> > > On 2021-01-07 15:47, Jaegeuk Kim wrote:
>>> > > > From: Jaegeuk Kim <jaegeuk@google.com>
>>> > > >
>>> > > > This fixes a warning caused by wrong reserve tag usage in
>>> > > > __ufshcd_issue_tm_cmd.
>>> > > >
>>> > > > WARNING: CPU: 7 PID: 7 at block/blk-core.c:630 blk_get_request+0x68/0x70
>>> > > > WARNING: CPU: 4 PID: 157 at block/blk-mq-tag.c:82
>>> > > > blk_mq_get_tag+0x438/0x46c
>>> > > >
>>> > > > And, in ufshcd_err_handler(), we can avoid to send tm_cmd before
>>> > > > aborting
>>> > > > outstanding commands by waiting a bit for IO completion like this.
>>> > > >
>>> > > > __ufshcd_issue_tm_cmd: task management cmd 0x80 timed-out
>>> > > >
>>> > > > Fixes: 69a6c269c097 ("scsi: ufs: Use blk_{get,put}_request() to
>>> > > > allocate and free TMFs")
>>> > > > Fixes: 2355b66ed20c ("scsi: ufs: Handle LINERESET indication in err
>>> > > > handler")
>>> > >
>>> > > Hi Jaegeuk,
>>> > >
>>> > > Sorry, what is wrong with commit 2355b66ed20c? Clearing pending I/O
>>> > > reqs is a general procedure for handling all non-fatal errors.
>>> >
>>> > Without waiting IOs, I hit the below timeout all the time from
>>> > LINERESET, which
>>> > causes UFS stuck permanently, as mentioned in the description.
>>> >
>>> > "__ufshcd_issue_tm_cmd: task management cmd 0x80 timed-out"
>>> 
>>> In that case, ufshcd_try_to_abort_task(), the caller of
>>> __ufshcd_issue_tm_cmd(),
>>> should return -ETIMEOUT, then err_handler would jump to do a full 
>>> reset,
>>> then bail.
>>> I am not sure what gets UFS stuck permanently. Could you please share 
>>> the
>>> callstack
>>> if possible? I really want to know what is happening. Thanks.
>> 
>> I can't share all the log tho, it entered full reset. While printing 
>> out
>> whole registers, the device was hard reset. Thanks,
> 
> Hi Jaegeuk,
> 
> Entering full reset is expected in this case, which is why I am saying
> line-reset handling logic should not be penalized. I think we need to
> find out what caused the hard reset but not just adding a delay before
> clearing pending reqs, because let's say 3 sec expires and you hit the
> same tm req timeout (maybe with a lower possibility), you may still end
> up same at the hard reset. You don't need to share all the log, just 
> the
> last call stacks before hard reset. Is it a QCOM's platform used in 
> your
> case? Can you check the log/dump if NoC error happened?
> 
> Thanks.
> Can Guo.
> 

Hi Jaegeuk,

If it is QCOM's platform, what you described looks like a known issue
which we have already fixed in downstream. Please try attached patch.
If not, please ignore it.

Thanks,
Can Guo.

>> 
>>> 
>>> Regards,
>>> Can Guo.
>>> 
>>> >
>>> > >
>>> > > Thanks,
>>> > > Can Guo.
>>> > >
>>> > > > Signed-off-by: Jaegeuk Kim <jaegeuk@kernel.org>
>>> > > > ---
>>> > > >  drivers/scsi/ufs/ufshcd.c | 35 +++++++++++++++++++++++++++++++----
>>> > > >  1 file changed, 31 insertions(+), 4 deletions(-)
>>> > > >
>>> > > > diff --git a/drivers/scsi/ufs/ufshcd.c b/drivers/scsi/ufs/ufshcd.c
>>> > > > index e6e7bdf99cd7..340dd5e515dd 100644
>>> > > > --- a/drivers/scsi/ufs/ufshcd.c
>>> > > > +++ b/drivers/scsi/ufs/ufshcd.c
>>> > > > @@ -44,6 +44,9 @@
>>> > > >  /* Query request timeout */
>>> > > >  #define QUERY_REQ_TIMEOUT 1500 /* 1.5 seconds */
>>> > > >
>>> > > > +/* LINERESET TIME OUT */
>>> > > > +#define LINERESET_IO_TIMEOUT_MS			(30000) /* 30 sec */
>>> > > > +
>>> > > >  /* Task management command timeout */
>>> > > >  #define TM_CMD_TIMEOUT	100 /* msecs */
>>> > > >
>>> > > > @@ -5826,6 +5829,7 @@ static void ufshcd_err_handler(struct work_struct
>>> > > > *work)
>>> > > >  	int err = 0, pmc_err;
>>> > > >  	int tag;
>>> > > >  	bool needs_reset = false, needs_restore = false;
>>> > > > +	ktime_t start;
>>> > > >
>>> > > >  	hba = container_of(work, struct ufs_hba, eh_work);
>>> > > >
>>> > > > @@ -5911,6 +5915,22 @@ static void ufshcd_err_handler(struct work_struct
>>> > > > *work)
>>> > > >  	}
>>> > > >
>>> > > >  	hba->silence_err_logs = true;
>>> > > > +
>>> > > > +	/* Wait for IO completion for non-fatal errors to avoid aborting IOs
>>> > > > */
>>> > > > +	start = ktime_get();
>>> > > > +	while (hba->outstanding_reqs) {
>>> > > > +		ufshcd_complete_requests(hba);
>>> > > > +		spin_unlock_irqrestore(hba->host->host_lock, flags);
>>> > > > +		schedule();
>>> > > > +		spin_lock_irqsave(hba->host->host_lock, flags);
>>> > > > +		if (ktime_to_ms(ktime_sub(ktime_get(), start)) >
>>> > > > +						LINERESET_IO_TIMEOUT_MS) {
>>> > > > +			dev_err(hba->dev, "%s: timeout, outstanding=0x%lx\n",
>>> > > > +					__func__, hba->outstanding_reqs);
>>> > > > +			break;
>>> > > > +		}
>>> > > > +	}
>>> > > > +
>>> > > >  	/* release lock as clear command might sleep */
>>> > > >  	spin_unlock_irqrestore(hba->host->host_lock, flags);
>>> > > >  	/* Clear pending transfer requests */
>>> > > > @@ -6302,9 +6322,13 @@ static irqreturn_t ufshcd_intr(int irq, void
>>> > > > *__hba)
>>> > > >  		intr_status = ufshcd_readl(hba, REG_INTERRUPT_STATUS);
>>> > > >  	}
>>> > > >
>>> > > > -	if (enabled_intr_status && retval == IRQ_NONE) {
>>> > > > -		dev_err(hba->dev, "%s: Unhandled interrupt 0x%08x\n",
>>> > > > -					__func__, intr_status);
>>> > > > +	if (enabled_intr_status && retval == IRQ_NONE &&
>>> > > > +				!ufshcd_eh_in_progress(hba)) {
>>> > > > +		dev_err(hba->dev, "%s: Unhandled interrupt 0x%08x (0x%08x,
>>> > > > 0x%08x)\n",
>>> > > > +					__func__,
>>> > > > +					intr_status,
>>> > > > +					hba->ufs_stats.last_intr_status,
>>> > > > +					enabled_intr_status);
>>> > > >  		ufshcd_dump_regs(hba, 0, UFSHCI_REG_SPACE_SIZE, "host_regs: ");
>>> > > >  	}
>>> > > >
>>> > > > @@ -6348,7 +6372,10 @@ static int __ufshcd_issue_tm_cmd(struct ufs_hba
>>> > > > *hba,
>>> > > >  	 * Even though we use wait_event() which sleeps indefinitely,
>>> > > >  	 * the maximum wait time is bounded by %TM_CMD_TIMEOUT.
>>> > > >  	 */
>>> > > > -	req = blk_get_request(q, REQ_OP_DRV_OUT, BLK_MQ_REQ_RESERVED);
>>> > > > +	req = blk_get_request(q, REQ_OP_DRV_OUT, 0);
>>> > > > +	if (IS_ERR(req))
>>> > > > +		return PTR_ERR(req);
>>> > > > +
>>> > > >  	req->end_io_data = &wait;
>>> > > >  	free_slot = req->tag;
>>> > > >  	WARN_ON_ONCE(free_slot < 0 || free_slot >= hba->nutmrs);

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: 0001-scsi-ufs-qcom-Disable-interrupt-in-reset-path.patch --]
[-- Type: text/x-diff; name=0001-scsi-ufs-qcom-Disable-interrupt-in-reset-path.patch, Size: 1298 bytes --]

From b50e595a80e9e31c2f9744439b3bdd986e9433ea Mon Sep 17 00:00:00 2001
From: Can Guo <cang@codeaurora.org>
Date: Thu, 7 Jan 2021 01:07:12 -0800
Subject: [PATCH] scsi: ufs-qcom: Disable interrupt in reset path

Disable interrupt in reset path

Signed-off-by: Can Guo <cang@codeaurora.org>

diff --git a/drivers/scsi/ufs/ufs-qcom.c b/drivers/scsi/ufs/ufs-qcom.c
index 2206b1e..e55201f 100644
--- a/drivers/scsi/ufs/ufs-qcom.c
+++ b/drivers/scsi/ufs/ufs-qcom.c
@@ -253,12 +253,17 @@ static int ufs_qcom_host_reset(struct ufs_hba *hba)
 {
 	int ret = 0;
 	struct ufs_qcom_host *host = ufshcd_get_variant(hba);
+	bool reenable_intr = false;
 
 	if (!host->core_reset) {
 		dev_warn(hba->dev, "%s: reset control not set\n", __func__);
 		goto out;
 	}
 
+	reenable_intr = hba->is_irq_enabled;
+	disable_irq(hba->irq);
+	hba->is_irq_enabled = false;
+
 	ret = reset_control_assert(host->core_reset);
 	if (ret) {
 		dev_err(hba->dev, "%s: core_reset assert failed, err = %d\n",
@@ -280,6 +285,11 @@ static int ufs_qcom_host_reset(struct ufs_hba *hba)
 
 	usleep_range(1000, 1100);
 
+	if (reenable_intr) {
+		enable_irq(hba->irq);
+		hba->is_irq_enabled = true;
+	}
+
 out:
 	return ret;
 }
-- 
Qualcomm Innovation Center, Inc. is a member of Code Aurora Forum, a Linux Foundation Collaborative Project.

Re: [PATCH v4 2/2] scsi: ufs: handle LINERESET with correct tm_cmd

[Jaegeuk Kim]

On 01/07, Can Guo wrote:
> On 2021-01-07 16:46, Jaegeuk Kim wrote:
> > On 01/07, Can Guo wrote:
> > > On 2021-01-07 16:07, Jaegeuk Kim wrote:
> > > > On 01/07, Can Guo wrote:
> > > > > On 2021-01-07 15:47, Jaegeuk Kim wrote:
> > > > > > From: Jaegeuk Kim <jaegeuk@google.com>
> > > > > >
> > > > > > This fixes a warning caused by wrong reserve tag usage in
> > > > > > __ufshcd_issue_tm_cmd.
> > > > > >
> > > > > > WARNING: CPU: 7 PID: 7 at block/blk-core.c:630 blk_get_request+0x68/0x70
> > > > > > WARNING: CPU: 4 PID: 157 at block/blk-mq-tag.c:82
> > > > > > blk_mq_get_tag+0x438/0x46c
> > > > > >
> > > > > > And, in ufshcd_err_handler(), we can avoid to send tm_cmd before
> > > > > > aborting
> > > > > > outstanding commands by waiting a bit for IO completion like this.
> > > > > >
> > > > > > __ufshcd_issue_tm_cmd: task management cmd 0x80 timed-out
> > > > > >
> > > > > > Fixes: 69a6c269c097 ("scsi: ufs: Use blk_{get,put}_request() to
> > > > > > allocate and free TMFs")
> > > > > > Fixes: 2355b66ed20c ("scsi: ufs: Handle LINERESET indication in err
> > > > > > handler")
> > > > >
> > > > > Hi Jaegeuk,
> > > > >
> > > > > Sorry, what is wrong with commit 2355b66ed20c? Clearing pending I/O
> > > > > reqs is a general procedure for handling all non-fatal errors.
> > > >
> > > > Without waiting IOs, I hit the below timeout all the time from
> > > > LINERESET, which
> > > > causes UFS stuck permanently, as mentioned in the description.
> > > >
> > > > "__ufshcd_issue_tm_cmd: task management cmd 0x80 timed-out"
> > > 
> > > In that case, ufshcd_try_to_abort_task(), the caller of
> > > __ufshcd_issue_tm_cmd(),
> > > should return -ETIMEOUT, then err_handler would jump to do a full
> > > reset,
> > > then bail.
> > > I am not sure what gets UFS stuck permanently. Could you please
> > > share the
> > > callstack
> > > if possible? I really want to know what is happening. Thanks.
> > 
> > I can't share all the log tho, it entered full reset. While printing out
> > whole registers, the device was hard reset. Thanks,
> 
> Hi Jaegeuk,
> 
> Entering full reset is expected in this case, which is why I am saying
> line-reset handling logic should not be penalized. I think we need to
> find out what caused the hard reset but not just adding a delay before
> clearing pending reqs, because let's say 3 sec expires and you hit the
> same tm req timeout (maybe with a lower possibility), you may still end
> up same at the hard reset. You don't need to share all the log, just the
> last call stacks before hard reset. Is it a QCOM's platform used in your
> case? Can you check the log/dump if NoC error happened?

Hi Can,

I figured out it is caused by verbose kernel logs printed in terminal.
I posted v5, so could you please review it?

Thanks,

> 
> Thanks.
> Can Guo.
> 
> > 
> > > 
> > > Regards,
> > > Can Guo.
> > > 
> > > >
> > > > >
> > > > > Thanks,
> > > > > Can Guo.
> > > > >
> > > > > > Signed-off-by: Jaegeuk Kim <jaegeuk@kernel.org>
> > > > > > ---
> > > > > >  drivers/scsi/ufs/ufshcd.c | 35 +++++++++++++++++++++++++++++++----
> > > > > >  1 file changed, 31 insertions(+), 4 deletions(-)
> > > > > >
> > > > > > diff --git a/drivers/scsi/ufs/ufshcd.c b/drivers/scsi/ufs/ufshcd.c
> > > > > > index e6e7bdf99cd7..340dd5e515dd 100644
> > > > > > --- a/drivers/scsi/ufs/ufshcd.c
> > > > > > +++ b/drivers/scsi/ufs/ufshcd.c
> > > > > > @@ -44,6 +44,9 @@
> > > > > >  /* Query request timeout */
> > > > > >  #define QUERY_REQ_TIMEOUT 1500 /* 1.5 seconds */
> > > > > >
> > > > > > +/* LINERESET TIME OUT */
> > > > > > +#define LINERESET_IO_TIMEOUT_MS			(30000) /* 30 sec */
> > > > > > +
> > > > > >  /* Task management command timeout */
> > > > > >  #define TM_CMD_TIMEOUT	100 /* msecs */
> > > > > >
> > > > > > @@ -5826,6 +5829,7 @@ static void ufshcd_err_handler(struct work_struct
> > > > > > *work)
> > > > > >  	int err = 0, pmc_err;
> > > > > >  	int tag;
> > > > > >  	bool needs_reset = false, needs_restore = false;
> > > > > > +	ktime_t start;
> > > > > >
> > > > > >  	hba = container_of(work, struct ufs_hba, eh_work);
> > > > > >
> > > > > > @@ -5911,6 +5915,22 @@ static void ufshcd_err_handler(struct work_struct
> > > > > > *work)
> > > > > >  	}
> > > > > >
> > > > > >  	hba->silence_err_logs = true;
> > > > > > +
> > > > > > +	/* Wait for IO completion for non-fatal errors to avoid aborting IOs
> > > > > > */
> > > > > > +	start = ktime_get();
> > > > > > +	while (hba->outstanding_reqs) {
> > > > > > +		ufshcd_complete_requests(hba);
> > > > > > +		spin_unlock_irqrestore(hba->host->host_lock, flags);
> > > > > > +		schedule();
> > > > > > +		spin_lock_irqsave(hba->host->host_lock, flags);
> > > > > > +		if (ktime_to_ms(ktime_sub(ktime_get(), start)) >
> > > > > > +						LINERESET_IO_TIMEOUT_MS) {
> > > > > > +			dev_err(hba->dev, "%s: timeout, outstanding=0x%lx\n",
> > > > > > +					__func__, hba->outstanding_reqs);
> > > > > > +			break;
> > > > > > +		}
> > > > > > +	}
> > > > > > +
> > > > > >  	/* release lock as clear command might sleep */
> > > > > >  	spin_unlock_irqrestore(hba->host->host_lock, flags);
> > > > > >  	/* Clear pending transfer requests */
> > > > > > @@ -6302,9 +6322,13 @@ static irqreturn_t ufshcd_intr(int irq, void
> > > > > > *__hba)
> > > > > >  		intr_status = ufshcd_readl(hba, REG_INTERRUPT_STATUS);
> > > > > >  	}
> > > > > >
> > > > > > -	if (enabled_intr_status && retval == IRQ_NONE) {
> > > > > > -		dev_err(hba->dev, "%s: Unhandled interrupt 0x%08x\n",
> > > > > > -					__func__, intr_status);
> > > > > > +	if (enabled_intr_status && retval == IRQ_NONE &&
> > > > > > +				!ufshcd_eh_in_progress(hba)) {
> > > > > > +		dev_err(hba->dev, "%s: Unhandled interrupt 0x%08x (0x%08x,
> > > > > > 0x%08x)\n",
> > > > > > +					__func__,
> > > > > > +					intr_status,
> > > > > > +					hba->ufs_stats.last_intr_status,
> > > > > > +					enabled_intr_status);
> > > > > >  		ufshcd_dump_regs(hba, 0, UFSHCI_REG_SPACE_SIZE, "host_regs: ");
> > > > > >  	}
> > > > > >
> > > > > > @@ -6348,7 +6372,10 @@ static int __ufshcd_issue_tm_cmd(struct ufs_hba
> > > > > > *hba,
> > > > > >  	 * Even though we use wait_event() which sleeps indefinitely,
> > > > > >  	 * the maximum wait time is bounded by %TM_CMD_TIMEOUT.
> > > > > >  	 */
> > > > > > -	req = blk_get_request(q, REQ_OP_DRV_OUT, BLK_MQ_REQ_RESERVED);
> > > > > > +	req = blk_get_request(q, REQ_OP_DRV_OUT, 0);
> > > > > > +	if (IS_ERR(req))
> > > > > > +		return PTR_ERR(req);
> > > > > > +
> > > > > >  	req->end_io_data = &wait;
> > > > > >  	free_slot = req->tag;
> > > > > >  	WARN_ON_ONCE(free_slot < 0 || free_slot >= hba->nutmrs);