Re: [alsa-devel] [PATCH] mfd: arizona: Call the runtime PM function if the state is runtime resumed

Re: [alsa-devel] [PATCH] mfd: arizona: Call the runtime PM function if the state is runtime resumed

[Charles Keepax]

On Thu, Sep 17, 2015 at 05:28:47PM +0900, Inha Song wrote:
> This patch call runtiem PM function manually if the state is runtime resumed
> before enter suspend.
> 
> This case has occurred when wake-up by the resume after entering to
> suspend during the playback.
> $ aplay -> runtime_resume() -> suspend() -> resume()
> 
> In this case, Can occurred an error when enter suspend.
> --
> [   82.559234] PM: suspend of devices complete after 57.252 msecs
> [   82.567978] arizona spi1.0: Failed to read IRQ status: -108
> [   82.567989] arizona spi1.0: Failed to read main IRQ status: -108
> [   82.568027] arizona spi1.0: Failed to read IRQ status: -108
> [   82.568036] arizona spi1.0: Failed to read main IRQ status: -108

Would it be possible to get some more detail on what is happening
here? A full log would be nice with DEBUG enabled in
arizona-core.c, also perhaps put some printk's in the SPI driver
suspend/resume as well.

It looks like what is happening is that the system is attempting
to handle an IRQ before the SPI has been resumed. But that is
exactly what the irq enables/disables in the system PM ops in
Arizona are trying to avoid.

> ....
> So, we should call runtime_suspend() manually when enter suspend
> if the state is runtime resume.

There are many use-cases where we want to leave the CODEC enabled
whilst the system is suspended so we really don't want to be
doing a runtime suspend with every system suspend.

Thanks,
Charles

[alsa-devel] [PATCH] mfd: arizona: Call the runtime PM function if the state is runtime resumed

[Inha Song]

This patch call runtiem PM function manually if the state is runtime resumed
before enter suspend.

This case has occurred when wake-up by the resume after entering to
suspend during the playback.
$ aplay -> runtime_resume() -> suspend() -> resume()

In this case, Can occurred an error when enter suspend.
--
[   82.559234] PM: suspend of devices complete after 57.252 msecs
[   82.567978] arizona spi1.0: Failed to read IRQ status: -108
[   82.567989] arizona spi1.0: Failed to read main IRQ status: -108
[   82.568027] arizona spi1.0: Failed to read IRQ status: -108
[   82.568036] arizona spi1.0: Failed to read main IRQ status: -108
....
So, we should call runtime_suspend() manually when enter suspend
if the state is runtime resume.

Also should call runtime_resume() when wake-up by resume if the state
was runtime resume before entering suspend.

Signed-off-by: Inha Song <ideal.song@samsung.com>
---
 drivers/mfd/arizona-core.c | 8 ++++++++
 1 file changed, 8 insertions(+)

diff --git a/drivers/mfd/arizona-core.c b/drivers/mfd/arizona-core.c
index 908c69b..de55706 100644
--- a/drivers/mfd/arizona-core.c
+++ b/drivers/mfd/arizona-core.c
@@ -683,6 +683,10 @@ static int arizona_suspend(struct device *dev)
 	struct arizona *arizona = dev_get_drvdata(dev);
 
 	dev_dbg(arizona->dev, "Suspend, disabling IRQ\n");
+
+	if (!pm_runtime_status_suspended(dev))
+		arizona_runtime_suspend(dev);
+
 	disable_irq(arizona->irq);
 
 	return 0;
@@ -713,6 +717,10 @@ static int arizona_resume(struct device *dev)
 	struct arizona *arizona = dev_get_drvdata(dev);
 
 	dev_dbg(arizona->dev, "Late resume, reenabling IRQ\n");
+
+	if (!pm_runtime_status_suspended(dev))
+		arizona_runtime_resume(dev);
+
 	enable_irq(arizona->irq);
 
 	return 0;
-- 
2.0.0.390.gcb682f8

Re: [alsa-devel] [PATCH] mfd: arizona: Call the runtime PM function if the state is runtime resumed

[Inha Song]

Hi,


It is a log:

# aplay
[   79.590767] s3c64xx_spi_runtime_resume
[   79.592288] arizona spi1.0: ASRC underclocked
[   79.592331] s3c64xx_spi_runtime_suspend
---
-> suspend ()

[   83.348754] s3c64xx_spi_runtime_resume
[   83.367711] s3c64xx_spi_suspend
[   83.368420] PM: suspend of devices complete after 59.666 msecs
[   83.375584] arizona spi1.0: Failed to read IRQ status: -108
[   83.375595] arizona spi1.0: Failed to read main IRQ status: -108
[   83.375672] arizona spi1.0: Failed to read IRQ status: -108
[   83.375679] arizona spi1.0: Failed to read main IRQ status: -108
[   83.375749] arizona spi1.0: Failed to read IRQ status: -108
.....
[   83.580360] Call trace:
[   83.580369] [<ffffffc000089f8c>] dump_backtrace+0x0/0x12c
[   83.580373] [<ffffffc00008a0c8>] show_stack+0x10/0x1c
[   83.580380] [<ffffffc0009f10e4>] dump_stack+0x78/0xc8
[   83.580386] [<ffffffc00009ade8>] warn_slowpath_common+0x98/0xd0
[   83.580390] [<ffffffc00009ae6c>] warn_slowpath_fmt+0x4c/0x58
[   83.580394] [<ffffffc0000e7f1c>] __enable_irq+0x40/0x8c
[   83.580399] [<ffffffc0000e7f9c>] enable_irq+0x34/0x74
[   83.580404] [<ffffffc0004d00d0>] arizona_resume+0x10/0x20
[   83.580410] [<ffffffc0004b6bac>] dpm_run_callback+0x50/0x1a0
[   83.580414] [<ffffffc0004b728c>] device_resume+0x90/0x268
[   83.580418] [<ffffffc0004b88cc>] dpm_resume+0x120/0x350
[   83.580422] [<ffffffc0004b8f1c>] dpm_resume_end+0x10/0x28
[   83.580426] [<ffffffc0000e1bec>] suspend_devices_and_enter+0x138/0x7f4
[   83.580430] [<ffffffc0000e25bc>] pm_suspend+0x314/0x5bc
[   83.580435] [<ffffffc0000e0bc8>] state_store+0x7c/0xf0
[   83.580441] [<ffffffc00035ee58>] kobj_attr_store+0x10/0x24
[   83.580448] [<ffffffc00020e1e0>] sysfs_kf_write+0x40/0x4c
[   83.580452] [<ffffffc00020d664>] kernfs_fop_write+0xb8/0x180
[   83.580458] [<ffffffc0001a2ef4>] __vfs_write+0x2c/0x11c
[   83.580463] [<ffffffc0001a38f0>] vfs_write+0x90/0x170
[   83.580467] [<ffffffc0001a422c>] SyS_write+0x40/0xa0

Best Regards,
Inha Song.

On Thu, 17 Sep 2015 09:25:42 +0100
Charles Keepax <ckeepax@opensource.wolfsonmicro.com> wrote:

> On Thu, Sep 17, 2015 at 05:28:47PM +0900, Inha Song wrote:
> > This patch call runtiem PM function manually if the state is runtime resumed
> > before enter suspend.
> > 
> > This case has occurred when wake-up by the resume after entering to
> > suspend during the playback.
> > $ aplay -> runtime_resume() -> suspend() -> resume()
> > 
> > In this case, Can occurred an error when enter suspend.
> > --
> > [   82.559234] PM: suspend of devices complete after 57.252 msecs
> > [   82.567978] arizona spi1.0: Failed to read IRQ status: -108
> > [   82.567989] arizona spi1.0: Failed to read main IRQ status: -108
> > [   82.568027] arizona spi1.0: Failed to read IRQ status: -108
> > [   82.568036] arizona spi1.0: Failed to read main IRQ status: -108
> 
> Would it be possible to get some more detail on what is happening
> here? A full log would be nice with DEBUG enabled in
> arizona-core.c, also perhaps put some printk's in the SPI driver
> suspend/resume as well.
> 
> It looks like what is happening is that the system is attempting
> to handle an IRQ before the SPI has been resumed. But that is
> exactly what the irq enables/disables in the system PM ops in
> Arizona are trying to avoid.
> 
> > ....
> > So, we should call runtime_suspend() manually when enter suspend
> > if the state is runtime resume.
> 
> There are many use-cases where we want to leave the CODEC enabled
> whilst the system is suspended so we really don't want to be
> doing a runtime suspend with every system suspend.
> 
> Thanks,
> Charles

Re: [alsa-devel] [PATCH] mfd: arizona: Call the runtime PM function if the state is runtime resumed

[Charles Keepax]

On Thu, Sep 17, 2015 at 06:05:30PM +0900, Inha Song wrote:
> Hi,
> 
> 
> It is a log:
> 
> # aplay
> [   79.590767] s3c64xx_spi_runtime_resume
> [   79.592288] arizona spi1.0: ASRC underclocked
> [   79.592331] s3c64xx_spi_runtime_suspend
> ---
> -> suspend ()
> 
> [   83.348754] s3c64xx_spi_runtime_resume
> [   83.367711] s3c64xx_spi_suspend
> [   83.368420] PM: suspend of devices complete after 59.666 msecs
> [   83.375584] arizona spi1.0: Failed to read IRQ status: -108
> [   83.375595] arizona spi1.0: Failed to read main IRQ status: -108
> [   83.375672] arizona spi1.0: Failed to read IRQ status: -108
> [   83.375679] arizona spi1.0: Failed to read main IRQ status: -108
> [   83.375749] arizona spi1.0: Failed to read IRQ status: -108
> .....
> [   83.580360] Call trace:
> [   83.580369] [<ffffffc000089f8c>] dump_backtrace+0x0/0x12c
> [   83.580373] [<ffffffc00008a0c8>] show_stack+0x10/0x1c
> [   83.580380] [<ffffffc0009f10e4>] dump_stack+0x78/0xc8
> [   83.580386] [<ffffffc00009ade8>] warn_slowpath_common+0x98/0xd0
> [   83.580390] [<ffffffc00009ae6c>] warn_slowpath_fmt+0x4c/0x58
> [   83.580394] [<ffffffc0000e7f1c>] __enable_irq+0x40/0x8c
> [   83.580399] [<ffffffc0000e7f9c>] enable_irq+0x34/0x74
> [   83.580404] [<ffffffc0004d00d0>] arizona_resume+0x10/0x20
> [   83.580410] [<ffffffc0004b6bac>] dpm_run_callback+0x50/0x1a0
> [   83.580414] [<ffffffc0004b728c>] device_resume+0x90/0x268
> [   83.580418] [<ffffffc0004b88cc>] dpm_resume+0x120/0x350
> [   83.580422] [<ffffffc0004b8f1c>] dpm_resume_end+0x10/0x28
> [   83.580426] [<ffffffc0000e1bec>] suspend_devices_and_enter+0x138/0x7f4
> [   83.580430] [<ffffffc0000e25bc>] pm_suspend+0x314/0x5bc
> [   83.580435] [<ffffffc0000e0bc8>] state_store+0x7c/0xf0
> [   83.580441] [<ffffffc00035ee58>] kobj_attr_store+0x10/0x24
> [   83.580448] [<ffffffc00020e1e0>] sysfs_kf_write+0x40/0x4c
> [   83.580452] [<ffffffc00020d664>] kernfs_fop_write+0xb8/0x180
> [   83.580458] [<ffffffc0001a2ef4>] __vfs_write+0x2c/0x11c
> [   83.580463] [<ffffffc0001a38f0>] vfs_write+0x90/0x170
> [   83.580467] [<ffffffc0001a422c>] SyS_write+0x40/0xa0

OK so this is definitely that the SPI driver hasn't resumed
yet. Could we also get DEBUG turned on in arizona-core here. I am
interested to check where in the process the arizona
suspend/resume ops are being called.

Thanks,
Charles

Re: [alsa-devel] [PATCH] mfd: arizona: Call the runtime PM function if the state is runtime resumed

[Inha Song]

Hi,

I just change dev_err() to dev_info() in arizona-core.


root@localhost:~# aplay test.wav
[   42.731358] arizona spi1.0: Leaving AoD mode
....
[   42.823514] s3c64xx_spi_runtime_resume
[   42.828270] arizona spi1.0: ASRC underclocked
[   42.828281] s3c64xx_spi_runtime_suspend
....
-> suspend ()
[   72.398152] arizona spi1.0: Suspend, disabling IRQ
[   72.410471] s3c64xx_spi_runtime_resume
[   72.429045] s3c64xx_spi_suspend
-> spi suspended
[   72.429905] PM: suspend of devices complete after 67.309 msecs
[   72.440084] arizona spi1.0: Late suspend, reenabling IRQ
-> try to access spi irq after spi suspend()
[   72.440165] arizona spi1.0: Failed to read IRQ status: -108
[   72.440174] arizona spi1.0: Failed to read main IRQ status: -108
[   72.440242] arizona spi1.0: Failed to read IRQ status: -108
[   72.440249] arizona spi1.0: Failed to read main IRQ status: -108
[   72.440275] arizona spi1.0: Failed to read IRQ status: -108
[   72.440282] arizona spi1.0: Failed to read main IRQ status: -108
[   72.440304] arizona spi1.0: Failed to read IRQ status: -108
....
[   72.465525] s3c64xx_spi_resume
[   72.650760] arizona spi1.0: Late resume, reenabling IRQ
[   72.650819] [<ffffffc000089f8c>] dump_backtrace+0x0/0x12c
[   72.650824] [<ffffffc00008a0c8>] show_stack+0x10/0x1c
[   72.650832] [<ffffffc0009f1398>] dump_stack+0x78/0xc8
[   72.650838] [<ffffffc00009ade8>] warn_slowpath_common+0x98/0xd0
[   72.650842] [<ffffffc00009ae6c>] warn_slowpath_fmt+0x4c/0x58
[   72.650847] [<ffffffc0000e7f1c>] __enable_irq+0x40/0x8c
[   72.650851] [<ffffffc0000e7f9c>] enable_irq+0x34/0x74
[   72.650858] [<ffffffc0004d013c>] arizona_resume+0x24/0x38
[   72.650865] [<ffffffc0004b6bac>] dpm_run_callback+0x50/0x1a0
[   72.650870] [<ffffffc0004b728c>] device_resume+0x90/0x268
[   72.650874] [<ffffffc0004b88cc>] dpm_resume+0x120/0x350
[   72.650878] [<ffffffc0004b8f1c>] dpm_resume_end+0x10/0x28
[   72.650884] [<ffffffc0000e1bec>] suspend_devices_and_enter+0x138/0x7f4
[   72.650887] [<ffffffc0000e25bc>] pm_suspend+0x314/0x5bc
[   72.650893] [<ffffffc0000e0bc8>] state_store+0x7c/0xf0
[   72.650901] [<ffffffc00035ee58>] kobj_attr_store+0x10/0x24
[   72.650910] [<ffffffc00020e1e0>] sysfs_kf_write+0x40/0x4c
[   72.650914] [<ffffffc00020d664>] kernfs_fop_write+0xb8/0x180
[   72.650922] [<ffffffc0001a2ef4>] __vfs_write+0x2c/0x11c
[   72.650926] [<ffffffc0001a38f0>] vfs_write+0x90/0x170
[   72.650931] [<ffffffc0001a422c>] SyS_write+0x40/0xa0
-----

This irq failed errors are occured in enable_irq() that in arizona_suspend_late().
Becase of access the irq after spi suspend. (arizona->irq == spi->irq)

Best Regards,
Inha Song.

On Thu, 17 Sep 2015 10:16:32 +0100
Charles Keepax <ckeepax@opensource.wolfsonmicro.com> wrote:

> 
> OK so this is definitely that the SPI driver hasn't resumed
> yet. Could we also get DEBUG turned on in arizona-core here. I am
> interested to check where in the process the arizona
> suspend/resume ops are being called.
> 
> Thanks,
> Charles

Re: [alsa-devel] [PATCH] mfd: arizona: Call the runtime PM function if the state is runtime resumed

[Charles Keepax]

On Fri, Sep 18, 2015 at 03:49:03PM +0900, Inha Song wrote:
> Hi,
> 
> I just change dev_err() to dev_info() in arizona-core.
> 
> 
> root@localhost:~# aplay test.wav
> [   42.731358] arizona spi1.0: Leaving AoD mode
> ....
> [   42.823514] s3c64xx_spi_runtime_resume
> [   42.828270] arizona spi1.0: ASRC underclocked
> [   42.828281] s3c64xx_spi_runtime_suspend
> ....
> -> suspend ()
> [   72.398152] arizona spi1.0: Suspend, disabling IRQ
> [   72.410471] s3c64xx_spi_runtime_resume
> [   72.429045] s3c64xx_spi_suspend
> -> spi suspended
> [   72.429905] PM: suspend of devices complete after 67.309 msecs
> [   72.440084] arizona spi1.0: Late suspend, reenabling IRQ
> -> try to access spi irq after spi suspend()
> [   72.440165] arizona spi1.0: Failed to read IRQ status: -108
> [   72.440174] arizona spi1.0: Failed to read main IRQ status: -108
> [   72.440242] arizona spi1.0: Failed to read IRQ status: -108
> [   72.440249] arizona spi1.0: Failed to read main IRQ status: -108
> [   72.440275] arizona spi1.0: Failed to read IRQ status: -108
> [   72.440282] arizona spi1.0: Failed to read main IRQ status: -108
> [   72.440304] arizona spi1.0: Failed to read IRQ status: -108

Ok so looking at the system PM code I think the problem here is
there is currently a small window between when we enable this IRQ
and when the suspend proceedure disables IRQs and this IRQ is
sneaking in at that point.

Can you try the following diff and let me know what happens:

--- a/drivers/mfd/arizona-core.c
+++ b/drivers/mfd/arizona-core.c
@@ -727,7 +727,7 @@ const struct dev_pm_ops arizona_pm_ops = {
                           NULL)
        SET_SYSTEM_SLEEP_PM_OPS(arizona_suspend, arizona_resume)
 #ifdef CONFIG_PM_SLEEP
-       .suspend_late = arizona_suspend_late,
+       .suspend_noirq = arizona_suspend_late,
        .resume_noirq = arizona_resume_noirq,
 #endif

Thanks,
Charles

Re: [alsa-devel] [PATCH] mfd: arizona: Call the runtime PM function if the state is runtime resumed

[Inha Song]

Hi, Charles,

I've already tried to change.
If I change to that, we can't enter the suspen during the playback.

-
[   72.538263] arizona spi1.0: Suspend, disabling IRQ
...
[   72.585823] arizona spi1.0: Late suspend, reengabling IRQ
[   72.585904] arizona spi1.0: Early resume, disabling IRQ
...
[   72.646770] PM: noirq suspend of devices failed
		<- because of "spi1.0" pm_wakeup_pending() in suspend_noirq()
...
[   72.663623] s3c64xx_spi_resume
[   72.851089] arizona spi1.0: Late resume, reenabling IRQ


Best Regards,
Inha Song.


On Fri, 18 Sep 2015 09:24:46 +0100
Charles Keepax <ckeepax@opensource.wolfsonmicro.com> wrote:

> On Fri, Sep 18, 2015 at 03:49:03PM +0900, Inha Song wrote:
> > Hi,
> > 
> > I just change dev_err() to dev_info() in arizona-core.
> > 
> > 
> > root@localhost:~# aplay test.wav
> > [   42.731358] arizona spi1.0: Leaving AoD mode
> > ....
> > [   42.823514] s3c64xx_spi_runtime_resume
> > [   42.828270] arizona spi1.0: ASRC underclocked
> > [   42.828281] s3c64xx_spi_runtime_suspend
> > ....
> > -> suspend ()
> > [   72.398152] arizona spi1.0: Suspend, disabling IRQ
> > [   72.410471] s3c64xx_spi_runtime_resume
> > [   72.429045] s3c64xx_spi_suspend
> > -> spi suspended
> > [   72.429905] PM: suspend of devices complete after 67.309 msecs
> > [   72.440084] arizona spi1.0: Late suspend, reenabling IRQ
> > -> try to access spi irq after spi suspend()
> > [   72.440165] arizona spi1.0: Failed to read IRQ status: -108
> > [   72.440174] arizona spi1.0: Failed to read main IRQ status: -108
> > [   72.440242] arizona spi1.0: Failed to read IRQ status: -108
> > [   72.440249] arizona spi1.0: Failed to read main IRQ status: -108
> > [   72.440275] arizona spi1.0: Failed to read IRQ status: -108
> > [   72.440282] arizona spi1.0: Failed to read main IRQ status: -108
> > [   72.440304] arizona spi1.0: Failed to read IRQ status: -108
> 
> Ok so looking at the system PM code I think the problem here is
> there is currently a small window between when we enable this IRQ
> and when the suspend proceedure disables IRQs and this IRQ is
> sneaking in at that point.
> 
> Can you try the following diff and let me know what happens:
> 
> --- a/drivers/mfd/arizona-core.c
> +++ b/drivers/mfd/arizona-core.c
> @@ -727,7 +727,7 @@ const struct dev_pm_ops arizona_pm_ops = {
>                            NULL)
>         SET_SYSTEM_SLEEP_PM_OPS(arizona_suspend, arizona_resume)
>  #ifdef CONFIG_PM_SLEEP
> -       .suspend_late = arizona_suspend_late,
> +       .suspend_noirq = arizona_suspend_late,
>         .resume_noirq = arizona_resume_noirq,
>  #endif
> 
> Thanks,
> Charles

Re: [alsa-devel] [PATCH] mfd: arizona: Call the runtime PM function if the state is runtime resumed

[Charles Keepax]

On Mon, Sep 21, 2015 at 11:16:42AM +0900, Inha Song wrote:
> Hi, Charles,
> 
> I've already tried to change.
> If I change to that, we can't enter the suspen during the playback.
> 
> -
> [   72.538263] arizona spi1.0: Suspend, disabling IRQ
> ...
> [   72.585823] arizona spi1.0: Late suspend, reengabling IRQ
> [   72.585904] arizona spi1.0: Early resume, disabling IRQ
> ...
> [   72.646770] PM: noirq suspend of devices failed
> 		<- because of "spi1.0" pm_wakeup_pending() in suspend_noirq()

Ok this looks more reasonable, suspend should fail because we do
have an IRQ waiting to be handled, so we shouldn't suspend. But
you are saying this happens every time the CODEC goes to suspend,
thus blocking the suspend from suspending?

First step then would be to identify what IRQ is occurring, could
you set LOG_DEVICE at the top of drivers/base/regmap/regmap.c to
"spi1.0" and provide a log, so we can see what IRQ is being
asserted from the CODEC.

Thanks,
Charles

Re: [alsa-devel] [PATCH] mfd: arizona: Call the runtime PM function if the state is runtime resumed

[Inha Song]

 Hi, Charles,

I saw the log with LOG_DEVICE in regmap. But, I'm not sure the reason that suspend noirq failed is IRQ occuring.

Here is my log:
--
root@localhost:~# aplay test.wav 
[   40.831047] arizona spi1.0: Leaving AoD mode
[   40.834448] s3c64xx_spi_runtime_resume
[   40.834876] arizona spi1.0: d23 => 1
[   40.835029] s3c64xx_spi_runtime_suspend
[   40.846040] s3c64xx_spi_runtime_resume
[   40.846423] arizona spi1.0: d23 => 100
[   40.846557] s3c64xx_spi_runtime_suspend
[   40.846771] arizona spi1.0: d04 <= 100
[   40.846956] s3c64xx_spi_runtime_resume
[   40.852145] s3c64xx_spi_runtime_suspend
[   40.852386] s3c64xx_spi_runtime_resume
[   40.852894] s3c64xx_spi_runtime_suspend
[   40.854307] s3c64xx_spi_runtime_resume
[   40.858375] arizona spi1.0: d40 => 3
[   40.858410] s3c64xx_spi_runtime_suspend
[   40.865429] s3c64xx_spi_runtime_resume
[   40.869637] arizona spi1.0: d02 <= 2040
[   40.869671] s3c64xx_spi_runtime_suspend
[   40.876836] s3c64xx_spi_runtime_resume
[   40.880749] arizona spi1.0: Spurious HPDET IRQ
[   40.880773] arizona spi1.0: FLL1: Fref=24000000 Fout=135475200
[   40.880787] arizona spi1.0: FLL1: Fvco=90316800Hz
[   40.880793] s3c64xx_spi_runtime_suspend
[   40.880803] arizona spi1.0: FLL1: GCD=19200
[   40.880817] arizona spi1.0: FLL1: N=7 THETA=149 LAMBDA=271
[   40.880831] arizona spi1.0: FLL1: FRATIO=0(0) OUTDIV=2 REFCLK_DIV=1
[   40.880842] arizona spi1.0: FLL1: GAIN=4
[   40.880886] arizona spi1.0: 171 <= 1
[   40.880944] s3c64xx_spi_runtime_resume
[   40.881218] s3c64xx_spi_runtime_suspend
[   40.930152] s3c64xx_spi_runtime_resume
[   40.934071] arizona spi1.0: d26 => 1
[   40.934140] s3c64xx_spi_runtime_suspend
[   40.941237] arizona spi1.0: Mixer dropped sample
[   40.945901] s3c64xx_spi_runtime_resume
[   40.950067] arizona spi1.0: d40 => 3
[   40.950091] s3c64xx_spi_runtime_suspend
[   40.957025] s3c64xx_spi_runtime_resume
[   40.960971] arizona spi1.0: d04 <= 1
[   40.961006] s3c64xx_spi_runtime_suspend
[   40.968106] s3c64xx_spi_runtime_resume
[   40.971956] arizona spi1.0: FLL1: clock OK
[   40.971987] s3c64xx_spi_runtime_suspend
[   40.979751] arizona spi1.0: SYSCLK set to 135475200Hz
[   40.984742] wm5110-codec wm5110-codec: AIF1: BCLK 1411200Hz LRCLK 44100Hz
[   40.992144] arizona spi1.0: SYSCLK set to 135475200Hz
[   40.996646] arizona spi1.0: 101 <= 8644
[   41.000360] s3c64xx_spi_runtime_resume
[   41.004300] arizona spi1.0: 51a <= 1
[   41.004357] s3c64xx_spi_runtime_suspend
[   41.011499] s3c64xx_spi_runtime_resume
[   41.015689] arizona spi1.0: 400 <= 8
[   41.015692] s3c64xx_spi_runtime_suspend
[   41.022581] s3c64xx_spi_runtime_resume
[   41.026735] arizona spi1.0: d40 => 3
[   41.026737] s3c64xx_spi_runtime_suspend
[   41.033687] s3c64xx_spi_runtime_resume
[   41.037765] arizona spi1.0: d02 <= 40
[   41.037800] s3c64xx_spi_runtime_suspend
[   41.044883] s3c64xx_spi_runtime_resume
[   41.049054] arizona spi1.0: d26 => 8
[   41.049072] s3c64xx_spi_runtime_suspend
[   41.056043] arizona spi1.0: ASRC underclocked
....
[   72.308238] arizona spi1.0: Suspend, disabling IRQ
[   72.320286] arizona spi1.0: 400 <= 0
[   72.320310] s3c64xx_spi_runtime_resume
[   72.336047] arizona spi1.0: 51a <= 0
[   72.336217] arizona spi1.0: 101 <= 8604
[   72.336401] arizona spi1.0: 171 <= 3
[   72.336425] arizona spi1.0: 171 <= 2
[   72.336731] arizona spi1.0: 171 <= 0
[   72.336751] arizona spi1.0: SYSCLK cleared
[   72.338584] arizona spi1.0: SYSCLK cleared
[   72.339123] s3c64xx_spi_suspend
[   72.355866] arizona spi1.0: Late suspend, reenabling IRQ
[   72.355893] >>> noirq failed because of spi1
[   72.355948] arizona spi1.0: Early resume, disabling IRQ
[   72.416798] PM: noirq suspend of devices failed
......

Best Regards,
Inha Song.

On Tue, 22 Sep 2015 08:46:18 +0100
Charles Keepax <ckeepax@opensource.wolfsonmicro.com> wrote:

> On Mon, Sep 21, 2015 at 11:16:42AM +0900, Inha Song wrote:
> > Hi, Charles,
> > 
> > I've already tried to change.
> > If I change to that, we can't enter the suspen during the playback.
> > 
> > -
> > [   72.538263] arizona spi1.0: Suspend, disabling IRQ
> > ...
> > [   72.585823] arizona spi1.0: Late suspend, reengabling IRQ
> > [   72.585904] arizona spi1.0: Early resume, disabling IRQ
> > ...
> > [   72.646770] PM: noirq suspend of devices failed
> > 		<- because of "spi1.0" pm_wakeup_pending() in suspend_noirq()
> 
> Ok this looks more reasonable, suspend should fail because we do
> have an IRQ waiting to be handled, so we shouldn't suspend. But
> you are saying this happens every time the CODEC goes to suspend,
> thus blocking the suspend from suspending?
> 
> First step then would be to identify what IRQ is occurring, could
> you set LOG_DEVICE at the top of drivers/base/regmap/regmap.c to
> "spi1.0" and provide a log, so we can see what IRQ is being
> asserted from the CODEC.
> 
> Thanks,
> Charles
> 

Re: [alsa-devel] [PATCH] mfd: arizona: Call the runtime PM function if the state is runtime resumed

[Charles Keepax]

On Wed, Sep 23, 2015 at 11:04:04AM +0900, Inha Song wrote:
>  Hi, Charles,
> 
> I saw the log with LOG_DEVICE in regmap. But, I'm not sure the reason that suspend noirq failed is IRQ occuring.
> 
> Here is my log:
> --
> root@localhost:~# aplay test.wav 
> [   41.049072] s3c64xx_spi_runtime_suspend
> [   41.056043] arizona spi1.0: ASRC underclocked
> ....
> [   72.308238] arizona spi1.0: Suspend, disabling IRQ
> [   72.320286] arizona spi1.0: 400 <= 0
> [   72.320310] s3c64xx_spi_runtime_resume
> [   72.336047] arizona spi1.0: 51a <= 0
> [   72.336217] arizona spi1.0: 101 <= 8604
> [   72.336401] arizona spi1.0: 171 <= 3
> [   72.336425] arizona spi1.0: 171 <= 2
> [   72.336731] arizona spi1.0: 171 <= 0
> [   72.336751] arizona spi1.0: SYSCLK cleared
> [   72.338584] arizona spi1.0: SYSCLK cleared

This bit looks likely related to your problem, it looks like the
FLL is being turned off. My guess here would be that you haven't
called snd_soc_dapm_ignore_suspend from your machine driver, you
need to call this for all end points that may want to stay
powered up during system suspend and also set the ignore_suspend
flag on any DAI links you want to remain active during system
suspend.

Likely what is happening here is that you are disabling the FLL
and this is causing some IRQ which is then causing a wake event
thus aborting the suspend.

Thanks,
Charles

Re: [alsa-devel] [PATCH] mfd: arizona: Call the runtime PM function if the state is runtime resumed

[Inha Song]

Hi, Charles,

On Wed, 23 Sep 2015 15:43:12 +0100
Charles Keepax <ckeepax@opensource.wolfsonmicro.com> wrote:

> On Wed, Sep 23, 2015 at 11:04:04AM +0900, Inha Song wrote:
> >  Hi, Charles,
> > 
> > I saw the log with LOG_DEVICE in regmap. But, I'm not sure the reason that suspend noirq failed is IRQ occuring.
> > 
> > Here is my log:
> > --
> > root@localhost:~# aplay test.wav 
> > [   41.049072] s3c64xx_spi_runtime_suspend
> > [   41.056043] arizona spi1.0: ASRC underclocked
> > ....
> > [   72.308238] arizona spi1.0: Suspend, disabling IRQ
> > [   72.320286] arizona spi1.0: 400 <= 0
> > [   72.320310] s3c64xx_spi_runtime_resume
> > [   72.336047] arizona spi1.0: 51a <= 0
> > [   72.336217] arizona spi1.0: 101 <= 8604
> > [   72.336401] arizona spi1.0: 171 <= 3
> > [   72.336425] arizona spi1.0: 171 <= 2
> > [   72.336731] arizona spi1.0: 171 <= 0
> > [   72.336751] arizona spi1.0: SYSCLK cleared
> > [   72.338584] arizona spi1.0: SYSCLK cleared
> 
> This bit looks likely related to your problem, it looks like the
> FLL is being turned off. My guess here would be that you haven't
> called snd_soc_dapm_ignore_suspend from your machine driver, you
> need to call this for all end points that may want to stay
> powered up during system suspend and also set the ignore_suspend
> flag on any DAI links you want to remain active during system
> suspend.

But, We should call the trigger callback with SNDRV_PCM_TRIGGER_SUSPEND and *_RESUME command
for support senarios what suspend during the playback and resume.
So, I can't set the "ignore_suspend" in playback DAI.

For this reason, I would have called the runtime_suspend manually in arizona-core when suspend.

Best Reagrds,
Inha Song.

> 
> Likely what is happening here is that you are disabling the FLL
> and this is causing some IRQ which is then causing a wake event
> thus aborting the suspend.
> 
> Thanks,
> Charles

Re: [alsa-devel] [PATCH] mfd: arizona: Call the runtime PM function if the state is runtime resumed

[Charles Keepax]

On Thu, Sep 24, 2015 at 10:38:09AM +0900, Inha Song wrote:
> Hi, Charles,
> 
> On Wed, 23 Sep 2015 15:43:12 +0100
> Charles Keepax <ckeepax@opensource.wolfsonmicro.com> wrote:
> 
> > On Wed, Sep 23, 2015 at 11:04:04AM +0900, Inha Song wrote:
> > >  Hi, Charles,
> > > 
> > > I saw the log with LOG_DEVICE in regmap. But, I'm not sure the reason that suspend noirq failed is IRQ occuring.
> > > 
> > > Here is my log:
> > > --
> > > root@localhost:~# aplay test.wav 
> > > [   41.049072] s3c64xx_spi_runtime_suspend
> > > [   41.056043] arizona spi1.0: ASRC underclocked
> > > ....
> > > [   72.308238] arizona spi1.0: Suspend, disabling IRQ
> > > [   72.320286] arizona spi1.0: 400 <= 0
> > > [   72.320310] s3c64xx_spi_runtime_resume
> > > [   72.336047] arizona spi1.0: 51a <= 0
> > > [   72.336217] arizona spi1.0: 101 <= 8604
> > > [   72.336401] arizona spi1.0: 171 <= 3
> > > [   72.336425] arizona spi1.0: 171 <= 2
> > > [   72.336731] arizona spi1.0: 171 <= 0
> > > [   72.336751] arizona spi1.0: SYSCLK cleared
> > > [   72.338584] arizona spi1.0: SYSCLK cleared
> > 
> > This bit looks likely related to your problem, it looks like the
> > FLL is being turned off. My guess here would be that you haven't
> > called snd_soc_dapm_ignore_suspend from your machine driver, you
> > need to call this for all end points that may want to stay
> > powered up during system suspend and also set the ignore_suspend
> > flag on any DAI links you want to remain active during system
> > suspend.
> 
> But, We should call the trigger callback with SNDRV_PCM_TRIGGER_SUSPEND and *_RESUME command
> for support senarios what suspend during the playback and resume.
> So, I can't set the "ignore_suspend" in playback DAI.
> 
> For this reason, I would have called the runtime_suspend manually in arizona-core when suspend.
> 
> Best Reagrds,
> Inha Song.
> 

Ah ok so you want the audio to stop during suspend?

Ok in that case can we get a bit more of log, your log finished
up here:

[   72.308238] arizona spi1.0: Suspend, disabling IRQ
[   72.320286] arizona spi1.0: 400 <= 0
[   72.320310] s3c64xx_spi_runtime_resume
[   72.336047] arizona spi1.0: 51a <= 0
[   72.336217] arizona spi1.0: 101 <= 8604
[   72.336401] arizona spi1.0: 171 <= 3
[   72.336425] arizona spi1.0: 171 <= 2
[   72.336731] arizona spi1.0: 171 <= 0
[   72.336751] arizona spi1.0: SYSCLK cleared
[   72.338584] arizona spi1.0: SYSCLK cleared
[   72.339123] s3c64xx_spi_suspend
[   72.355866] arizona spi1.0: Late suspend, reenabling IRQ
[   72.355893] >>> noirq failed because of spi1
[   72.355948] arizona spi1.0: Early resume, disabling IRQ
[   72.416798] PM: noirq suspend of devices failed

Which finished too early as we can't see which IRQ it was that
triggered the wakeup.

Thanks,
Charles

Re: [alsa-devel] [PATCH] mfd: arizona: Call the runtime PM function if the state is runtime resumed

[Inha Song]

Hi, Charles,

On Thu, 24 Sep 2015 08:41:07 +0100
Charles Keepax <ckeepax@opensource.wolfsonmicro.com> wrote:

> On Thu, Sep 24, 2015 at 10:38:09AM +0900, Inha Song wrote:
> > Hi, Charles,
> > 
> > On Wed, 23 Sep 2015 15:43:12 +0100
> > Charles Keepax <ckeepax@opensource.wolfsonmicro.com> wrote:
> > 
> > > On Wed, Sep 23, 2015 at 11:04:04AM +0900, Inha Song wrote:
> > > >  Hi, Charles,
> > > > 
> > > > I saw the log with LOG_DEVICE in regmap. But, I'm not sure the reason that suspend noirq failed is IRQ occuring.
> > > > 
> > > > Here is my log:
> > > > --
> > > > root@localhost:~# aplay test.wav 
> > > > [   41.049072] s3c64xx_spi_runtime_suspend
> > > > [   41.056043] arizona spi1.0: ASRC underclocked
> > > > ....
> > > > [   72.308238] arizona spi1.0: Suspend, disabling IRQ
> > > > [   72.320286] arizona spi1.0: 400 <= 0
> > > > [   72.320310] s3c64xx_spi_runtime_resume
> > > > [   72.336047] arizona spi1.0: 51a <= 0
> > > > [   72.336217] arizona spi1.0: 101 <= 8604
> > > > [   72.336401] arizona spi1.0: 171 <= 3
> > > > [   72.336425] arizona spi1.0: 171 <= 2
> > > > [   72.336731] arizona spi1.0: 171 <= 0
> > > > [   72.336751] arizona spi1.0: SYSCLK cleared
> > > > [   72.338584] arizona spi1.0: SYSCLK cleared
> > > 
> > > This bit looks likely related to your problem, it looks like the
> > > FLL is being turned off. My guess here would be that you haven't
> > > called snd_soc_dapm_ignore_suspend from your machine driver, you
> > > need to call this for all end points that may want to stay
> > > powered up during system suspend and also set the ignore_suspend
> > > flag on any DAI links you want to remain active during system
> > > suspend.
> > 
> > But, We should call the trigger callback with SNDRV_PCM_TRIGGER_SUSPEND and *_RESUME command
> > for support senarios what suspend during the playback and resume.
> > So, I can't set the "ignore_suspend" in playback DAI.
> > 
> > For this reason, I would have called the runtime_suspend manually in arizona-core when suspend.
> > 
> > Best Reagrds,
> > Inha Song.
> > 
> 
> Ah ok so you want the audio to stop during suspend?

Yes, I want to stop when suspend and continuous play when resume.

> 
> Ok in that case can we get a bit more of log, your log finished
> up here:
> 
> [   72.308238] arizona spi1.0: Suspend, disabling IRQ
> [   72.320286] arizona spi1.0: 400 <= 0
> [   72.320310] s3c64xx_spi_runtime_resume
> [   72.336047] arizona spi1.0: 51a <= 0
> [   72.336217] arizona spi1.0: 101 <= 8604
> [   72.336401] arizona spi1.0: 171 <= 3
> [   72.336425] arizona spi1.0: 171 <= 2
> [   72.336731] arizona spi1.0: 171 <= 0
> [   72.336751] arizona spi1.0: SYSCLK cleared
> [   72.338584] arizona spi1.0: SYSCLK cleared
> [   72.339123] s3c64xx_spi_suspend
> [   72.355866] arizona spi1.0: Late suspend, reenabling IRQ
> [   72.355893] >>> noirq failed because of spi1
> [   72.355948] arizona spi1.0: Early resume, disabling IRQ
> [   72.416798] PM: noirq suspend of devices failed
> 
> Which finished too early as we can't see which IRQ it was that
> triggered the wakeup.

But, I can't find any spi regmap log that for IRQ.
--
[  114.282681] arizona spi1.0: Late suspend, reenabling IRQ
[  114.282708] >>> noirq failed because of spi1
[  114.282760] arizona spi1.0: Early resume, disabling IRQ
[  114.316510] PM: noirq suspend of devices failed
[  114.333590] s3c64xx_spi_resume

     -> set the FLL in machine for playback when resume.
[  114.334756] arizona spi1.0: FLL1: Fref=24000000 Fout=135475200
[  114.334762] arizona spi1.0: FLL1: Fvco=90316800Hz
[  114.334792] arizona spi1.0: FLL1: GCD=19200
[  114.334798] arizona spi1.0: FLL1: N=7 THETA=149 LAMBDA=271
[  114.334803] arizona spi1.0: FLL1: FRATIO=0(0) OUTDIV=2 REFCLK_DIV=1
[  114.334807] arizona spi1.0: FLL1: GAIN=4
[  114.334827] arizona spi1.0: 171 <= 1
[  114.520724] arizona spi1.0: Late resume, reenabling IRQ
[  114.521152] arizona spi1.0: d40 => 3
[  114.521387] arizona spi1.0: d04 <= 1
[  114.521500] arizona spi1.0: FLL1: clock OK
[  114.521773] arizona spi1.0: SYSCLK set to 135475200Hz
[  114.522651] arizona spi1.0: SYSCLK set to 135475200Hz
[  114.522752] arizona spi1.0: 101 <= 8644
[  114.522940] arizona spi1.0: 51a <= 1
[  114.523057] arizona spi1.0: 400 <= 8
[  114.909270] s3c64xx_spi_runtime_suspend
[  114.909721] done.
Suspended. Trying resume. Failed. Restarting stream. Done.

    -> retry to enter suspend Immediately.
[  115.478349] arizona spi1.0: Suspend, disabling IRQ
[  115.489783] arizona spi1.0: 400 <= 0
[  115.489804] s3c64xx_spi_runtime_resume
[  115.506127] arizona spi1.0: 51a <= 0
[  115.506298] arizona spi1.0: 101 <= 8604
[  115.506493] arizona spi1.0: 171 <= 3
[  115.506515] arizona spi1.0: 171 <= 2
[  115.506777] arizona spi1.0: 171 <= 0
[  115.506793] arizona spi1.0: SYSCLK cleared
[  115.507842] arizona spi1.0: SYSCLK cleared
[  115.508373] s3c64xx_spi_suspend                                                                                                     

[  115.523095] arizona spi1.0: Late suspend, reenabling IRQ                                                                            
[  115.523121] >>> noirq failed because of spi1                                                                                        
[  115.523171] arizona spi1.0: Early resume, disabling IRQ
[  115.556507] PM: noirq suspend of devices failed 
     -> Repeats:

Do you have any idea to check which IRQ was occur? 

Best Regards,
Inha Song.


> 
> Thanks,
> Charles

Re: [alsa-devel] [PATCH] mfd: arizona: Call the runtime PM function if the state is runtime resumed

[Charles Keepax]

On Fri, Sep 25, 2015 at 04:51:28PM +0900, Inha Song wrote:
> Hi, Charles,
> 
> On Thu, 24 Sep 2015 08:41:07 +0100
> Charles Keepax <ckeepax@opensource.wolfsonmicro.com> wrote:
> 
> > On Thu, Sep 24, 2015 at 10:38:09AM +0900, Inha Song wrote:
> > > Hi, Charles,
> > > 
> > > On Wed, 23 Sep 2015 15:43:12 +0100
> > > Charles Keepax <ckeepax@opensource.wolfsonmicro.com> wrote:
> > > 
> > > > On Wed, Sep 23, 2015 at 11:04:04AM +0900, Inha Song wrote:
> > > > >  Hi, Charles,
> > > > > 
> > > > > I saw the log with LOG_DEVICE in regmap. But, I'm not sure the reason that suspend noirq failed is IRQ occuring.
> > > > > 
> > > > > Here is my log:
> > > > > --
> > > > > root@localhost:~# aplay test.wav 
> > > > > [   41.049072] s3c64xx_spi_runtime_suspend
> But, I can't find any spi regmap log that for IRQ.
> --
> [  114.282681] arizona spi1.0: Late suspend, reenabling IRQ
> [  114.282708] >>> noirq failed because of spi1
> [  114.282760] arizona spi1.0: Early resume, disabling IRQ
> [  114.316510] PM: noirq suspend of devices failed
> [  114.333590] s3c64xx_spi_resume
> 
>      -> set the FLL in machine for playback when resume.
> [  114.334756] arizona spi1.0: FLL1: Fref=24000000 Fout=135475200
> [  114.334762] arizona spi1.0: FLL1: Fvco=90316800Hz
> [  114.334792] arizona spi1.0: FLL1: GCD=19200
> [  114.334798] arizona spi1.0: FLL1: N=7 THETA=149 LAMBDA=271
> [  114.334803] arizona spi1.0: FLL1: FRATIO=0(0) OUTDIV=2 REFCLK_DIV=1
> [  114.334807] arizona spi1.0: FLL1: GAIN=4
> [  114.334827] arizona spi1.0: 171 <= 1
> [  114.520724] arizona spi1.0: Late resume, reenabling IRQ
> [  114.521152] arizona spi1.0: d40 => 3
> [  114.521387] arizona spi1.0: d04 <= 1
> [  114.521500] arizona spi1.0: FLL1: clock OK
> [  114.521773] arizona spi1.0: SYSCLK set to 135475200Hz
> [  114.522651] arizona spi1.0: SYSCLK set to 135475200Hz
> [  114.522752] arizona spi1.0: 101 <= 8644
> [  114.522940] arizona spi1.0: 51a <= 1
> [  114.523057] arizona spi1.0: 400 <= 8
> [  114.909270] s3c64xx_spi_runtime_suspend
> [  114.909721] done.
> Suspended. Trying resume. Failed. Restarting stream. Done.
> 
>     -> retry to enter suspend Immediately.
> [  115.478349] arizona spi1.0: Suspend, disabling IRQ
> [  115.489783] arizona spi1.0: 400 <= 0
> [  115.489804] s3c64xx_spi_runtime_resume
> [  115.506127] arizona spi1.0: 51a <= 0
> [  115.506298] arizona spi1.0: 101 <= 8604
> [  115.506493] arizona spi1.0: 171 <= 3
> [  115.506515] arizona spi1.0: 171 <= 2
> [  115.506777] arizona spi1.0: 171 <= 0
> [  115.506793] arizona spi1.0: SYSCLK cleared
> [  115.507842] arizona spi1.0: SYSCLK cleared
> [  115.508373] s3c64xx_spi_suspend                                                                                                     
> 
> [  115.523095] arizona spi1.0: Late suspend, reenabling IRQ                                                                            
> [  115.523121] >>> noirq failed because of spi1                                                                                        
> [  115.523171] arizona spi1.0: Early resume, disabling IRQ
> [  115.556507] PM: noirq suspend of devices failed 
>      -> Repeats:
> 
> Do you have any idea to check which IRQ was occur? 

Hmm... yes that is odd whatever the IRQ was it appears to have
disappeared by the time we try to handle it.

Two things I would check next, is it perhaps electrical, is the
IRQ line getting pulled low for some reason other than an IRQ
being generated. For example are all the supplies being removed
from the CODEC and any pull-ups on that IRQ line? Perhaps then
when the system resumes the supplies are re-instated and the
false IRQ disappears. However this is probably unlikely as I
would expect to see an IRQ for boot done in this case.

Secondly, could you try taking the extcon driver out of the build
(CONFIG_EXTCON_ARIZONA), that should keep all the jack detect
disabled, which is probably the second most likely source of a
random IRQ from the chip.

I am attempting to reproduce your problem here, but alas
suspend/resume support on the Arndale board (our main dev system
at the moment) is pretty bad. If you know anyone your end who
might have any ideas why the SPI is totally unresponsive after
resume I would be happy to hear from them :-)

Thanks,
Charles