Received: by 2002:a05:6a10:9848:0:0:0:0 with SMTP id x8csp4467912pxf; Tue, 16 Mar 2021 14:26:49 -0700 (PDT) X-Google-Smtp-Source: ABdhPJwEpBV9AxdD1/g+dvvwIifIjXWu2LbIqMoLHciyKgl/WtDl5Vs2wY5KKvKCcLTp/c9LWkSd X-Received: by 2002:aa7:d1d0:: with SMTP id g16mr21899779edp.358.1615930009071; Tue, 16 Mar 2021 14:26:49 -0700 (PDT) ARC-Seal: i=1; a=rsa-sha256; t=1615930009; cv=none; d=google.com; s=arc-20160816; b=F5C2m1ngQoH2NoK3FzFdeJxQWqCOKElLbNAH9+DPhKWK/RcmSJ3Ms0jdTNK4PLoEG1 +4NUyNdTuzFkzjSb8ImI19lTd8rryRnfTQyUSo6XUwEMDGcO6pBgbNXqWT1L1bTLX4rP 8o1VNiVjMQQ+SxUkDWwV9mtTnYRkXPdy//SWUienK8vcbf1GCEveTfI5IP/N2guQvN5v uAFC16IbQhsOZNT2D4lMPY4vLytlocwtYqMSGU3iac/V7B232acjIMMkcd6bQE8O6bBh y/PISDR60CtonsnBwZiP665bAYDTtO7LKOa2nz1kdmzPfBwAi4oQcK9uZEwZ/asKUkcC /40Q== ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=arc-20160816; h=list-id:precedence:content-transfer-encoding:content-language :in-reply-to:mime-version:user-agent:date:message-id:from:references :cc:to:subject:dmarc-filter:sender:dkim-signature; bh=N4Hz6uBUkKf8smNohwwvtSXuWNFF6/smD+q/fi6b+7w=; b=oUjfkVuEoCEAR9CmrrQELovdM49gHJGcskwY+jyyX/4yekjlU9lflMbtCFi9PRJeQS dAheBzz2Wa0Tic5SeB28z89SlnQu+jLdZkUzJrvbC3y+m5m5TVASBRHitx0AesdvT3C6 cqgv8a1JOt3xPRnHEOK7BSrjy2O2fEqP4pFKK7hkd2ZtVXTqWYXywj+LqZVsGxfZhwAH wholcy7dKGzgqw0//HYYRUXSV0Ef6OjkLyqrwom1XR1rh6AJAT0TnqXEZQvsPrJ9ah97 DJ5jalwO/O2GIYDJRCGfjpRMFBrLM6wsWhb42n3HISUclKXez3xqjEoWFjB6tLdJF7ql O7Ww== ARC-Authentication-Results: i=1; mx.google.com; dkim=pass header.i=@mg.codeaurora.org header.s=smtp header.b=nZqVyvlT; spf=pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) smtp.mailfrom=linux-kernel-owner@vger.kernel.org Return-Path: Received: from vger.kernel.org (vger.kernel.org. [23.128.96.18]) by mx.google.com with ESMTP id q20si11581700edd.31.2021.03.16.14.26.26; Tue, 16 Mar 2021 14:26:49 -0700 (PDT) Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) client-ip=23.128.96.18; Authentication-Results: mx.google.com; dkim=pass header.i=@mg.codeaurora.org header.s=smtp header.b=nZqVyvlT; spf=pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) smtp.mailfrom=linux-kernel-owner@vger.kernel.org Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S231349AbhCPUgR (ORCPT + 99 others); Tue, 16 Mar 2021 16:36:17 -0400 Received: from z11.mailgun.us ([104.130.96.11]:64951 "EHLO z11.mailgun.us" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S230028AbhCPUfv (ORCPT ); Tue, 16 Mar 2021 16:35:51 -0400 DKIM-Signature: a=rsa-sha256; v=1; c=relaxed/relaxed; d=mg.codeaurora.org; q=dns/txt; s=smtp; t=1615926951; h=Content-Transfer-Encoding: Content-Type: In-Reply-To: MIME-Version: Date: Message-ID: From: References: Cc: To: Subject: Sender; bh=N4Hz6uBUkKf8smNohwwvtSXuWNFF6/smD+q/fi6b+7w=; b=nZqVyvlTXqazjtCypls4cb1F1Dpl8QRXmB1mINims9uIlrGYKTT4KDbbG57SraM/62Pog5PB HfT9CciTv8wEwHePhl6HyB2WSwiA2OcKFy7CmC+YQNHc1vvZsFiPtCaYh/FZvCZMXg+Nb8XN 0UjQUsms/gVlfG1jEgoIMv9fmZ8= X-Mailgun-Sending-Ip: 104.130.96.11 X-Mailgun-Sid: WyI0MWYwYSIsICJsaW51eC1rZXJuZWxAdmdlci5rZXJuZWwub3JnIiwgImJlOWU0YSJd Received: from smtp.codeaurora.org (ec2-35-166-182-171.us-west-2.compute.amazonaws.com [35.166.182.171]) by smtp-out-n05.prod.us-west-2.postgun.com with SMTP id 60511695c32ceb3a919faafd (version=TLS1.2, cipher=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256); Tue, 16 Mar 2021 20:35:33 GMT Sender: asutoshd=codeaurora.org@mg.codeaurora.org Received: by smtp.codeaurora.org (Postfix, from userid 1001) id DF09FC43468; Tue, 16 Mar 2021 20:35:33 +0000 (UTC) X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-caf-mail-1.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-2.9 required=2.0 tests=ALL_TRUSTED,BAYES_00, NICE_REPLY_A,SPF_FAIL,URIBL_BLOCKED autolearn=no autolearn_force=no version=3.4.0 Received: from [192.168.8.168] (cpe-70-95-149-85.san.res.rr.com [70.95.149.85]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (No client certificate requested) (Authenticated sender: asutoshd) by smtp.codeaurora.org (Postfix) with ESMTPSA id C0288C433CA; Tue, 16 Mar 2021 20:35:26 +0000 (UTC) DMARC-Filter: OpenDMARC Filter v1.3.2 smtp.codeaurora.org C0288C433CA Authentication-Results: aws-us-west-2-caf-mail-1.web.codeaurora.org; dmarc=none (p=none dis=none) header.from=codeaurora.org Authentication-Results: aws-us-west-2-caf-mail-1.web.codeaurora.org; spf=fail smtp.mailfrom=asutoshd@codeaurora.org Subject: Re: [PATCH v10 1/2] scsi: ufs: Enable power management for wlun To: Adrian Hunter , Alan Stern , Bart Van Assche Cc: "Rafael J. Wysocki" , cang@codeaurora.org, "Martin K. Petersen" , "open list:TARGET SUBSYSTEM" , linux-arm-msm , Alim Akhtar , Avri Altman , "James E.J. Bottomley" , Krzysztof Kozlowski , Stanley Chu , Andy Gross , Bjorn Andersson , Steven Rostedt , Ingo Molnar , Matthias Brugger , Kiwoong Kim , Bean Huo , Lee Jones , Wei Yongjun , Dinghao Liu , "Gustavo A. R. Silva" , Tomas Winkler , Jaegeuk Kim , Satya Tangirala , open list , "moderated list:ARM/SAMSUNG S3C, S5P AND EXYNOS ARM ARCHITECTURES" , "open list:ARM/SAMSUNG S3C, S5P AND EXYNOS ARM ARCHITECTURES" , "moderated list:UNIVERSAL FLASH STORAGE HOST CONTROLLER DRIVER..." , Linux-PM mailing list References: <0576d6eae15486740c25767e2d8805f7e94eb79d.1614725302.git.asutoshd@codeaurora.org> <85086647-7292-b0a2-d842-290818bd2858@intel.com> <6e98724d-2e75-d1fe-188f-a7010f86c509@codeaurora.org> <20210306161616.GC74411@rowland.harvard.edu> <2bd90336-18a9-9acd-5abb-5b52b27fc535@codeaurora.org> <20cbd52d-7254-3e1c-06a3-712326c99f75@codeaurora.org> From: "Asutosh Das (asd)" Message-ID: Date: Tue, 16 Mar 2021 13:35:26 -0700 User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:78.0) Gecko/20100101 Thunderbird/78.7.1 MIME-Version: 1.0 In-Reply-To: Content-Type: text/plain; charset=utf-8; format=flowed Content-Language: en-US Content-Transfer-Encoding: 8bit Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On 3/16/2021 12:48 AM, Adrian Hunter wrote: > On 16/03/21 12:22 am, Asutosh Das (asd) wrote: >> On 3/14/2021 1:11 AM, Adrian Hunter wrote: >>> On 10/03/21 5:04 am, Asutosh Das (asd) wrote: >>>> 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 wrote: >>>>>>> >>>>>>> On Sat, Mar 6, 2021 at 5:17 PM Alan Stern 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/@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! >>>>> >>>>> >>>> >>>> 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. >>> >>> Is this with DL_FLAG_RPM_ACTIVE?  In that case, wouldn't active >>> consumers have link->rpm_active = 2 and also have incremented >>> the supplier's usage_count? Yes this is with DL_FLAG_RPM_ACTIVE. Please let me share a log here: BEF means - Before, AFT means After. [ 6.843445][ T7] scsi 0:0:0:4: [UFSDBG]: ufshcd_setup_links:4779: supp: usage_cnt: 3 Link - 0:0:0:49488 link-rpm_active: 2 avail_luns: 5 [ 6.892545][ T7] scsi 0:0:0:4: pm_runtime_get_suppliers: (0:0:0:49488): supp: usage_count: 5 rpm_active: 4 In the above log, T7 is the context in which this scsi device is being added - scsi_sysfs_add_sdev() [ 6.931846][ T7] ufs_rpmb_wlun 0:0:0:4: [UFSDBG]: ufshcd_rpmb_probe:9692: invoked [ 6.941246][ T7] scsi 0:0:0:4: pm_runtime_put_suppliers: rpm_active: 4 [ 6.941246][ T7] scsi 0:0:0:4: pm_runtime_put_suppliers: (0:0:0:49488) [BEF] usage_count: 5 [ 6.941247][ T7] scsi 0:0:0:4: pm_runtime_put_suppliers: (0:0:0:49488) [AFT] usage_count: 4 rpm_active: 3 [ 6.941267][ T7] scsi 0:0:0:4: rpm_put_suppliers: [BEF] Supp (0:0:0:49488) usage_count: 4 rpm_active: 3 ------ T196 Context comes in while T7 is running ---------- [ 6.941466][ T196] scsi 0:0:0:4: pm_runtime_get_suppliers: (0:0:0:49488): supp: usage_count: 5 rpm_active: 4 -------------------------------------------------------------- [ 7.788397][ T7] scsi 0:0:0:4: rpm_put_suppliers: [AFT] Supp (0:0:0:49488) usage_count: 2 rpm_active: 1 -- T196 is the context in which sd_probe() is invoked for this scsi device. [ 7.974410][ T196] sd 0:0:0:4: [sde] Attached SCSI disk [ 7.984188][ T196] sd 0:0:0:4: pm_runtime_put_suppliers: rpm_active: 2 [ 7.998424][ T196] sd 0:0:0:4: pm_runtime_put_suppliers: (0:0:0:49488) [BEF] usage_count: 4 [ 8.017320][ T196] sd 0:0:0:4: pm_runtime_put_suppliers: (0:0:0:49488) [AFT] usage_count: 1 rpm_active: 1 The reference to the link is released after sd_probe() is completed. At this point, the rpm_active should be 2. And the rpm_active should become 1 when sd 0:0:0:4 actually suspends. But at the end of sd_probe() the suspend is only scheduled. However the supplier is now free to suspend. In this log, the usage_count of supplier becomes 0 here: [ 11.963885][ T117] sd 0:0:0:7: rpm_put_suppliers: [BEF] Supp (0:0:0:49488) usage_count: 1 rpm_active: 2 [ 11.973821][ T117] sd 0:0:0:7: rpm_put_suppliers: [AFT] Supp (0:0:0:49488) usage_count: 0 rpm_active: 1 However, the consumer sd 0:0:0:4 is still active but has released the reference to the supplier: [ 12.002792][ T117] scsi 0:0:0:49456: rpm_status - 2 [ 12.002806][ T117] sd 0:0:0:0: rpm_status - 2 [ 12.002834][ T117] sd 0:0:0:1: rpm_status - 2 [ 12.017730][ T117] sd 0:0:0:2: rpm_status - 2 [ 12.041317][ T117] sd 0:0:0:3: rpm_status - 2 [ 12.045953][ T117] sd 0:0:0:4: rpm_status - 0 And sd 0:0:0:4 tries to suspend here: [ 15.465914][ T117] sd 0:0:0:4: [sde] Synchronizing SCSI cache >>> >>> Another outstanding issue that comes to mind, is to ensure >>> hba->sdev_ufs_device does not runtime suspend before it is probed. >>> I suggest changing ufshcd_slave_configure() so it does not set >>> sdev->rpm_autosuspend for hba->sdev_ufs_device, and instead do >>> pm_runtime_allow / pm_runtime_forbid() in ufshcd_wl_probe() / >>> ufshcd_wl_remove() respectively. >>> If pm_runtime_allow() is invoked from ufshcd_wl_probe() it'd invoke runtime_suspend on hba->sdev_ufs_device before exiting scsi_sysfs_add_sdev(). So I think pm_runtime_allow() should be invoked in ufshcd_scsi_add_wlus(). >>> However we still want to stop hba->sdev_ufs_device runtime >>> suspending while consumers are being added.  With that in mind, >>> I would expect pm_runtime_get_noresume(&hba->sdev_ufs_device->sdev_gendev) >>> in ufshcd_scsi_add_wlus() to come *before* >>> ufshcd_blk_pm_runtime_init(hba->sdev_ufs_device).  In fact, it would >>> be more logical to make it, pm_runtime_get_sync() since we require >>> hba->sdev_ufs_device to be active at that point. >>> Correct, scsi_autopm_get_device(hba->sdev_ufs_device) should be invoked before ufshcd_blk_pm_runtime_init(hba->sdev_ufs_device). Now a corresponding scsi_autopm_put_device(hba->sdev_ufs_device) is invoked after the consumers are added in ufshcd_setup_links(). Even then I think this issue would still pop up. >>> >> >> Hi Adrian, >> I think the v11 that I pushed can handle this. >> runtime-suspend is forbidden at probe and is re-enabled after probe is done. Please take a look and let me know if I'm missing something. > > If the PM APIs are being used correctly, the usage and active > counts should never be wrong. If they were, then that would > be an issue for the PM framework. >It is more likely that I'm using it incorrectly :). > However, it is hard to tell what the issues are until all the > UFS driver changes have been completed, such as the ones I > suggested above above. > Ok, understood. > v11 could be hiding issues rather than fixing them. > Based on the logs, in v11, I tried to forbid any runtime-suspend until sd_probe() is done. I could be misunderstanding the whole thing though. Having said that, I will make the changes as per your suggestions and push a v12. I will test with v12 as well and see if this issue is seen. >> >>>> >>>> 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/@Bart/@Adrian) have any thoughts on this. >>>> >>>> Thanks, >>>> -asd >>>> >>> >> >> > -- The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum, Linux Foundation Collaborative Project