[alsa-devel] [PATCH] mfd: arizona: Call the runtime PM function if the state is runtime resumed
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;
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
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
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
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
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
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
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
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
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
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
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
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
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
participants (2)
-
Charles Keepax -
Inha Song