[PATCH v3] scsi: ufs: initialize devfreq synchronously

[PATCH v3] scsi: ufs: initialize devfreq synchronously

[Adrien Thierry]

During ufs initialization, devfreq initialization is asynchronous:
ufshcd_async_scan() calls ufshcd_add_lus(), which in turn initializes
devfreq for ufs. The simple ondemand governor is then loaded. If it is
built as a module, request_module() is called and throws a warning:

  WARNING: CPU: 7 PID: 167 at kernel/kmod.c:136 __request_module+0x1e0/0x460
  Modules linked in: crct10dif_ce llcc_qcom phy_qcom_qmp_usb ufs_qcom phy_qcom_snps_femto_v2 ufshcd_pltfrm phy_qcom_qmp_combo ufshcd_core phy_qcom_qmp_ufs qcom_wdt socinfo fuse ipv6
  CPU: 7 PID: 167 Comm: kworker/u16:3 Not tainted 6.2.0-rc6-00009-g58706f7fb045 #1
  Hardware name: Qualcomm SA8540P Ride (DT)
  Workqueue: events_unbound async_run_entry_fn
  pstate: 00400005 (nzcv daif +PAN -UAO -TCO -DIT -SSBS BTYPE=--)
  pc : __request_module+0x1e0/0x460
  lr : __request_module+0x1d8/0x460
  sp : ffff800009323b90
  x29: ffff800009323b90 x28: 0000000000000000 x27: 0000000000000000
  x26: ffff800009323d50 x25: ffff7b9045f57810 x24: ffff7b9045f57830
  x23: ffffdc5a83e426e8 x22: ffffdc5ae80a9818 x21: 0000000000000001
  x20: ffffdc5ae7502f98 x19: ffff7b9045f57800 x18: ffffffffffffffff
  x17: 312f716572667665 x16: 642f7366752e3030 x15: 0000000000000000
  x14: 000000000000021c x13: 0000000000005400 x12: ffff7b9042ed7614
  x11: ffff7b9042ed7600 x10: 00000000636c0890 x9 : 0000000000000038
  x8 : ffff7b9045f2c880 x7 : ffff7b9045f57c68 x6 : 0000000000000080
  x5 : 0000000000000000 x4 : 8000000000000000 x3 : 0000000000000000
  x2 : 0000000000000000 x1 : ffffdc5ae5d382f0 x0 : 0000000000000001
  Call trace:
   __request_module+0x1e0/0x460
   try_then_request_governor+0x7c/0x100
   devfreq_add_device+0x4b0/0x5fc
   ufshcd_async_scan+0x1d4/0x310 [ufshcd_core]
   async_run_entry_fn+0x34/0xe0
   process_one_work+0x1d0/0x320
   worker_thread+0x14c/0x444
   kthread+0x10c/0x110
   ret_from_fork+0x10/0x20

This occurs because synchronous module loading from async is not
allowed. According to __request_module():

  /*
   * We don't allow synchronous module loading from async.  Module
   * init may invoke async_synchronize_full() which will end up
   * waiting for this task which already is waiting for the module
   * loading to complete, leading to a deadlock.
   */

I experienced such a deadlock on the Qualcomm QDrive3/sa8540p-ride. With
DEVFREQ_GOV_SIMPLE_ONDEMAND=m, the boot hangs after the warning.

This patch fixes both the warning and the deadlock, by moving devfreq
initialization out of the async routine.

I tested this on the sa8540p-ride by using fio to put the UFS under
load, and printing the trace generated by
/sys/kernel/tracing/events/ufs/ufshcd_clk_scaling events. The trace
looks similar with and without the change.

Signed-off-by: Adrien Thierry <athierry@redhat.com>
---
v3: Addressed Bart's comments
v2: Addressed Bart's comments

 drivers/ufs/core/ufshcd.c | 47 ++++++++++++++++++++++++++-------------
 include/ufs/ufshcd.h      |  1 +
 2 files changed, 32 insertions(+), 16 deletions(-)

diff --git a/drivers/ufs/core/ufshcd.c b/drivers/ufs/core/ufshcd.c
index 3a1c4d31e010..2c22a1367440 100644
--- a/drivers/ufs/core/ufshcd.c
+++ b/drivers/ufs/core/ufshcd.c
@@ -1357,6 +1357,13 @@ static int ufshcd_devfreq_target(struct device *dev,
 	struct ufs_clk_info *clki;
 	unsigned long irq_flags;
 
+	/*
+	 * Skip devfreq if ufs initialization is not finished.
+	 * Otherwise ufs could be in a inconsistent state.
+	 */
+	if (!smp_load_acquire(&hba->logical_unit_scan_finished))
+		return 0;
+
 	if (!ufshcd_is_clkscaling_supported(hba))
 		return -EINVAL;
 
@@ -8136,22 +8143,6 @@ static int ufshcd_add_lus(struct ufs_hba *hba)
 	if (ret)
 		goto out;
 
-	/* Initialize devfreq after UFS device is detected */
-	if (ufshcd_is_clkscaling_supported(hba)) {
-		memcpy(&hba->clk_scaling.saved_pwr_info.info,
-			&hba->pwr_info,
-			sizeof(struct ufs_pa_layer_attr));
-		hba->clk_scaling.saved_pwr_info.is_valid = true;
-		hba->clk_scaling.is_allowed = true;
-
-		ret = ufshcd_devfreq_init(hba);
-		if (ret)
-			goto out;
-
-		hba->clk_scaling.is_enabled = true;
-		ufshcd_init_clk_scaling_sysfs(hba);
-	}
-
 	ufs_bsg_probe(hba);
 	ufshpb_init(hba);
 	scsi_scan_host(hba->host);
@@ -8290,6 +8281,12 @@ static void ufshcd_async_scan(void *data, async_cookie_t cookie)
 	if (ret) {
 		pm_runtime_put_sync(hba->dev);
 		ufshcd_hba_exit(hba);
+	} else {
+		/*
+		 * Make sure that when reader code sees ufs initialization has finished,
+		 * all initialization steps have really been executed.
+		 */
+		smp_store_release(&hba->logical_unit_scan_finished, true);
 	}
 }
 
@@ -9896,12 +9893,30 @@ int ufshcd_init(struct ufs_hba *hba, void __iomem *mmio_base, unsigned int irq)
 	 */
 	ufshcd_set_ufs_dev_active(hba);
 
+	/* Initialize devfreq */
+	if (ufshcd_is_clkscaling_supported(hba)) {
+		memcpy(&hba->clk_scaling.saved_pwr_info.info,
+			&hba->pwr_info,
+			sizeof(struct ufs_pa_layer_attr));
+		hba->clk_scaling.saved_pwr_info.is_valid = true;
+		hba->clk_scaling.is_allowed = true;
+
+		err = ufshcd_devfreq_init(hba);
+		if (err)
+			goto rpm_put_sync;
+
+		hba->clk_scaling.is_enabled = true;
+		ufshcd_init_clk_scaling_sysfs(hba);
+	}
+
 	async_schedule(ufshcd_async_scan, hba);
 	ufs_sysfs_add_nodes(hba->dev);
 
 	device_enable_async_suspend(dev);
 	return 0;
 
+rpm_put_sync:
+	pm_runtime_put_sync(dev);
 free_tmf_queue:
 	blk_mq_destroy_queue(hba->tmf_queue);
 	blk_put_queue(hba->tmf_queue);
diff --git a/include/ufs/ufshcd.h b/include/ufs/ufshcd.h
index 727084cd79be..941ede501367 100644
--- a/include/ufs/ufshcd.h
+++ b/include/ufs/ufshcd.h
@@ -896,6 +896,7 @@ struct ufs_hba {
 	struct completion *uic_async_done;
 
 	enum ufshcd_state ufshcd_state;
+	bool logical_unit_scan_finished;
 	u32 eh_flags;
 	u32 intr_mask;
 	u16 ee_ctrl_mask;
-- 
2.39.1

Re: [PATCH v3] scsi: ufs: initialize devfreq synchronously

[Bart Van Assche]

On 2/17/23 11:44, Adrien Thierry wrote:
> During ufs initialization, devfreq initialization is asynchronous:
> ufshcd_async_scan() calls ufshcd_add_lus(), which in turn initializes
> devfreq for ufs. The simple ondemand governor is then loaded. If it is
> built as a module, request_module() is called and throws a warning:

Reviewed-by: Bart Van Assche <bvanassche@acm.org>

Re: [PATCH v3] scsi: ufs: initialize devfreq synchronously

[Martin K. Petersen]

Adrien,

> During ufs initialization, devfreq initialization is asynchronous:
> ufshcd_async_scan() calls ufshcd_add_lus(), which in turn initializes
> devfreq for ufs. The simple ondemand governor is then loaded. If it is
> built as a module, request_module() is called and throws a warning:

Applied to 6.3/scsi-staging, thanks!

-- 
Martin K. Petersen	Oracle Linux Engineering

Re: [PATCH v3] scsi: ufs: initialize devfreq synchronously

[Stanley Chu]

Hi Adrien,

On Sat, Feb 18, 2023 at 3:50 AM Adrien Thierry <athierry@redhat.com> wrote:
>
> During ufs initialization, devfreq initialization is asynchronous:
> ufshcd_async_scan() calls ufshcd_add_lus(), which in turn initializes
> devfreq for ufs. The simple ondemand governor is then loaded. If it is
> built as a module, request_module() is called and throws a warning:
>
>   WARNING: CPU: 7 PID: 167 at kernel/kmod.c:136 __request_module+0x1e0/0x460
>   Modules linked in: crct10dif_ce llcc_qcom phy_qcom_qmp_usb ufs_qcom phy_qcom_snps_femto_v2 ufshcd_pltfrm phy_qcom_qmp_combo ufshcd_core phy_qcom_qmp_ufs qcom_wdt socinfo fuse ipv6
>   CPU: 7 PID: 167 Comm: kworker/u16:3 Not tainted 6.2.0-rc6-00009-g58706f7fb045 #1
>   Hardware name: Qualcomm SA8540P Ride (DT)
>   Workqueue: events_unbound async_run_entry_fn
>   pstate: 00400005 (nzcv daif +PAN -UAO -TCO -DIT -SSBS BTYPE=--)
>   pc : __request_module+0x1e0/0x460
>   lr : __request_module+0x1d8/0x460
>   sp : ffff800009323b90
>   x29: ffff800009323b90 x28: 0000000000000000 x27: 0000000000000000
>   x26: ffff800009323d50 x25: ffff7b9045f57810 x24: ffff7b9045f57830
>   x23: ffffdc5a83e426e8 x22: ffffdc5ae80a9818 x21: 0000000000000001
>   x20: ffffdc5ae7502f98 x19: ffff7b9045f57800 x18: ffffffffffffffff
>   x17: 312f716572667665 x16: 642f7366752e3030 x15: 0000000000000000
>   x14: 000000000000021c x13: 0000000000005400 x12: ffff7b9042ed7614
>   x11: ffff7b9042ed7600 x10: 00000000636c0890 x9 : 0000000000000038
>   x8 : ffff7b9045f2c880 x7 : ffff7b9045f57c68 x6 : 0000000000000080
>   x5 : 0000000000000000 x4 : 8000000000000000 x3 : 0000000000000000
>   x2 : 0000000000000000 x1 : ffffdc5ae5d382f0 x0 : 0000000000000001
>   Call trace:
>    __request_module+0x1e0/0x460
>    try_then_request_governor+0x7c/0x100
>    devfreq_add_device+0x4b0/0x5fc
>    ufshcd_async_scan+0x1d4/0x310 [ufshcd_core]
>    async_run_entry_fn+0x34/0xe0
>    process_one_work+0x1d0/0x320
>    worker_thread+0x14c/0x444
>    kthread+0x10c/0x110
>    ret_from_fork+0x10/0x20
>
> This occurs because synchronous module loading from async is not
> allowed. According to __request_module():
>
>   /*
>    * We don't allow synchronous module loading from async.  Module
>    * init may invoke async_synchronize_full() which will end up
>    * waiting for this task which already is waiting for the module
>    * loading to complete, leading to a deadlock.
>    */
>
> I experienced such a deadlock on the Qualcomm QDrive3/sa8540p-ride. With
> DEVFREQ_GOV_SIMPLE_ONDEMAND=m, the boot hangs after the warning.
>
> This patch fixes both the warning and the deadlock, by moving devfreq
> initialization out of the async routine.
>
> I tested this on the sa8540p-ride by using fio to put the UFS under
> load, and printing the trace generated by
> /sys/kernel/tracing/events/ufs/ufshcd_clk_scaling events. The trace
> looks similar with and without the change.
>
> Signed-off-by: Adrien Thierry <athierry@redhat.com>
> ---
> v3: Addressed Bart's comments
> v2: Addressed Bart's comments
>
>  drivers/ufs/core/ufshcd.c | 47 ++++++++++++++++++++++++++-------------
>  include/ufs/ufshcd.h      |  1 +
>  2 files changed, 32 insertions(+), 16 deletions(-)
>
> diff --git a/drivers/ufs/core/ufshcd.c b/drivers/ufs/core/ufshcd.c
> index 3a1c4d31e010..2c22a1367440 100644
> --- a/drivers/ufs/core/ufshcd.c
> +++ b/drivers/ufs/core/ufshcd.c
> @@ -1357,6 +1357,13 @@ static int ufshcd_devfreq_target(struct device *dev,
>         struct ufs_clk_info *clki;
>         unsigned long irq_flags;
>
> +       /*
> +        * Skip devfreq if ufs initialization is not finished.
> +        * Otherwise ufs could be in a inconsistent state.
> +        */
> +       if (!smp_load_acquire(&hba->logical_unit_scan_finished))
> +               return 0;
> +
>         if (!ufshcd_is_clkscaling_supported(hba))
>                 return -EINVAL;
>
> @@ -8136,22 +8143,6 @@ static int ufshcd_add_lus(struct ufs_hba *hba)
>         if (ret)
>                 goto out;
>
> -       /* Initialize devfreq after UFS device is detected */
> -       if (ufshcd_is_clkscaling_supported(hba)) {
> -               memcpy(&hba->clk_scaling.saved_pwr_info.info,
> -                       &hba->pwr_info,
> -                       sizeof(struct ufs_pa_layer_attr));
> -               hba->clk_scaling.saved_pwr_info.is_valid = true;
> -               hba->clk_scaling.is_allowed = true;
> -
> -               ret = ufshcd_devfreq_init(hba);
> -               if (ret)
> -                       goto out;
> -
> -               hba->clk_scaling.is_enabled = true;
> -               ufshcd_init_clk_scaling_sysfs(hba);
> -       }
> -
>         ufs_bsg_probe(hba);
>         ufshpb_init(hba);
>         scsi_scan_host(hba->host);
> @@ -8290,6 +8281,12 @@ static void ufshcd_async_scan(void *data, async_cookie_t cookie)
>         if (ret) {
>                 pm_runtime_put_sync(hba->dev);
>                 ufshcd_hba_exit(hba);
> +       } else {
> +               /*
> +                * Make sure that when reader code sees ufs initialization has finished,
> +                * all initialization steps have really been executed.
> +                */
> +               smp_store_release(&hba->logical_unit_scan_finished, true);
>         }
>  }
>
> @@ -9896,12 +9893,30 @@ int ufshcd_init(struct ufs_hba *hba, void __iomem *mmio_base, unsigned int irq)
>          */
>         ufshcd_set_ufs_dev_active(hba);
>
> +       /* Initialize devfreq */
> +       if (ufshcd_is_clkscaling_supported(hba)) {
> +               memcpy(&hba->clk_scaling.saved_pwr_info.info,
> +                       &hba->pwr_info,
> +                       sizeof(struct ufs_pa_layer_attr));

Here, hba->pwr_info is not initialized yet, so
hba->clk_scaling.saved_pwr_info will also have uninitialized values.
This is logically incorrect.

First of all, hba->saved_pwr_info is originally designed to keep the
"scaled-up" gear. This statement breaks it.

In addition, the incorrect hba->save_pwr_info may cause serious issues
in ufshcd_scale_gear(), as power mode changes will fail due to
incorrect "new_pwr_info".

Could you please revert this patch first and then upload a fixed one?

Thanks.
Stanley

Re: [PATCH v3] scsi: ufs: initialize devfreq synchronously

[Adrien Thierry]

Hi Stanley,

On Wed, Mar 29, 2023 at 04:39:30PM +0800, Stanley Chu wrote:
> Hi Adrien,
> 
> On Sat, Feb 18, 2023 at 3:50 AM Adrien Thierry <athierry@redhat.com> wrote:
> >
> > During ufs initialization, devfreq initialization is asynchronous:
> > ufshcd_async_scan() calls ufshcd_add_lus(), which in turn initializes
> > devfreq for ufs. The simple ondemand governor is then loaded. If it is
> > built as a module, request_module() is called and throws a warning:
> >
> >   WARNING: CPU: 7 PID: 167 at kernel/kmod.c:136 __request_module+0x1e0/0x460
> >   Modules linked in: crct10dif_ce llcc_qcom phy_qcom_qmp_usb ufs_qcom phy_qcom_snps_femto_v2 ufshcd_pltfrm phy_qcom_qmp_combo ufshcd_core phy_qcom_qmp_ufs qcom_wdt socinfo fuse ipv6
> >   CPU: 7 PID: 167 Comm: kworker/u16:3 Not tainted 6.2.0-rc6-00009-g58706f7fb045 #1
> >   Hardware name: Qualcomm SA8540P Ride (DT)
> >   Workqueue: events_unbound async_run_entry_fn
> >   pstate: 00400005 (nzcv daif +PAN -UAO -TCO -DIT -SSBS BTYPE=--)
> >   pc : __request_module+0x1e0/0x460
> >   lr : __request_module+0x1d8/0x460
> >   sp : ffff800009323b90
> >   x29: ffff800009323b90 x28: 0000000000000000 x27: 0000000000000000
> >   x26: ffff800009323d50 x25: ffff7b9045f57810 x24: ffff7b9045f57830
> >   x23: ffffdc5a83e426e8 x22: ffffdc5ae80a9818 x21: 0000000000000001
> >   x20: ffffdc5ae7502f98 x19: ffff7b9045f57800 x18: ffffffffffffffff
> >   x17: 312f716572667665 x16: 642f7366752e3030 x15: 0000000000000000
> >   x14: 000000000000021c x13: 0000000000005400 x12: ffff7b9042ed7614
> >   x11: ffff7b9042ed7600 x10: 00000000636c0890 x9 : 0000000000000038
> >   x8 : ffff7b9045f2c880 x7 : ffff7b9045f57c68 x6 : 0000000000000080
> >   x5 : 0000000000000000 x4 : 8000000000000000 x3 : 0000000000000000
> >   x2 : 0000000000000000 x1 : ffffdc5ae5d382f0 x0 : 0000000000000001
> >   Call trace:
> >    __request_module+0x1e0/0x460
> >    try_then_request_governor+0x7c/0x100
> >    devfreq_add_device+0x4b0/0x5fc
> >    ufshcd_async_scan+0x1d4/0x310 [ufshcd_core]
> >    async_run_entry_fn+0x34/0xe0
> >    process_one_work+0x1d0/0x320
> >    worker_thread+0x14c/0x444
> >    kthread+0x10c/0x110
> >    ret_from_fork+0x10/0x20
> >
> > This occurs because synchronous module loading from async is not
> > allowed. According to __request_module():
> >
> >   /*
> >    * We don't allow synchronous module loading from async.  Module
> >    * init may invoke async_synchronize_full() which will end up
> >    * waiting for this task which already is waiting for the module
> >    * loading to complete, leading to a deadlock.
> >    */
> >
> > I experienced such a deadlock on the Qualcomm QDrive3/sa8540p-ride. With
> > DEVFREQ_GOV_SIMPLE_ONDEMAND=m, the boot hangs after the warning.
> >
> > This patch fixes both the warning and the deadlock, by moving devfreq
> > initialization out of the async routine.
> >
> > I tested this on the sa8540p-ride by using fio to put the UFS under
> > load, and printing the trace generated by
> > /sys/kernel/tracing/events/ufs/ufshcd_clk_scaling events. The trace
> > looks similar with and without the change.
> >
> > Signed-off-by: Adrien Thierry <athierry@redhat.com>
> > ---
> > v3: Addressed Bart's comments
> > v2: Addressed Bart's comments
> >
> >  drivers/ufs/core/ufshcd.c | 47 ++++++++++++++++++++++++++-------------
> >  include/ufs/ufshcd.h      |  1 +
> >  2 files changed, 32 insertions(+), 16 deletions(-)
> >
> > diff --git a/drivers/ufs/core/ufshcd.c b/drivers/ufs/core/ufshcd.c
> > index 3a1c4d31e010..2c22a1367440 100644
> > --- a/drivers/ufs/core/ufshcd.c
> > +++ b/drivers/ufs/core/ufshcd.c
> > @@ -1357,6 +1357,13 @@ static int ufshcd_devfreq_target(struct device *dev,
> >         struct ufs_clk_info *clki;
> >         unsigned long irq_flags;
> >
> > +       /*
> > +        * Skip devfreq if ufs initialization is not finished.
> > +        * Otherwise ufs could be in a inconsistent state.
> > +        */
> > +       if (!smp_load_acquire(&hba->logical_unit_scan_finished))
> > +               return 0;
> > +
> >         if (!ufshcd_is_clkscaling_supported(hba))
> >                 return -EINVAL;
> >
> > @@ -8136,22 +8143,6 @@ static int ufshcd_add_lus(struct ufs_hba *hba)
> >         if (ret)
> >                 goto out;
> >
> > -       /* Initialize devfreq after UFS device is detected */
> > -       if (ufshcd_is_clkscaling_supported(hba)) {
> > -               memcpy(&hba->clk_scaling.saved_pwr_info.info,
> > -                       &hba->pwr_info,
> > -                       sizeof(struct ufs_pa_layer_attr));
> > -               hba->clk_scaling.saved_pwr_info.is_valid = true;
> > -               hba->clk_scaling.is_allowed = true;
> > -
> > -               ret = ufshcd_devfreq_init(hba);
> > -               if (ret)
> > -                       goto out;
> > -
> > -               hba->clk_scaling.is_enabled = true;
> > -               ufshcd_init_clk_scaling_sysfs(hba);
> > -       }
> > -
> >         ufs_bsg_probe(hba);
> >         ufshpb_init(hba);
> >         scsi_scan_host(hba->host);
> > @@ -8290,6 +8281,12 @@ static void ufshcd_async_scan(void *data, async_cookie_t cookie)
> >         if (ret) {
> >                 pm_runtime_put_sync(hba->dev);
> >                 ufshcd_hba_exit(hba);
> > +       } else {
> > +               /*
> > +                * Make sure that when reader code sees ufs initialization has finished,
> > +                * all initialization steps have really been executed.
> > +                */
> > +               smp_store_release(&hba->logical_unit_scan_finished, true);
> >         }
> >  }
> >
> > @@ -9896,12 +9893,30 @@ int ufshcd_init(struct ufs_hba *hba, void __iomem *mmio_base, unsigned int irq)
> >          */
> >         ufshcd_set_ufs_dev_active(hba);
> >
> > +       /* Initialize devfreq */
> > +       if (ufshcd_is_clkscaling_supported(hba)) {
> > +               memcpy(&hba->clk_scaling.saved_pwr_info.info,
> > +                       &hba->pwr_info,
> > +                       sizeof(struct ufs_pa_layer_attr));
> 
> Here, hba->pwr_info is not initialized yet, so
> hba->clk_scaling.saved_pwr_info will also have uninitialized values.
> This is logically incorrect.
> 
> First of all, hba->saved_pwr_info is originally designed to keep the
> "scaled-up" gear. This statement breaks it.
> 
> In addition, the incorrect hba->save_pwr_info may cause serious issues
> in ufshcd_scale_gear(), as power mode changes will fail due to
> incorrect "new_pwr_info".
> 
> Could you please revert this patch first and then upload a fixed one?

Thanks for pointing that out.

I also realized today that the patch introduces a devfreq warning:
"devfreq 1d84000.ufs: Couldn't update frequency transition information".

So I'm going to post a revert and take the time to come up with an
improved solution that fixes both issues.

Best,

Adrien