On Sat, Mar 6, 2021 at 5:17 PM Alan Stern [off-list ref] wrote:

On Fri, Mar 05, 2021 at 06:54:24PM -0800, Asutosh Das (asd) wrote:

quoted

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
RPM_ACTIVE, but the supplier suspends successfully nevertheless?

quoted

[   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/@Alan - 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!