| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Message-ID: <2bd90336-18a9-9acd-5abb-5b52b27fc535@codeaurora.org>
Date: Tue, 9 Mar 2021 19:04:34 -0800
From: "Asutosh Das (asd)" <asutoshd@...eaurora.org>
To: Alan Stern <stern@...land.harvard.edu>,
Bart Van Assche <bvanassche@....org>,
Adrian Hunter <adrian.hunter@...el.com>
Cc: "Rafael J. Wysocki" <rafael@...nel.org>, cang@...eaurora.org,
"Martin K. Petersen" <martin.petersen@...cle.com>,
"open list:TARGET SUBSYSTEM" <linux-scsi@...r.kernel.org>,
linux-arm-msm <linux-arm-msm@...r.kernel.org>,
Alim Akhtar <alim.akhtar@...sung.com>,
Avri Altman <avri.altman@....com>,
"James E.J. Bottomley" <jejb@...ux.ibm.com>,
Krzysztof Kozlowski <krzk@...nel.org>,
Stanley Chu <stanley.chu@...iatek.com>,
Andy Gross <agross@...nel.org>,
Bjorn Andersson <bjorn.andersson@...aro.org>,
Steven Rostedt <rostedt@...dmis.org>,
Ingo Molnar <mingo@...hat.com>,
Matthias Brugger <matthias.bgg@...il.com>,
Kiwoong Kim <kwmad.kim@...sung.com>,
Bean Huo <beanhuo@...ron.com>,
Lee Jones <lee.jones@...aro.org>,
Wei Yongjun <weiyongjun1@...wei.com>,
Dinghao Liu <dinghao.liu@....edu.cn>,
"Gustavo A. R. Silva" <gustavoars@...nel.org>,
Tomas Winkler <tomas.winkler@...el.com>,
Jaegeuk Kim <jaegeuk@...nel.org>,
Satya Tangirala <satyat@...gle.com>,
open list <linux-kernel@...r.kernel.org>,
"moderated list:ARM/SAMSUNG S3C, S5P AND EXYNOS ARM ARCHITECTURES"
<linux-arm-kernel@...ts.infradead.org>,
"open list:ARM/SAMSUNG S3C, S5P AND EXYNOS ARM ARCHITECTURES"
<linux-samsung-soc@...r.kernel.org>,
"moderated list:UNIVERSAL FLASH STORAGE HOST CONTROLLER DRIVER..."
<linux-mediatek@...ts.infradead.org>,
Linux-PM mailing list <linux-pm@...r.kernel.org>
Subject: Re: [PATCH v10 1/2] scsi: ufs: Enable power management for wlun
On 3/9/2021 7:56 AM, Asutosh Das (asd) wrote:
> On 3/8/2021 9:17 AM, Rafael J. Wysocki wrote:
>> On Mon, Mar 8, 2021 at 5:21 PM Rafael J. Wysocki <rafael@...nel.org>
>> wrote:
>>>
>>> On Sat, Mar 6, 2021 at 5:17 PM Alan Stern <stern@...land.harvard.edu>
>>> wrote:
>>>>
>>>> On Fri, Mar 05, 2021 at 06:54:24PM -0800, Asutosh Das (asd) wrote:
>>>>
>>>>> Now during my testing I see a weird issue sometimes (1 in 7).
>>>>> Scenario - bootups
>>>>>
>>>>> Issue:
>>>>> The supplier 'ufs_device_wlun 0:0:0:49488' goes into runtime
>>>>> suspend even
>>>>> when one/more of its consumers are in RPM_ACTIVE state.
>>>>>
>>>>> *Log:
>>>>> [ 10.056379][ T206] sd 0:0:0:1: [sdb] Synchronizing SCSI cache
>>>>> [ 10.062497][ T113] sd 0:0:0:5: [sdf] Synchronizing SCSI cache
>>>>> [ 10.356600][ T32] sd 0:0:0:7: [sdh] Synchronizing SCSI cache
>>>>> [ 10.362944][ T174] sd 0:0:0:3: [sdd] Synchronizing SCSI cache
>>>>> [ 10.696627][ T83] sd 0:0:0:2: [sdc] Synchronizing SCSI cache
>>>>> [ 10.704562][ T170] sd 0:0:0:6: [sdg] Synchronizing SCSI cache
>>>>> [ 10.980602][ T5] sd 0:0:0:0: [sda] Synchronizing SCSI cache
>>>>>
>>>>> /** Printing all the consumer nodes of supplier **/
>>>>> [ 10.987327][ T5] ufs_device_wlun 0:0:0:49488: usage-count @
>>>>> suspend: 0
>>>>> <-- this is the usage_count
>>>>> [ 10.994440][ T5] ufs_rpmb_wlun 0:0:0:49476: PM state - 2
>>>>> [ 11.000402][ T5] scsi 0:0:0:49456: PM state - 2
>>>>> [ 11.005453][ T5] sd 0:0:0:0: PM state - 2
>>>>> [ 11.009958][ T5] sd 0:0:0:1: PM state - 2
>>>>> [ 11.014469][ T5] sd 0:0:0:2: PM state - 2
>>>>> [ 11.019072][ T5] sd 0:0:0:3: PM state - 2
>>>>> [ 11.023595][ T5] sd 0:0:0:4: PM state - 0 << RPM_ACTIVE
>>>>> [ 11.353298][ T5] sd 0:0:0:5: PM state - 2
>>>>> [ 11.357726][ T5] sd 0:0:0:6: PM state - 2
>>>>> [ 11.362155][ T5] sd 0:0:0:7: PM state - 2
>>>>> [ 11.366584][ T5] ufshcd-qcom 1d84000.ufshc:
>>>>> __ufshcd_wl_suspend - 8709
>>>>> [ 11.374366][ T5] ufs_device_wlun 0:0:0:49488:
>>>>> __ufshcd_wl_suspend -
>>>>> (0) has rpm_active flags
>>>
>>> Do you mean that rpm_active of the link between the consumer and the
>>> supplier is greater than 0 at this point and the consumer is
>>
>> I mean is rpm_active of the link greater than 1 (because 1 means "no
>> active references to the supplier")?
> Hi Rafael:
> No - it is not greater than 1.
>
> I'm trying to understand what's going on in it; will update when I've
> something.
>
>>
>>> RPM_ACTIVE, but the supplier suspends successfully nevertheless?
>>>
>>>>> [ 11.383376][ T5] ufs_device_wlun 0:0:0:49488:
>>>>> ufshcd_wl_runtime_suspend <-- Supplier suspends fine.
>>>>> [ 12.977318][ T174] sd 0:0:0:4: [sde] Synchronizing SCSI cache
>>>>>
>>>>> And the the suspend of sde is stuck now:
>>>>> schedule+0x9c/0xe0
>>>>> schedule_timeout+0x40/0x128
>>>>> io_schedule_timeout+0x44/0x68
>>>>> wait_for_common_io+0x7c/0x100
>>>>> wait_for_completion_io+0x14/0x20
>>>>> blk_execute_rq+0x90/0xcc
>>>>> __scsi_execute+0x104/0x1c4
>>>>> sd_sync_cache+0xf8/0x2a0
>>>>> sd_suspend_common+0x74/0x11c
>>>>> sd_suspend_runtime+0x14/0x20
>>>>> scsi_runtime_suspend+0x64/0x94
>>>>> __rpm_callback+0x80/0x2a4
>>>>> rpm_suspend+0x308/0x614
>>>>> pm_runtime_work+0x98/0xa8
>>>>>
>>>>> I added 'DL_FLAG_RPM_ACTIVE' while creating links.
>>>>> if (hba->sdev_ufs_device) {
>>>>> link = device_link_add(&sdev->sdev_gendev,
>>>>> &hba->sdev_ufs_device->sdev_gendev,
>>>>>
>>>>> DL_FLAG_PM_RUNTIME|DL_FLAG_RPM_ACTIVE);
>>>>> I didn't expect this to resolve the issue anyway and it didn't.
>>>>>
>>>>> Another interesting point here is when I resume any of the above
>>>>> suspended
>>>>> consumers, it all goes back to normal, which is kind of expected. I
>>>>> tried
>>>>> resuming the consumer and the supplier is resumed and the supplier is
>>>>> suspended when all the consumers are suspended.
>>>>>
>>>>> Any pointers on this issue please?
>>>>>
>>>>> @Bart/@...n - Do you've any pointers please?
>>>>
>>>> It's very noticeable that although you seem to have isolated a bug in
>>>> the power management subsystem (supplier goes into runtime suspend
>>>> even when one of its consumers is still active), you did not CC the
>>>> power management maintainer or mailing list.
>>>>
>>>> I have added the appropriate CC's.
>>>
>>> Thanks Alan!
>
>
Hello
I & Can (thanks CanG) debugged this further:
Looks like this issue can occur if the sd probe is asynchronous.
Essentially, the sd_probe() is done asynchronously and
driver_probe_device() invokes pm_runtime_get_suppliers() before invoking
sd_probe().
But scsi_probe_and_add_lun() runs in a separate context.
So the scsi_autopm_put_device() invoked from scsi_scan_host() context
reduces the link->rpm_active to 1. And sd_probe() invokes
scsi_autopm_put_device() and starts a timer. And then
driver_probe_device() invoked from __device_attach_async_helper context
reduces the link->rpm_active to 1 thus enabling the supplier to suspend
before the consumer suspends.
So if:
Context T1:
[1] scsi_probe_and_add_lun()
[2] |- scsi_autopm_put_device() - reduce the link->rpm_active to 1
Context T2:
__device_attach_async_helper()
|- driver_probe_device()
|- sd_probe()
In between [1] and [2] say, driver_probe_device() -> sd_probe() is
invoked in a separate context from __device_attach_async_helper().
The driver_probe_device() -> pm_runtime_get_suppliers() but [2] would
reduce link->rpm_active to 1.
Then sd_probe() would invoke rpm_resume() and proceed as is.
When sd_probe() invokes scsi_autopm_put_device() it'd start a timer,
dev->power.timer_autosuspends = 1.
Now then, pm_runtime_put_suppliers() is invoked from
driver_probe_device() and that makes the link->rpm_active = 1.
But by now, the corresponding 'sd dev' (consumer) usage_count = 0, state
= RPM_ACTIVE and link->rpm_active = 1.
At this point of time, all other 'sd dev' (consumers) _may_ be suspended
or active but would have the link->rpm_active = 1.
Since the supplier has 0 auto-suspend delay, it now suspends!
Context [T1]
Call trace:
dump_backtrace+0x0/0x1d4
show_stack+0x18/0x24
dump_stack+0xc4/0x144
__pm_runtime_idle+0xb4/0x184
scsi_autopm_put_device+0x18/0x24
scsi_sysfs_add_sdev+0x26c/0x278
scsi_probe_and_add_lun+0xbac/0xd48
__scsi_scan_target+0x38c/0x510
scsi_scan_host_selected+0x14c/0x1e4
scsi_scan_host+0x1e0/0x228
ufshcd_async_scan+0x39c/0x408
async_run_entry_fn+0x48/0x128
process_one_work+0x1f0/0x470
worker_thread+0x26c/0x4c8
kthread+0x13c/0x320
ret_from_fork+0x10/0x18
Context [T2]
Call trace:
dump_backtrace+0x0/0x1d4
show_stack+0x18/0x24
dump_stack+0xc4/0x144
rpm_get_suppliers+0x48/0x1ac
__rpm_callback+0x58/0x12c
rpm_resume+0x3a4/0x618
__pm_runtime_resume+0x50/0x80
scsi_autopm_get_device+0x20/0x54
sd_probe+0x40/0x3d0
really_probe+0x1bc/0x4a0
driver_probe_device+0x84/0xf0
__device_attach_driver+0x114/0x138
bus_for_each_drv+0x84/0xd0
__device_attach_async_helper+0x7c/0xf0
async_run_entry_fn+0x48/0x128
process_one_work+0x1f0/0x470
worker_thread+0x26c/0x4c8
kthread+0x13c/0x320
ret_from_fork+0x10/0x18
Below prints show how link->rpm_active becomes 1 for sd 0:0:0:4
[ 7.574654][ T212] Call trace:
[ 7.574657][ T212] dump_backtrace+0x0/0x1d4
[ 7.574661][ T212] show_stack+0x18/0x24
[ 7.574665][ T212] dump_stack+0xc4/0x144
[ 7.574668][ T212] __pm_runtime_idle+0xb4/0x184
[ 7.574671][ T212] scsi_autopm_put_device+0x18/0x24
[ 7.574675][ T212] sd_probe+0x314/0x3d0
[ 7.574677][ T212] really_probe+0x1bc/0x4a0
[ 7.574680][ T212] driver_probe_device+0x84/0xf0
[ 7.574683][ T212] __device_attach_driver+0x114/0x138
[ 7.574686][ T212] bus_for_each_drv+0x84/0xd0
[ 7.574689][ T212] __device_attach_async_helper+0x7c/0xf0
[ 7.574692][ T212] async_run_entry_fn+0x48/0x128
[ 7.574695][ T212] process_one_work+0x1f0/0x470
[ 7.574698][ T212] worker_thread+0x26c/0x4c8
[ 7.574700][ T212] kthread+0x13c/0x320
[ 7.574703][ T212] ret_from_fork+0x10/0x18
[ 7.574706][ T212] sd 0:0:0:4: scsi_runtime_idle
[ 7.574712][ T212] sd 0:0:0:4: __pm_runtime_idle: aft: [UFSDBG]:
pwr.timer_autosuspends: 1 pwr.request_pending: 0 retval: -16
pwr.request: 0 usage_count: 0 rpm_status: 0 link-rpm_active:2
[ 7.574715][ T212] sd 0:0:0:4: sd_probe: [UFSDBG]: Exit
[ 7.574738][ T212] sd 0:0:0:4: __pm_runtime_idle: b4: [UFSDBG]:
pwr.request: 0 usage_count: 0 rpm_status: 0 link-rpm_active:2
[ 7.574752][ T212] Workqueue: events_unbound async_run_entry_fn
[ 7.574754][ T212] Call trace:
[ 7.574758][ T212] dump_backtrace+0x0/0x1d4
[ 7.574761][ T212] show_stack+0x18/0x24
[ 7.574765][ T212] dump_stack+0xc4/0x144
[ 7.574767][ T212] __pm_runtime_idle+0xb4/0x184
[ 7.574770][ T212] driver_probe_device+0x94/0xf0
[ 7.574773][ T212] __device_attach_driver+0x114/0x138
[ 7.574775][ T212] bus_for_each_drv+0x84/0xd0
[ 7.574778][ T212] __device_attach_async_helper+0x7c/0xf0
[ 7.574781][ T212] async_run_entry_fn+0x48/0x128
[ 7.574783][ T212] process_one_work+0x1f0/0x470
[ 7.574786][ T212] worker_thread+0x26c/0x4c8
[ 7.574788][ T212] kthread+0x13c/0x320
[ 7.574791][ T212] ret_from_fork+0x10/0x18
[ 7.574848][ T80] sd 0:0:0:4: scsi_runtime_idle
[ 7.574858][ T212] sd 0:0:0:4: __pm_runtime_idle: aft: [UFSDBG]:
pwr.timer_autosuspends: 1 pwr.request_pending: 0 retval: 0 pwr.request:
0 usage_count: 0 rpm_status: 0 link-rpm_active:2
[ 7.574863][ T212] sd 0:0:0:4: pm_runtime_put_suppliers: [UFSDBG]:
rpm_status: 0 link-rpm_active:1
[ 7.574866][ T212] sd 0:0:0:4: async probe completed
[ 7.574870][ T212] sd 0:0:0:4: __pm_runtime_idle: b4: [UFSDBG]:
pwr.request: 0 usage_count: 0 rpm_status: 0 link-rpm_active:1
So, from the above it looks like when async probe is enabled this is a
possibility.
I don't see a way around this. Please let me know if you
(@Alan/@...t/@...ian) have any thoughts on this.
Thanks,
-asd
--
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum,
Linux Foundation Collaborative Project
Powered by blists - more mailing lists