Re: [PATCH v20 1/2] scsi: ufs: Enable power management for wlun

From: Adrian Hunter
Date: Fri Apr 23 2021 - 02:19:06 EST

On 23/04/21 7:23 am, Adrian Hunter wrote:
> On 22/04/21 7:38 pm, Asutosh Das (asd) wrote:
>> On 4/20/2021 12:42 AM, Adrian Hunter wrote:
>>> On 20/04/21 7:15 am, Adrian Hunter wrote:
>>>> On 20/04/21 12:53 am, Asutosh Das (asd) wrote:
>>>>> On 4/19/2021 11:37 AM, Adrian Hunter wrote:
>>>>>> On 16/04/21 10:49 pm, Asutosh Das wrote:
>>>>>>>
>>>>>>> Co-developed-by: Can Guo <cang@xxxxxxxxxxxxxx>
>>>>>>> Signed-off-by: Can Guo <cang@xxxxxxxxxxxxxx>
>>>>>>> Signed-off-by: Asutosh Das <asutoshd@xxxxxxxxxxxxxx>
>>>>>>> ---
>>>>>>
>>>>>> I came across 3 issues while testing.  See comments below.
>>>>>>
>>>>> Hi Adrian
>>>>> Thanks for the comments.
>>>>>> <SNIP>
>>>>>>
>>>>>>> @@ -5794,7 +5839,7 @@ static void ufshcd_err_handling_unprepare(struct ufs_hba *hba)
>>>>>>>        if (ufshcd_is_clkscaling_supported(hba))
>>>>>>>            ufshcd_clk_scaling_suspend(hba, false);
>>>>>>>        ufshcd_clear_ua_wluns(hba);
>>>>>>
>>>>>> ufshcd_clear_ua_wluns() deadlocks trying to clear UFS_UPIU_RPMB_WLUN
>>>>>> if sdev_rpmb is suspended and sdev_ufs_device is suspending.
>>>>>> e.g. ufshcd_wl_suspend() is waiting on host_sem while ufshcd_err_handler()
>>>>>> is running, at which point sdev_rpmb has already suspended.
>>>>>>
>>>>> Umm, I didn't understand this deadlock.
>>>>> When you say, sdev_rpmb is suspended, does it mean runtime_suspended?
>>>>> sdev_ufs_device is suspending - this can't be runtime_suspending, while ufshcd_err_handling_unprepare is running.
>>>>>
>>>>> If you've a call-stack of this deadlock, please can you share it with me. I'll also try to reproduce this.
>>>>
>>>> Yes it is system suspend. sdev_rpmb has suspended, sdev_ufs_device is waiting on host_sem.
>>>> ufshcd_err_handler() holds host_sem. ufshcd_clear_ua_wlun(UFS_UPIU_RPMB_WLUN) gets stuck.
>>>> I will get some call-stacks.
>>>
>> Hi Adrian,
>>
>> Thanks for the call stacks.
>> From the current information, I can't say for sure why it'd get stuck in blk_queue_enter().
>
> I presume SCSI is leaving the RPMB WLUN device runtime suspended and consequently the queue status is RPM_SUSPENDED
>
>>
>> I tried reproducing this issue on my setup yesterday but couldn't.
>> Here's what I did:
>> 1. sdev_rpmb is RPM_SUSPENDED, checked before initiating system suspend
>> 2. sdev_ufs_device is RPM_RESUMED
>> 3. I triggered system suspend (echo mem > /sys/power/state) and scheduled the error handler from ufshcd_wl_suspend().
>> 4. Waited until error handler ran and then ufshcd_wl_suspend() blocks on host_sem.
>> 5. The ufshcd_clear_wa_wlun(UFS_UPIU_RPMB_WLUN) went through fine.
>>
>> Do you've some specific steps to reproduce this or a script, perhaps? If so, please can you share it with me. I will try again.
>
> I was using a device that gives occasional errors, but I will what see I can do.

I have attached 2 patches to reproduce the issue, and the test script I used.
Note it is using down_timeout() so it doesn't lock up completely.
The kernel messages are:

[ 79.385456] ufshcd_wl_suspend: doing ufshcd_schedule_eh_work
[ 79.385511] ufshcd_wl_suspend: sleeping 1000 ms
[ 79.386916] ufshcd_err_handler: start
[ 79.386979] ufshcd_err_handler: got sem
[ 79.387053] ufshcd_err_handling_unprepare: start
[ 79.387302] ufshcd_clear_ua_wluns: before ufshcd_clear_ua_wlun(hba, UFS_UPIU_RPMB_WLUN)
[ 80.435878] ufshcd_wl_suspend: trying to get sem
[ 85.683876] ufshcd_wl_suspend: failed to get sem
[ 85.683993] ufs_device_wlun 0:0:0:49488: PM: failed to suspend async: error -22
[ 85.686901] ufshcd_clear_ua_wluns: after ufshcd_clear_ua_wlun(hba, UFS_UPIU_RPMB_WLUN), ret 0
[ 85.687025] ufshcd_err_handling_unprepare: finish
[ 85.687090] ufshcd_err_handler: finish


>From c21ea993b28bec894f96c0c7b387f9688b01900f Mon Sep 17 00:00:00 2001
From: Adrian Hunter <adrian.hunter@xxxxxxxxx>
Date: Tue, 20 Apr 2021 14:33:03 +0300
Subject: [PATCH 1/2] changes suggested since v20

Signed-off-by: Adrian Hunter <adrian.hunter@xxxxxxxxx>
---
drivers/scsi/ufs/ufshcd.c | 50 ++++++++++-----------------------------
drivers/scsi/ufs/ufshcd.h | 1 +
2 files changed, 14 insertions(+), 37 deletions(-)

diff --git a/drivers/scsi/ufs/ufshcd.c b/drivers/scsi/ufs/ufshcd.c
index eb36f753469d..5be5b2472db0 100644
--- a/drivers/scsi/ufs/ufshcd.c
+++ b/drivers/scsi/ufs/ufshcd.c
@@ -5844,7 +5844,7 @@ static void ufshcd_err_handling_unprepare(struct ufs_hba *hba)

static inline bool ufshcd_err_handling_should_stop(struct ufs_hba *hba)
{
- return (!hba->is_powered || hba->shutting_down ||
+ return (!hba->is_powered || hba->shutting_down || !hba->sdev_ufs_device ||
hba->ufshcd_state == UFSHCD_STATE_ERROR ||
(!(hba->saved_err || hba->saved_uic_err || hba->force_reset ||
ufshcd_is_link_broken(hba))));
@@ -9572,51 +9572,27 @@ void ufshcd_resume_complete(struct device *dev)
{
struct ufs_hba *hba = dev_get_drvdata(dev);

- ufshcd_rpm_put(hba);
+ if (hba->complete_put) {
+ hba->complete_put = false;
+ ufshcd_rpm_put(hba);
+ }
}
EXPORT_SYMBOL_GPL(ufshcd_resume_complete);

int ufshcd_suspend_prepare(struct device *dev)
{
struct ufs_hba *hba = dev_get_drvdata(dev);
- struct device *ufs_dev = &hba->sdev_ufs_device->sdev_gendev;
- enum ufs_dev_pwr_mode spm_pwr_mode;
- enum uic_link_state spm_link_state;
- unsigned long flags;
- bool rpm_state_ok;
-
- /*
- * SCSI assumes that runtime-pm and system-pm for scsi drivers
- * are same. And it doesn't wake up the device for system-suspend
- * if it's runtime suspended. But ufs doesn't follow that.
- * The rpm-lvl and spm-lvl can be different in ufs.
- * However, if the current_{pwr_mode, link_state} is same as the
- * desired_{pwr_mode, link_state}, there's no need to rpm resume
- * the device.
- * Refer ufshcd_resume_complete()
- */
- pm_runtime_get_noresume(ufs_dev);
-
- spin_lock_irqsave(&ufs_dev->power.lock, flags);
-
- spm_pwr_mode = ufs_get_pm_lvl_to_dev_pwr_mode(hba->spm_lvl);
- spm_link_state = ufs_get_pm_lvl_to_link_pwr_state(hba->spm_lvl);
-
- rpm_state_ok = pm_runtime_suspended(ufs_dev) &&
- hba->curr_dev_pwr_mode == spm_pwr_mode &&
- hba->uic_link_state == spm_link_state &&
- !hba->dev_info.b_rpm_dev_flush_capable;
-
- spin_unlock_irqrestore(&ufs_dev->power.lock, flags);
+ int ret;

- if (!rpm_state_ok) {
- int ret = pm_runtime_resume(ufs_dev);
+ if (!hba->sdev_ufs_device)
+ return 0;

- if (ret < 0 && ret != -EACCES) {
- pm_runtime_put(ufs_dev);
- return ret;
- }
+ ret = ufshcd_rpm_get_sync(hba);
+ if (ret < 0 && ret != -EACCES) {
+ ufshcd_rpm_put(hba);
+ return ret;
}
+ hba->complete_put = true;
return 0;
}
EXPORT_SYMBOL_GPL(ufshcd_suspend_prepare);
diff --git a/drivers/scsi/ufs/ufshcd.h b/drivers/scsi/ufs/ufshcd.h
index 3a8dc0dfae05..fd5be083e168 100644
--- a/drivers/scsi/ufs/ufshcd.h
+++ b/drivers/scsi/ufs/ufshcd.h
@@ -850,6 +850,7 @@ struct ufs_hba {
u32 debugfs_ee_rate_limit_ms;
#endif
u32 luns_avail;
+ bool complete_put;
};

/* Returns true if clocks can be gated. Otherwise false */
--
2.25.1

>From 2b9aae51ac5b1f1b13fdab5570dceefbbdc9682b Mon Sep 17 00:00:00 2001
From: Adrian Hunter <adrian.hunter@xxxxxxxxx>
Date: Fri, 23 Apr 2021 08:56:18 +0300
Subject: [PATCH 2/2] instrumentation to reproduce issue

Signed-off-by: Adrian Hunter <adrian.hunter@xxxxxxxxx>
---
drivers/scsi/ufs/ufshcd.c | 26 ++++++++++++++++++++++----
1 file changed, 22 insertions(+), 4 deletions(-)

diff --git a/drivers/scsi/ufs/ufshcd.c b/drivers/scsi/ufs/ufshcd.c
index 5be5b2472db0..32fc4e3991ff 100644
--- a/drivers/scsi/ufs/ufshcd.c
+++ b/drivers/scsi/ufs/ufshcd.c
@@ -5834,12 +5834,14 @@ static void ufshcd_err_handling_prepare(struct ufs_hba *hba)

static void ufshcd_err_handling_unprepare(struct ufs_hba *hba)
{
+ pr_err("%s: start\n", __func__);
ufshcd_scsi_unblock_requests(hba);
ufshcd_release(hba);
if (ufshcd_is_clkscaling_supported(hba))
ufshcd_clk_scaling_suspend(hba, false);
ufshcd_clear_ua_wluns(hba);
ufshcd_rpm_put(hba);
+ pr_err("%s: finish\n", __func__);
}

static inline bool ufshcd_err_handling_should_stop(struct ufs_hba *hba)
@@ -5919,11 +5921,14 @@ static void ufshcd_err_handler(struct work_struct *work)
int tag;
bool needs_reset = false, needs_restore = false;

+ pr_err("%s: start\n", __func__);
+
hba = container_of(work, struct ufs_hba, eh_work);

down(&hba->host_sem);
+ pr_err("%s: got sem\n", __func__);
spin_lock_irqsave(hba->host->host_lock, flags);
- if (ufshcd_err_handling_should_stop(hba)) {
+ if (0 && ufshcd_err_handling_should_stop(hba)) {
if (hba->ufshcd_state != UFSHCD_STATE_ERROR)
hba->ufshcd_state = UFSHCD_STATE_OPERATIONAL;
spin_unlock_irqrestore(hba->host->host_lock, flags);
@@ -6095,6 +6100,7 @@ static void ufshcd_err_handler(struct work_struct *work)
ufshcd_clear_eh_in_progress(hba);
spin_unlock_irqrestore(hba->host->host_lock, flags);
ufshcd_err_handling_unprepare(hba);
+ pr_err("%s: finish\n", __func__);
up(&hba->host_sem);
}

@@ -7872,12 +7878,15 @@ static int ufshcd_clear_ua_wluns(struct ufs_hba *hba)
{
int ret = 0;

- if (!hba->wlun_dev_clr_ua)
+ if (0 && !hba->wlun_dev_clr_ua)
goto out;

ret = ufshcd_clear_ua_wlun(hba, UFS_UPIU_UFS_DEVICE_WLUN);
- if (!ret)
+ if (!ret) {
+ pr_err("%s: before ufshcd_clear_ua_wlun(hba, UFS_UPIU_RPMB_WLUN)\n", __func__);
ret = ufshcd_clear_ua_wlun(hba, UFS_UPIU_RPMB_WLUN);
+ pr_err("%s: after ufshcd_clear_ua_wlun(hba, UFS_UPIU_RPMB_WLUN), ret %d\n", __func__, ret);
+ }
if (!ret)
hba->wlun_dev_clr_ua = false;
out:
@@ -8983,7 +8992,16 @@ static int ufshcd_wl_suspend(struct device *dev)
ktime_t start = ktime_get();

hba = shost_priv(sdev->host);
- down(&hba->host_sem);
+ pr_err("%s: doing ufshcd_schedule_eh_work\n", __func__);
+ ufshcd_schedule_eh_work(hba);
+ pr_err("%s: sleeping 1000 ms\n", __func__);
+ msleep(1000);
+ pr_err("%s: trying to get sem\n", __func__);
+ if (down_timeout(&hba->host_sem, msecs_to_jiffies(5000))) {
+ pr_err("%s: failed to get sem\n", __func__);
+ return -EINVAL;
+ }
+ pr_err("%s: got sem\n", __func__);

if (pm_runtime_suspended(dev))
goto out;
--
2.25.1

Attachment: go.sh
Description: application/shellscript