rsnd_adg_clk_control() sometimes disables already-disabled clock

rsnd_adg_clk_control() sometimes disables already-disabled clock

[Geert Uytterhoeven]

Hi Morimoto-san,

Once in a while, I see the following warning on Salvator-X(S) when entering
s2idle[1]:

    ------------[ cut here ]------------
    clk_multiplier already disabled
    WARNING: CPU: 0 PID: 1084 at drivers/clk/clk.c:1194
clk_core_disable+0xd0/0xd8
    CPU: 0 UID: 0 PID: 1084 Comm: s2idle Not tainted
6.13.0-rc3-arm64-renesas-01336-g13a53d27900d #2738
    Hardware name: Renesas Salvator-X 2nd version board based on r8a77951 (DT)
    pstate: 600000c5 (nZCv daIF -PAN -UAO -TCO -DIT -SSBS BTYPE=--)
    pc : clk_core_disable+0xd0/0xd8
    lr : clk_core_disable+0xd0/0xd8
    sp : ffff800083a8ba00
    x29: ffff800083a8ba00 x28: ffff0004ca7e1a40 x27: ffff800081a0a968
    x26: ffff8000825ee000 x25: ffff800081ae0090 x24: 0000000000000000
    x23: ffff0004c0d64500 x22: 0000000000000000 x21: ffff0004c0d64480
    x20: ffff0004c32c5800 x19: ffff0004c32c5800 x18: ffffffffffffffff
    x17: 000000040044ffff x16: 00000034b5503510 x15: ffff800103a8b617
    x14: 0000000000000000 x13: ffff8000818c66e0 x12: 00000000000007fe
    x11: 00000000000002aa x10: ffff80008191e6e0 x9 : ffff8000818c66e0
    x8 : 00000000ffffefff x7 : ffff80008191e6e0 x6 : 0000000000000000
    x5 : ffff0006ff69a408 x4 : 0000000000000000 x3 : 0000000000000027
    x2 : 0000000000000000 x1 : 0000000000000000 x0 : ffff0004ca7e1a40
    Call trace:
     clk_core_disable+0xd0/0xd8 (P)
     clk_disable+0x2c/0x44
     rsnd_adg_clk_control+0x80/0xf4
     rsnd_suspend+0x14/0x20
     dpm_run_callback+0x4c/0x14c
     device_suspend+0x11c/0x4dc
     dpm_suspend+0xdc/0x214
     dpm_suspend_start+0x48/0x60
     suspend_devices_and_enter+0x124/0x574
     pm_suspend+0x1ac/0x274
     state_store+0x88/0x124
     kobj_attr_store+0x14/0x24
     sysfs_kf_write+0x48/0x6c
     kernfs_fop_write_iter+0x118/0x1a8
     vfs_write+0x280/0x37c
    [...]
    irq event stamp: 0
    hardirqs last  enabled at (0): [<0000000000000000>] 0x0
    hardirqs last disabled at (0): [<ffff800080097c44>]
copy_process+0x638/0x18f4
    softirqs last  enabled at (0): [<ffff800080097c44>]
copy_process+0x638/0x18f4
    softirqs last disabled at (0): [<0000000000000000>] 0x0
    ---[ end trace 0000000000000000 ]---
    ------------[ cut here ]------------
    clk_multiplier already unprepared
    WARNING: CPU: 0 PID: 1084 at drivers/clk/clk.c:1053
clk_core_unprepare+0x110/0x130
    sd 0:0:0:0: [sda] Synchronizing SCSI cache
    CPU: 0 UID: 0 PID: 1084 Comm: s2idle Tainted: G        W
6.13.0-rc3-arm64-renesas-01336-g13a53d27900d #2738
    Tainted: [W]=WARN
    Hardware name: Renesas Salvator-X 2nd version board based on r8a77951 (DT)
    pstate: 60000005 (nZCv daif -PAN -UAO -TCO -DIT -SSBS BTYPE=--)
    pc : clk_core_unprepare+0x110/0x130
    lr : clk_core_unprepare+0x110/0x130
    sp : ffff800083a8ba00
    x29: ffff800083a8ba00 x28: ffff0004ca7e1a40 x27: ffff800081a0a968
    x26: ffff8000825ee000 x25: ffff800081ae0090 x24: 0000000000000000
    x23: ffff0004c0d64500 x22: 0000000000000000 x21: ffff0004c0d64480
    x20: 0000000000000001 x19: ffff0004c32c5800 x18: ffffffffffffffff
    x17: 000000040044ffff x16: 00000034b5503510 x15: 000000000000027a
    x14: 0000000000000000 x13: 000000000000b817 x12: 0000000000000000
    x11: 0000000000000001 x10: 0000000000001410 x9 : ffff800083a8b870
    x8 : ffff800083a8b798 x7 : ffff800083a8b850 x6 : ffff800083a8b7f0
    x5 : ffff800083a8b7d8 x4 : ffff800083a8c000 x3 : 0000000000000000
    x2 : 0000000000000000 x1 : 0000000000000000 x0 : ffff0004ca7e1a40
    Call trace:
     clk_core_unprepare+0x110/0x130 (P)
     clk_unprepare+0x28/0x3c
     rsnd_adg_clk_control+0x88/0xf4
     rsnd_suspend+0x14/0x20
     dpm_run_callback+0x4c/0x14c
     device_suspend+0x11c/0x4dc
     dpm_suspend+0xdc/0x214
     dpm_suspend_start+0x48/0x60
     suspend_devices_and_enter+0x124/0x574
     pm_suspend+0x1ac/0x274
     state_store+0x88/0x124
     kobj_attr_store+0x14/0x24
     sysfs_kf_write+0x48/0x6c
     kernfs_fop_write_iter+0x118/0x1a8
     vfs_write+0x280/0x37c
    [...]
    irq event stamp: 0
    hardirqs last  enabled at (0): [<0000000000000000>] 0x0
    hardirqs last disabled at (0): [<ffff800080097c44>]
copy_process+0x638/0x18f4
    softirqs last  enabled at (0): [<ffff800080097c44>]
copy_process+0x638/0x18f4
    softirqs last disabled at (0): [<0000000000000000>] 0x0
    ---[ end trace 0000000000000000 ]---

Unfortunately I cannot reproduce it at will.
The above is from today's renesas-devel release, but my logs indicate
it happens every few months since at least v6.1.
So far I have seen it on all Salvator-X(S) variants, but not on any other
SoCs or boards.

Do you have a clue?
Thanks!

[1] echo freeze > /sys/power/state

Gr{oetje,eeting}s,

                        Geert

-- 
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
                                -- Linus Torvalds

Re: rsnd_adg_clk_control() sometimes disables already-disabled clock

[Kuninori Morimoto]

Hi Geert

Thank you for reporting

>     ------------[ cut here ]------------
>     clk_multiplier already disabled
(snip)
>     ------------[ cut here ]------------
>     clk_multiplier already unprepared
(snip)
> Unfortunately I cannot reproduce it at will.
> The above is from today's renesas-devel release, but my logs indicate
> it happens every few months since at least v6.1.
> So far I have seen it on all Salvator-X(S) variants, but not on any other
> SoCs or boards.

Hmm... I'm not sure why, but according to the log, it seems it calls
clk_disable_unprepare() without calling clk_prepare_enable().
I think "clk_multiplier" means "cs2000" on Salvator-X(S).

Basically, I don't think it can be happen. But current rsnd driver doesn't
check return value of clk_prepare_enable(). So if cs2000 failed clk_enable()
for some reasons, indeed clk_disable_unprepare() might be called without
enabled (It is another issue, though...)

I'm not tesed, but can this patch improve situation ?

If above assumption was correct, the clk WARNING issue itself can be solved,
but sound driver itself will fail to probe...

------------------
From: Kuninori Morimoto <kuninori.morimoto.gx@renesas.com>
Date: Tue, 17 Dec 2024 11:30:46 +0900
Subject: [PATCH] ASoC: rsnd: check rsnd_adg_clk_enable() return value

rsnd_adg_clk_enable() might be failed for some reasons. In such case,
we will get WARNING from clk.c when suspend was used that it try to
disable clk without enabled. Check rsnd_adg_clk_enable() return value.

Signed-off-by: Kuninori Morimoto <kuninori.morimoto.gx@renesas.com>
---
 sound/soc/renesas/rcar/adg.c  | 30 ++++++++++++++++++++++++------
 sound/soc/renesas/rcar/core.c |  4 +---
 sound/soc/renesas/rcar/rsnd.h |  2 +-
 3 files changed, 26 insertions(+), 10 deletions(-)

diff --git a/sound/soc/renesas/rcar/adg.c b/sound/soc/renesas/rcar/adg.c
index 0f190abf00e75..723dcc88af306 100644
--- a/sound/soc/renesas/rcar/adg.c
+++ b/sound/soc/renesas/rcar/adg.c
@@ -374,12 +374,12 @@ int rsnd_adg_ssi_clk_try_start(struct rsnd_mod *ssi_mod, unsigned int rate)
 	return 0;
 }
 
-void rsnd_adg_clk_control(struct rsnd_priv *priv, int enable)
+int rsnd_adg_clk_control(struct rsnd_priv *priv, int enable)
 {
 	struct rsnd_adg *adg = rsnd_priv_to_adg(priv);
 	struct rsnd_mod *adg_mod = rsnd_mod_get(adg);
 	struct clk *clk;
-	int i;
+	int ret = 0, i;
 
 	if (enable) {
 		rsnd_mod_bset(adg_mod, BRGCKR, 0x80770000, adg->ckr);
@@ -389,18 +389,33 @@ void rsnd_adg_clk_control(struct rsnd_priv *priv, int enable)
 
 	for_each_rsnd_clkin(clk, adg, i) {
 		if (enable) {
-			clk_prepare_enable(clk);
+			ret = clk_prepare_enable(clk);
 
 			/*
 			 * We shouldn't use clk_get_rate() under
 			 * atomic context. Let's keep it when
 			 * rsnd_adg_clk_enable() was called
 			 */
-			adg->clkin_rate[i] = clk_get_rate(clk);
+			if (ret < 0)
+				break;
+			else
+				adg->clkin_rate[i] = clk_get_rate(clk);
 		} else {
-			clk_disable_unprepare(clk);
+			if (adg->clkin_rate[i])
+				clk_disable_unprepare(clk);
+
+			adg->clkin_rate[i] = 0;
 		}
 	}
+
+	/*
+	 * rsnd_adg_clk_enable() might return error (_disable() will not).
+	 * We need to rollback in such case
+	 */
+	if (ret < 0)
+		rsnd_adg_clk_disable(priv);
+
+	return ret;
 }
 
 static struct clk *rsnd_adg_create_null_clk(struct rsnd_priv *priv,
@@ -753,7 +768,10 @@ int rsnd_adg_probe(struct rsnd_priv *priv)
 	if (ret)
 		return ret;
 
-	rsnd_adg_clk_enable(priv);
+	ret = rsnd_adg_clk_enable(priv);
+	if (ret)
+		return ret;
+
 	rsnd_adg_clk_dbg_info(priv, NULL);
 
 	return 0;
diff --git a/sound/soc/renesas/rcar/core.c b/sound/soc/renesas/rcar/core.c
index e2234928c9e88..d3709fd0409e4 100644
--- a/sound/soc/renesas/rcar/core.c
+++ b/sound/soc/renesas/rcar/core.c
@@ -2086,9 +2086,7 @@ static int __maybe_unused rsnd_resume(struct device *dev)
 {
 	struct rsnd_priv *priv = dev_get_drvdata(dev);
 
-	rsnd_adg_clk_enable(priv);
-
-	return 0;
+	return rsnd_adg_clk_enable(priv);
 }
 
 static const struct dev_pm_ops rsnd_pm_ops = {
diff --git a/sound/soc/renesas/rcar/rsnd.h b/sound/soc/renesas/rcar/rsnd.h
index 3c164d8e3b16b..a5f54b65313c4 100644
--- a/sound/soc/renesas/rcar/rsnd.h
+++ b/sound/soc/renesas/rcar/rsnd.h
@@ -608,7 +608,7 @@ int rsnd_adg_set_cmd_timsel_gen2(struct rsnd_mod *cmd_mod,
 				 struct rsnd_dai_stream *io);
 #define rsnd_adg_clk_enable(priv)	rsnd_adg_clk_control(priv, 1)
 #define rsnd_adg_clk_disable(priv)	rsnd_adg_clk_control(priv, 0)
-void rsnd_adg_clk_control(struct rsnd_priv *priv, int enable);
+int rsnd_adg_clk_control(struct rsnd_priv *priv, int enable);
 void rsnd_adg_clk_dbg_info(struct rsnd_priv *priv, struct seq_file *m);
 
 /*
-- 
2.43.0



Thank you for your help !!

Best regards
---
Kuninori Morimoto

Re: rsnd_adg_clk_control() sometimes disables already-disabled clock

[Geert Uytterhoeven]

Hi Morimoto-san,

On Tue, Dec 17, 2024 at 3:38 AM Kuninori Morimoto
<kuninori.morimoto.gx@renesas.com> wrote:
> >     ------------[ cut here ]------------
> >     clk_multiplier already disabled
> (snip)
> >     ------------[ cut here ]------------
> >     clk_multiplier already unprepared
> (snip)
> > Unfortunately I cannot reproduce it at will.
> > The above is from today's renesas-devel release, but my logs indicate
> > it happens every few months since at least v6.1.
> > So far I have seen it on all Salvator-X(S) variants, but not on any other
> > SoCs or boards.
>
> Hmm... I'm not sure why, but according to the log, it seems it calls
> clk_disable_unprepare() without calling clk_prepare_enable().
> I think "clk_multiplier" means "cs2000" on Salvator-X(S).
>
> Basically, I don't think it can be happen. But current rsnd driver doesn't
> check return value of clk_prepare_enable(). So if cs2000 failed clk_enable()
> for some reasons, indeed clk_disable_unprepare() might be called without
> enabled (It is another issue, though...)

That sounds plausible...

> I'm not tesed, but can this patch improve situation ?
>
> If above assumption was correct, the clk WARNING issue itself can be solved,
> but sound driver itself will fail to probe...

I'm adding your patch to my local tree.
Let's see what happens during the next few months...

> ------------------
> From: Kuninori Morimoto <kuninori.morimoto.gx@renesas.com>
> Date: Tue, 17 Dec 2024 11:30:46 +0900
> Subject: [PATCH] ASoC: rsnd: check rsnd_adg_clk_enable() return value
>
> rsnd_adg_clk_enable() might be failed for some reasons. In such case,
> we will get WARNING from clk.c when suspend was used that it try to
> disable clk without enabled. Check rsnd_adg_clk_enable() return value.
>
> Signed-off-by: Kuninori Morimoto <kuninori.morimoto.gx@renesas.com>
> ---
>  sound/soc/renesas/rcar/adg.c  | 30 ++++++++++++++++++++++++------
>  sound/soc/renesas/rcar/core.c |  4 +---
>  sound/soc/renesas/rcar/rsnd.h |  2 +-
>  3 files changed, 26 insertions(+), 10 deletions(-)
>
> diff --git a/sound/soc/renesas/rcar/adg.c b/sound/soc/renesas/rcar/adg.c
> index 0f190abf00e75..723dcc88af306 100644
> --- a/sound/soc/renesas/rcar/adg.c
> +++ b/sound/soc/renesas/rcar/adg.c

> @@ -389,18 +389,33 @@ void rsnd_adg_clk_control(struct rsnd_priv *priv, int enable)
>
>         for_each_rsnd_clkin(clk, adg, i) {
>                 if (enable) {
> -                       clk_prepare_enable(clk);
> +                       ret = clk_prepare_enable(clk);
>
>                         /*
>                          * We shouldn't use clk_get_rate() under
>                          * atomic context. Let's keep it when
>                          * rsnd_adg_clk_enable() was called
>                          */
> -                       adg->clkin_rate[i] = clk_get_rate(clk);
> +                       if (ret < 0)
> +                               break;
> +                       else

No need for the else.

> +                               adg->clkin_rate[i] = clk_get_rate(clk);
>                 } else {
> -                       clk_disable_unprepare(clk);
> +                       if (adg->clkin_rate[i])
> +                               clk_disable_unprepare(clk);
> +
> +                       adg->clkin_rate[i] = 0;
>                 }
>         }

Gr{oetje,eeting}s,

                        Geert

-- 
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
                                -- Linus Torvalds