rsnd: clk-multiplier already disabled warning on Ebisu

rsnd: clk-multiplier already disabled warning on Ebisu

[Geert Uytterhoeven]

Hi Morimoto-san,

While booting Ebisu-4D, I saw the below warnings (once).

    rcar_sound ec500000.sound: can't use clk 1

rsnd_adg_clk_control() failed to enable CLKB, but continues.

    ------------[ cut here ]------------
    clk-multiplier already disabled
    WARNING: CPU: 1 PID: 52 at drivers/clk/clk.c:952 clk_core_disable+0x30/0x9c
    Modules linked in:
    CPU: 1 PID: 52 Comm: kworker/1:2 Not tainted
5.10.0-rc7-rcar3-initrd-00582-gadecf297acf4-dirty #183
    Hardware name: Renesas Ebisu-4D board based on r8a77990 (DT)
    Workqueue: events deferred_probe_work_func
    pstate: 60000085 (nZCv daIf -PAN -UAO -TCO BTYPE=--)
    pc : clk_core_disable+0x30/0x9c
    lr : clk_core_disable+0x30/0x9c
    sp : ffffffc010f939f0
    x29: ffffffc010f939f0 x28: 0000000000000000
    x27: ffffff800949eb00 x26: ffffff80093c40f8
    x25: 0000000000000001 x24: ffffffc010805fea
    x23: 0000000000000000 x22: ffffff80082b8810
    x21: ffffff80093c4080 x20: ffffff8009368b00
    x19: ffffff8009368b00 x18: 0000000000000000
    x17: 000000004ef774c4 x16: 0000000000000014
    x15: ffffffffffffffff x14: ffffffc010b8e8b0
    x13: fffffffffff9fd47 x12: 0720072007200720
    x11: fffffffffffc0000 x10: ffffffc010b8e8d8
    x9 : 0720072007200720 x8 : 2079646165726c61
    x7 : 0000000000000004 x6 : 00000000ffffe6ad
    x5 : ffffffc010f93718 x4 : 0000000000000000
    x3 : 0000000000000000 x2 : 00000000ffffffff
    x1 : 0000000000000000 x0 : 0000000000000000
    Call trace:
     clk_core_disable+0x30/0x9c
     clk_core_disable_lock+0x24/0x3c
     clk_disable+0x20/0x30
     rsnd_adg_clk_control+0xa0/0xd4
     rsnd_adg_remove+0x58/0x6c
     rsnd_probe+0x134/0x3cc

Something else fails (-EPROBE_DEFER?), and thus rsnd_adg_remove() is
called.  The latter disables all clocks, including the one that failed to
enable before, leading to the warning.

     platform_drv_probe+0x54/0xa4
     really_probe+0x234/0x340
     driver_probe_device+0xa0/0xb0
     __device_attach_driver+0x9c/0xa8
     bus_for_each_drv+0x9c/0xc4
     __device_attach+0xd4/0x140
     device_initial_probe+0x14/0x20
     bus_probe_device+0x30/0x94
     deferred_probe_work_func+0x9c/0xb0
     process_one_work+0x180/0x1f0
     process_scheduled_works+0x44/0x48
     worker_thread+0x1ec/0x270
     kthread+0xdc/0xec
     ret_from_fork+0x10/0x30
    ---[ end trace 8d8c2a1b7537ca36 ]---
    ------------[ cut here ]------------
    clk-multiplier already unprepared
    WARNING: CPU: 1 PID: 52 at drivers/clk/clk.c:810
clk_core_unprepare+0x30/0xd0
    [...]
    ---[ end trace 8d8c2a1b7537ca37 ]---

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

rsnd: clk-multiplier already disabled warning on Ebisu

[Geert Uytterhoeven]

Hi Morimoto-san,

While booting Ebisu-4D, I saw the below warnings (once).

    rcar_sound ec500000.sound: can't use clk 1

rsnd_adg_clk_control() failed to enable CLKB, but continues.

    ------------[ cut here ]------------
    clk-multiplier already disabled
    WARNING: CPU: 1 PID: 52 at drivers/clk/clk.c:952 clk_core_disable+0x30/0x9c
    Modules linked in:
    CPU: 1 PID: 52 Comm: kworker/1:2 Not tainted
5.10.0-rc7-rcar3-initrd-00582-gadecf297acf4-dirty #183
    Hardware name: Renesas Ebisu-4D board based on r8a77990 (DT)
    Workqueue: events deferred_probe_work_func
    pstate: 60000085 (nZCv daIf -PAN -UAO -TCO BTYPE=--)
    pc : clk_core_disable+0x30/0x9c
    lr : clk_core_disable+0x30/0x9c
    sp : ffffffc010f939f0
    x29: ffffffc010f939f0 x28: 0000000000000000
    x27: ffffff800949eb00 x26: ffffff80093c40f8
    x25: 0000000000000001 x24: ffffffc010805fea
    x23: 0000000000000000 x22: ffffff80082b8810
    x21: ffffff80093c4080 x20: ffffff8009368b00
    x19: ffffff8009368b00 x18: 0000000000000000
    x17: 000000004ef774c4 x16: 0000000000000014
    x15: ffffffffffffffff x14: ffffffc010b8e8b0
    x13: fffffffffff9fd47 x12: 0720072007200720
    x11: fffffffffffc0000 x10: ffffffc010b8e8d8
    x9 : 0720072007200720 x8 : 2079646165726c61
    x7 : 0000000000000004 x6 : 00000000ffffe6ad
    x5 : ffffffc010f93718 x4 : 0000000000000000
    x3 : 0000000000000000 x2 : 00000000ffffffff
    x1 : 0000000000000000 x0 : 0000000000000000
    Call trace:
     clk_core_disable+0x30/0x9c
     clk_core_disable_lock+0x24/0x3c
     clk_disable+0x20/0x30
     rsnd_adg_clk_control+0xa0/0xd4
     rsnd_adg_remove+0x58/0x6c
     rsnd_probe+0x134/0x3cc

Something else fails (-EPROBE_DEFER?), and thus rsnd_adg_remove() is
called.  The latter disables all clocks, including the one that failed to
enable before, leading to the warning.

     platform_drv_probe+0x54/0xa4
     really_probe+0x234/0x340
     driver_probe_device+0xa0/0xb0
     __device_attach_driver+0x9c/0xa8
     bus_for_each_drv+0x9c/0xc4
     __device_attach+0xd4/0x140
     device_initial_probe+0x14/0x20
     bus_probe_device+0x30/0x94
     deferred_probe_work_func+0x9c/0xb0
     process_one_work+0x180/0x1f0
     process_scheduled_works+0x44/0x48
     worker_thread+0x1ec/0x270
     kthread+0xdc/0xec
     ret_from_fork+0x10/0x30
    ---[ end trace 8d8c2a1b7537ca36 ]---
    ------------[ cut here ]------------
    clk-multiplier already unprepared
    WARNING: CPU: 1 PID: 52 at drivers/clk/clk.c:810
clk_core_unprepare+0x30/0xd0
    [...]
    ---[ end trace 8d8c2a1b7537ca37 ]---

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

[PATCH][RFC] ASoC: rsnd: don't call clk_disable_unprepare() if can't use

[Kuninori Morimoto]

We need to care clock accessibility,
because we might can't use clock for some reasons.

It sets clk_rate for each clocks when enabled.
This means it doesn't have clk_rate if we can't use.
We can avoid to call clk_disable_unprepare() in such case.

Reported-by: Geert Uytterhoeven <geert@linux-m68k.org>
Signed-off-by: Kuninori Morimoto <kuninori.morimoto.gx@renesas.com>
---

Hi Geert.

Thank you for your reporting.
I have never seen this kind of error, but it possible to happen.
Unfortunately, I can't reproduce this but I hope this patch can solve it.
Could you please check this ?
I added [RFC] on this patch Subject.

 sound/soc/sh/rcar/adg.c | 16 ++++++++--------
 1 file changed, 8 insertions(+), 8 deletions(-)

diff --git a/sound/soc/sh/rcar/adg.c b/sound/soc/sh/rcar/adg.c
index b9aacf3d3b29..b870e834aa0a 100644
--- a/sound/soc/sh/rcar/adg.c
+++ b/sound/soc/sh/rcar/adg.c
@@ -366,25 +366,25 @@ void rsnd_adg_clk_control(struct rsnd_priv *priv, int enable)
 	struct rsnd_adg *adg = rsnd_priv_to_adg(priv);
 	struct device *dev = rsnd_priv_to_dev(priv);
 	struct clk *clk;
-	int i, ret;
+	int i;
 
 	for_each_rsnd_clk(clk, adg, i) {
-		ret = 0;
 		if (enable) {
-			ret = clk_prepare_enable(clk);
+			int 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->clk_rate[i] = clk_get_rate(adg->clk[i]);
+			if (ret < 0)
+				dev_warn(dev, "can't use clk %d\n", i);
+			else
+				adg->clk_rate[i] = clk_get_rate(adg->clk[i]);
 		} else {
-			clk_disable_unprepare(clk);
+			if (adg->clk_rate[i])
+				clk_disable_unprepare(clk);
 		}
-
-		if (ret < 0)
-			dev_warn(dev, "can't use clk %d\n", i);
 	}
 }
 
-- 
2.25.1

Re: [PATCH][RFC] ASoC: rsnd: don't call clk_disable_unprepare() if can't use

[Mark Brown]

[-- Attachment #1: Type: text/plain, Size: 581 bytes --]

On Tue, Dec 15, 2020 at 09:06:05AM +0900, Kuninori Morimoto wrote:

> -			adg->clk_rate[i] = clk_get_rate(adg->clk[i]);
> +			if (ret < 0)
> +				dev_warn(dev, "can't use clk %d\n", i);
> +			else
> +				adg->clk_rate[i] = clk_get_rate(adg->clk[i]);

We never reset adg->clk_rate[i] so if we use the clock once then get an
error attempting to use it again...

>  		} else {
> -			clk_disable_unprepare(clk);
> +			if (adg->clk_rate[i])
> +				clk_disable_unprepare(clk);

...we'll try to disable twice.  This was already an issue of course, not
something introduced in this patch.

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

Re: [PATCH][RFC] ASoC: rsnd: don't call clk_disable_unprepare() if can't use

[Mark Brown]

[-- Attachment #1: Type: text/plain, Size: 581 bytes --]

On Tue, Dec 15, 2020 at 09:06:05AM +0900, Kuninori Morimoto wrote:

> -			adg->clk_rate[i] = clk_get_rate(adg->clk[i]);
> +			if (ret < 0)
> +				dev_warn(dev, "can't use clk %d\n", i);
> +			else
> +				adg->clk_rate[i] = clk_get_rate(adg->clk[i]);

We never reset adg->clk_rate[i] so if we use the clock once then get an
error attempting to use it again...

>  		} else {
> -			clk_disable_unprepare(clk);
> +			if (adg->clk_rate[i])
> +				clk_disable_unprepare(clk);

...we'll try to disable twice.  This was already an issue of course, not
something introduced in this patch.

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

Re: [PATCH][RFC] ASoC: rsnd: don't call clk_disable_unprepare() if can't use

[Geert Uytterhoeven]

Hi Morimoto-san,

On Tue, Dec 15, 2020 at 1:06 AM Kuninori Morimoto
<kuninori.morimoto.gx@renesas.com> wrote:
> We need to care clock accessibility,
> because we might can't use clock for some reasons.
>
> It sets clk_rate for each clocks when enabled.
> This means it doesn't have clk_rate if we can't use.
> We can avoid to call clk_disable_unprepare() in such case.
>
> Reported-by: Geert Uytterhoeven <geert@linux-m68k.org>

Feel free to use geert+renesas@glider.be instead ;-)

> Signed-off-by: Kuninori Morimoto <kuninori.morimoto.gx@renesas.com>
> ---
>
> Hi Geert.
>
> Thank you for your reporting.
> I have never seen this kind of error, but it possible to happen.
> Unfortunately, I can't reproduce this but I hope this patch can solve it.
> Could you please check this ?
> I added [RFC] on this patch Subject.

The patch looks good to me, but I also cannot trigger the issue at will.
I went through my old boot logs, and found 2 other occurrences, also
on Ebisu.  In all cases, it happened while a lot of output was printed to
the serial console (either a WARN() splat, or DEBUG_PINCTRL output).
My guess is that console output or disabling interrupts too long is
triggering a race condition or other issue in the i2c driver (clk 1 is the
cs2000 clock generator, controlled through i2c).

> --- a/sound/soc/sh/rcar/adg.c
> +++ b/sound/soc/sh/rcar/adg.c
> @@ -366,25 +366,25 @@ void rsnd_adg_clk_control(struct rsnd_priv *priv, int enable)
>         struct rsnd_adg *adg = rsnd_priv_to_adg(priv);
>         struct device *dev = rsnd_priv_to_dev(priv);
>         struct clk *clk;
> -       int i, ret;
> +       int i;
>
>         for_each_rsnd_clk(clk, adg, i) {
> -               ret = 0;
>                 if (enable) {
> -                       ret = clk_prepare_enable(clk);
> +                       int 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->clk_rate[i] = clk_get_rate(adg->clk[i]);
> +                       if (ret < 0)
> +                               dev_warn(dev, "can't use clk %d\n", i);
> +                       else
> +                               adg->clk_rate[i] = clk_get_rate(adg->clk[i]);
>                 } else {
> -                       clk_disable_unprepare(clk);
> +                       if (adg->clk_rate[i])
> +                               clk_disable_unprepare(clk);

As pointed out by Mark, you may want to clear adg->clk_rate[i] here?

>                 }
> -
> -               if (ret < 0)
> -                       dev_warn(dev, "can't use clk %d\n", i);
>         }
>  }

With the above sorted out:
Reviewed-by: Geert Uytterhoeven <geert+renesas@glider.be>

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: [PATCH][RFC] ASoC: rsnd: don't call clk_disable_unprepare() if can't use

[Geert Uytterhoeven]

Hi Morimoto-san,

On Tue, Dec 15, 2020 at 1:06 AM Kuninori Morimoto
<kuninori.morimoto.gx@renesas.com> wrote:
> We need to care clock accessibility,
> because we might can't use clock for some reasons.
>
> It sets clk_rate for each clocks when enabled.
> This means it doesn't have clk_rate if we can't use.
> We can avoid to call clk_disable_unprepare() in such case.
>
> Reported-by: Geert Uytterhoeven <geert@linux-m68k.org>

Feel free to use geert+renesas@glider.be instead ;-)

> Signed-off-by: Kuninori Morimoto <kuninori.morimoto.gx@renesas.com>
> ---
>
> Hi Geert.
>
> Thank you for your reporting.
> I have never seen this kind of error, but it possible to happen.
> Unfortunately, I can't reproduce this but I hope this patch can solve it.
> Could you please check this ?
> I added [RFC] on this patch Subject.

The patch looks good to me, but I also cannot trigger the issue at will.
I went through my old boot logs, and found 2 other occurrences, also
on Ebisu.  In all cases, it happened while a lot of output was printed to
the serial console (either a WARN() splat, or DEBUG_PINCTRL output).
My guess is that console output or disabling interrupts too long is
triggering a race condition or other issue in the i2c driver (clk 1 is the
cs2000 clock generator, controlled through i2c).

> --- a/sound/soc/sh/rcar/adg.c
> +++ b/sound/soc/sh/rcar/adg.c
> @@ -366,25 +366,25 @@ void rsnd_adg_clk_control(struct rsnd_priv *priv, int enable)
>         struct rsnd_adg *adg = rsnd_priv_to_adg(priv);
>         struct device *dev = rsnd_priv_to_dev(priv);
>         struct clk *clk;
> -       int i, ret;
> +       int i;
>
>         for_each_rsnd_clk(clk, adg, i) {
> -               ret = 0;
>                 if (enable) {
> -                       ret = clk_prepare_enable(clk);
> +                       int 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->clk_rate[i] = clk_get_rate(adg->clk[i]);
> +                       if (ret < 0)
> +                               dev_warn(dev, "can't use clk %d\n", i);
> +                       else
> +                               adg->clk_rate[i] = clk_get_rate(adg->clk[i]);
>                 } else {
> -                       clk_disable_unprepare(clk);
> +                       if (adg->clk_rate[i])
> +                               clk_disable_unprepare(clk);

As pointed out by Mark, you may want to clear adg->clk_rate[i] here?

>                 }
> -
> -               if (ret < 0)
> -                       dev_warn(dev, "can't use clk %d\n", i);
>         }
>  }

With the above sorted out:
Reviewed-by: Geert Uytterhoeven <geert+renesas@glider.be>

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: [PATCH][RFC] ASoC: rsnd: don't call clk_disable_unprepare() if can't use

[Kuninori Morimoto]

Hi Geert, Mark

> > Reported-by: Geert Uytterhoeven <geert@linux-m68k.org>
> 
> Feel free to use geert+renesas@glider.be instead ;-)

OK, will do

> The patch looks good to me, but I also cannot trigger the issue at will.
> I went through my old boot logs, and found 2 other occurrences, also
> on Ebisu.  In all cases, it happened while a lot of output was printed to
> the serial console (either a WARN() splat, or DEBUG_PINCTRL output).
> My guess is that console output or disabling interrupts too long is
> triggering a race condition or other issue in the i2c driver (clk 1 is the
> cs2000 clock generator, controlled through i2c).

OK, Thanks, nice to know.
It was rare case issue, difficult to find :)

> >                 } else {
> > -                       clk_disable_unprepare(clk);
> > +                       if (adg->clk_rate[i])
> > +                               clk_disable_unprepare(clk);
> 
> As pointed out by Mark, you may want to clear adg->clk_rate[i] here?

I thought we can re-get clock if we could get clock once.
But we shouldn't assume it.
Will fix it in v2.

Thank you for your help !!

Best regards
---
Kuninori Morimoto

Re: [PATCH][RFC] ASoC: rsnd: don't call clk_disable_unprepare() if can't use

[Kuninori Morimoto]

Hi Geert, Mark

> > Reported-by: Geert Uytterhoeven <geert@linux-m68k.org>
> 
> Feel free to use geert+renesas@glider.be instead ;-)

OK, will do

> The patch looks good to me, but I also cannot trigger the issue at will.
> I went through my old boot logs, and found 2 other occurrences, also
> on Ebisu.  In all cases, it happened while a lot of output was printed to
> the serial console (either a WARN() splat, or DEBUG_PINCTRL output).
> My guess is that console output or disabling interrupts too long is
> triggering a race condition or other issue in the i2c driver (clk 1 is the
> cs2000 clock generator, controlled through i2c).

OK, Thanks, nice to know.
It was rare case issue, difficult to find :)

> >                 } else {
> > -                       clk_disable_unprepare(clk);
> > +                       if (adg->clk_rate[i])
> > +                               clk_disable_unprepare(clk);
> 
> As pointed out by Mark, you may want to clear adg->clk_rate[i] here?

I thought we can re-get clock if we could get clock once.
But we shouldn't assume it.
Will fix it in v2.

Thank you for your help !!

Best regards
---
Kuninori Morimoto

Re: [PATCH][RFC] ASoC: rsnd: don't call clk_disable_unprepare() if can't use

[Geert Uytterhoeven]

Hi Morimoto-san,

On Thu, Dec 17, 2020 at 1:20 AM Kuninori Morimoto
<kuninori.morimoto.gx@renesas.com> wrote:
> > > Reported-by: Geert Uytterhoeven <geert@linux-m68k.org>
> >
> > Feel free to use geert+renesas@glider.be instead ;-)
>
> OK, will do
>
> > The patch looks good to me, but I also cannot trigger the issue at will.
> > I went through my old boot logs, and found 2 other occurrences, also
> > on Ebisu.  In all cases, it happened while a lot of output was printed to
> > the serial console (either a WARN() splat, or DEBUG_PINCTRL output).
> > My guess is that console output or disabling interrupts too long is
> > triggering a race condition or other issue in the i2c driver (clk 1 is the
> > cs2000 clock generator, controlled through i2c).
>
> OK, Thanks, nice to know.
> It was rare case issue, difficult to find :)
>
> > >                 } else {
> > > -                       clk_disable_unprepare(clk);
> > > +                       if (adg->clk_rate[i])
> > > +                               clk_disable_unprepare(clk);
> >
> > As pointed out by Mark, you may want to clear adg->clk_rate[i] here?
>
> I thought we can re-get clock if we could get clock once.

Indeed. If a clock worked before, it should keep on working.
However, the failing clock was the cs2000 clock, which can fail to enable
if something goes wrong with i2c.

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: [PATCH][RFC] ASoC: rsnd: don't call clk_disable_unprepare() if can't use

[Geert Uytterhoeven]

Hi Morimoto-san,

On Thu, Dec 17, 2020 at 1:20 AM Kuninori Morimoto
<kuninori.morimoto.gx@renesas.com> wrote:
> > > Reported-by: Geert Uytterhoeven <geert@linux-m68k.org>
> >
> > Feel free to use geert+renesas@glider.be instead ;-)
>
> OK, will do
>
> > The patch looks good to me, but I also cannot trigger the issue at will.
> > I went through my old boot logs, and found 2 other occurrences, also
> > on Ebisu.  In all cases, it happened while a lot of output was printed to
> > the serial console (either a WARN() splat, or DEBUG_PINCTRL output).
> > My guess is that console output or disabling interrupts too long is
> > triggering a race condition or other issue in the i2c driver (clk 1 is the
> > cs2000 clock generator, controlled through i2c).
>
> OK, Thanks, nice to know.
> It was rare case issue, difficult to find :)
>
> > >                 } else {
> > > -                       clk_disable_unprepare(clk);
> > > +                       if (adg->clk_rate[i])
> > > +                               clk_disable_unprepare(clk);
> >
> > As pointed out by Mark, you may want to clear adg->clk_rate[i] here?
>
> I thought we can re-get clock if we could get clock once.

Indeed. If a clock worked before, it should keep on working.
However, the failing clock was the cs2000 clock, which can fail to enable
if something goes wrong with i2c.

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