diff mbox

i2c: omap: revert "i2c: omap: switch to threaded IRQ support"

Message ID alpine.DEB.2.00.1210150148080.16624@utopia.booyaka.com (mailing list archive)
State New, archived
Headers show

Commit Message

Paul Walmsley Oct. 15, 2012, 1:51 a.m. UTC
Commit 3b2f8f82dad7d1f79cdc8fc05bd1c94baf109bde ("i2c: omap: switch to
threaded IRQ support") causes communication with I2C devices to fail
after system suspend/resume on all OMAP3 devices:

...
[   40.228576] PM: noirq resume of devices complete after 3.723 msecs
[   40.233184] PM: early resume of devices complete after 3.173 msecs
[   40.242736] [sched_delayed] sched: RT throttling activated
[   41.235046] omap_i2c omap_i2c.1: controller timed out
[   41.235351] twl: i2c_read failed to transfer all messages
[   41.235382] omap_hsmmc omap_hsmmc.0: could not set regulator OCR (-110)
[   41.396453] mmc0: error -110 during resume (card was removed?)
[   42.391754] omap_i2c omap_i2c.1: controller timed out
[   42.391876] twl: i2c_write failed to transfer all messages
[   42.391906] twl_rtc: Could not write TWLregister F - error -110
[   43.391326] omap_i2c omap_i2c.1: controller timed out
[   43.391479] twl: i2c_read failed to transfer all messages
[   43.391510] twl_rtc: Could not read TWLregister D - error -110
[   43.391540] twl_rtc twl_rtc: twl_rtc_read_time: reading CTRL_REG, error -110
[   43.392364] PM: resume of devices complete after 3158.935 msecs

When the root filesystem is on MMC, as in the above example, the
card's voltage regulator is not re-enabled and the filesystem becomes
inaccessible after resume.

Fix by reverting the conversion to a threaded IRQ handler.

Signed-off-by: Paul Walmsley <paul@pwsan.com>
Cc: Felipe Balbi <balbi@ti.com>
Cc: Shubhrajyoti D <shubhrajyoti@ti.com>
Cc: Wolfram Sang <w.sang@pengutronix.de>
Cc: Ben Dooks <ben-linux@fluff.org>
---
 drivers/i2c/busses/i2c-omap.c |   44 +++++++----------------------------------
 1 file changed, 7 insertions(+), 37 deletions(-)

Comments

Felipe Balbi Oct. 15, 2012, 7:16 a.m. UTC | #1
Hi,

On Mon, Oct 15, 2012 at 01:51:08AM +0000, Paul Walmsley wrote:
> 
> Commit 3b2f8f82dad7d1f79cdc8fc05bd1c94baf109bde ("i2c: omap: switch to
> threaded IRQ support") causes communication with I2C devices to fail
> after system suspend/resume on all OMAP3 devices:
> 
> ...
> [   40.228576] PM: noirq resume of devices complete after 3.723 msecs
> [   40.233184] PM: early resume of devices complete after 3.173 msecs
> [   40.242736] [sched_delayed] sched: RT throttling activated
> [   41.235046] omap_i2c omap_i2c.1: controller timed out

instead of just reverting the patch, I'd rather try to figure out why
controller times out in that situation.

It should make no difference if you're running an IRQ thread or not.

Do you have any extra debugging information which might help figuring
out what the issue really is ?

If the thread is actually at fault, then we need to add IRQF_NO_THREAD
to the IRQ flags, otherwise same issue will appear if we boot with
"threadirqs" kernel parameter.

> [   41.235351] twl: i2c_read failed to transfer all messages
> [   41.235382] omap_hsmmc omap_hsmmc.0: could not set regulator OCR (-110)
> [   41.396453] mmc0: error -110 during resume (card was removed?)
> [   42.391754] omap_i2c omap_i2c.1: controller timed out
> [   42.391876] twl: i2c_write failed to transfer all messages
> [   42.391906] twl_rtc: Could not write TWLregister F - error -110
> [   43.391326] omap_i2c omap_i2c.1: controller timed out
> [   43.391479] twl: i2c_read failed to transfer all messages
> [   43.391510] twl_rtc: Could not read TWLregister D - error -110
> [   43.391540] twl_rtc twl_rtc: twl_rtc_read_time: reading CTRL_REG, error -110
> [   43.392364] PM: resume of devices complete after 3158.935 msecs
> 
> When the root filesystem is on MMC, as in the above example, the
> card's voltage regulator is not re-enabled and the filesystem becomes
> inaccessible after resume.

but it fails because I2C times out and I'd like to understand why,
before just reverting the patch.

> Fix by reverting the conversion to a threaded IRQ handler.
> 
> Signed-off-by: Paul Walmsley <paul@pwsan.com>
> Cc: Felipe Balbi <balbi@ti.com>
> Cc: Shubhrajyoti D <shubhrajyoti@ti.com>
> Cc: Wolfram Sang <w.sang@pengutronix.de>
> Cc: Ben Dooks <ben-linux@fluff.org>
> ---
>  drivers/i2c/busses/i2c-omap.c |   44 +++++++----------------------------------
>  1 file changed, 7 insertions(+), 37 deletions(-)
> 
> diff --git a/drivers/i2c/busses/i2c-omap.c b/drivers/i2c/busses/i2c-omap.c
> index db31eae..e001c2a 100644
> --- a/drivers/i2c/busses/i2c-omap.c
> +++ b/drivers/i2c/busses/i2c-omap.c
> @@ -180,7 +180,6 @@ enum {
>  #define I2C_OMAP_ERRATA_I462		(1 << 1)
>  
>  struct omap_i2c_dev {
> -	spinlock_t		lock;		/* IRQ synchronization */
>  	struct device		*dev;
>  	void __iomem		*base;		/* virtual */
>  	int			irq;
> @@ -865,35 +864,13 @@ static int omap_i2c_transmit_data(struct omap_i2c_dev *dev, u8 num_bytes,
>  }
>  
>  static irqreturn_t
> -omap_i2c_isr(int irq, void *dev_id)
> +omap_i2c_isr(int this_irq, void *dev_id)
>  {
>  	struct omap_i2c_dev *dev = dev_id;
> -	irqreturn_t ret = IRQ_HANDLED;
> -	u16 mask;
> -	u16 stat;
> -
> -	spin_lock(&dev->lock);
> -	mask = omap_i2c_read_reg(dev, OMAP_I2C_IE_REG);
> -	stat = omap_i2c_read_reg(dev, OMAP_I2C_STAT_REG);
> -
> -	if (stat & mask)
> -		ret = IRQ_WAKE_THREAD;
> -
> -	spin_unlock(&dev->lock);
> -
> -	return ret;
> -}
> -
> -static irqreturn_t
> -omap_i2c_isr_thread(int this_irq, void *dev_id)
> -{
> -	struct omap_i2c_dev *dev = dev_id;
> -	unsigned long flags;
>  	u16 bits;
>  	u16 stat;
>  	int err = 0, count = 0;
>  
> -	spin_lock_irqsave(&dev->lock, flags);
>  	do {
>  		bits = omap_i2c_read_reg(dev, OMAP_I2C_IE_REG);
>  		stat = omap_i2c_read_reg(dev, OMAP_I2C_STAT_REG);
> @@ -907,7 +884,7 @@ omap_i2c_isr_thread(int this_irq, void *dev_id)
>  
>  		if (!stat) {
>  			/* my work here is done */
> -			goto out;
> +			return IRQ_HANDLED;
>  		}
>  
>  		dev_dbg(dev->dev, "IRQ (ISR = 0x%04x)\n", stat);
> @@ -1016,8 +993,6 @@ omap_i2c_isr_thread(int this_irq, void *dev_id)
>  	omap_i2c_complete_cmd(dev, err);
>  
>  out:
> -	spin_unlock_irqrestore(&dev->lock, flags);
> -
>  	return IRQ_HANDLED;
>  }
>  
> @@ -1062,6 +1037,7 @@ omap_i2c_probe(struct platform_device *pdev)
>  		pdev->dev.platform_data;
>  	struct device_node	*node = pdev->dev.of_node;
>  	const struct of_device_id *match;
> +	irq_handler_t isr;
>  	int irq;
>  	int r;
>  
> @@ -1110,8 +1086,6 @@ omap_i2c_probe(struct platform_device *pdev)
>  	dev->dev = &pdev->dev;
>  	dev->irq = irq;
>  
> -	spin_lock_init(&dev->lock);
> -
>  	platform_set_drvdata(pdev, dev);
>  	init_completion(&dev->cmd_complete);
>  
> @@ -1166,14 +1140,10 @@ omap_i2c_probe(struct platform_device *pdev)
>  	/* reset ASAP, clearing any IRQs */
>  	omap_i2c_init(dev);
>  
> -	if (dev->rev < OMAP_I2C_OMAP1_REV_2)
> -		r = devm_request_irq(&pdev->dev, dev->irq, omap_i2c_omap1_isr,
> -				IRQF_NO_SUSPEND, pdev->name, dev);
> -	else
> -		r = devm_request_threaded_irq(&pdev->dev, dev->irq,
> -				omap_i2c_isr, omap_i2c_isr_thread,
> -				IRQF_NO_SUSPEND | IRQF_ONESHOT,
> -				pdev->name, dev);
> +	isr = (dev->rev < OMAP_I2C_OMAP1_REV_2) ? omap_i2c_omap1_isr :
> +								   omap_i2c_isr;
> +	r = devm_request_irq(&pdev->dev, dev->irq, isr, IRQF_NO_SUSPEND,
> +			     pdev->name, dev);
>  
>  	if (r) {
>  		dev_err(dev->dev, "failure requesting irq %i\n", dev->irq);
> -- 
> 1.7.10.4
Paul Walmsley Oct. 15, 2012, 3:05 p.m. UTC | #2
Hi

On Mon, 15 Oct 2012, Felipe Balbi wrote:

> On Mon, Oct 15, 2012 at 01:51:08AM +0000, Paul Walmsley wrote:
> > 
> > Commit 3b2f8f82dad7d1f79cdc8fc05bd1c94baf109bde ("i2c: omap: switch to
> > threaded IRQ support") causes communication with I2C devices to fail
> > after system suspend/resume on all OMAP3 devices:
> > 
> > ...
> > [   40.228576] PM: noirq resume of devices complete after 3.723 msecs
> > [   40.233184] PM: early resume of devices complete after 3.173 msecs
> > [   40.242736] [sched_delayed] sched: RT throttling activated
> > [   41.235046] omap_i2c omap_i2c.1: controller timed out
> 
> instead of just reverting the patch, I'd rather try to figure out why
> controller times out in that situation.
> 
> It should make no difference if you're running an IRQ thread or not.
> 
> Do you have any extra debugging information which might help figuring
> out what the issue really is ?

As mentioned, the problem can be easily reproduced on OMAP3 is test by 
running

"echo mem > /sys/power/state"

in userspace when rootfs is on MMC.  Then wake up out of suspend, for 
example, by hitting ENTER on the serial console.

This needs to be part of the testing before any OMAP patches are posted to 
the lists -- if for no other reason than because Android kernels enter and 
exit system suspend frequently as part of their standard usage model.

> If the thread is actually at fault, then we need to add IRQF_NO_THREAD
> to the IRQ flags, otherwise same issue will appear if we boot with
> "threadirqs" kernel parameter.

...

> but it fails because I2C times out and I'd like to understand why,
> before just reverting the patch.

It doesn't matter to me how it's fixed as long as it's fixed quickly 
during the early 3.7-rcs.  


- Paul
Shubhrajyoti Datta Oct. 16, 2012, 12:58 p.m. UTC | #3
On Mon, Oct 15, 2012 at 7:21 AM, Paul Walmsley <paul@pwsan.com> wrote:
>
> Commit 3b2f8f82dad7d1f79cdc8fc05bd1c94baf109bde ("i2c: omap: switch to
> threaded IRQ support") causes communication with I2C devices to fail
> after system suspend/resume on all OMAP3 devices:
>
Could you tell me which  omap3 platform

On Beagle Xm
after
mount /dev/mmcblk  /mmcfs


# mount /dev/mmcblk0p2 /mmcfs/
[  412.480041] kjournald starting.  Commit interval 5 seconds
[  412.490020] EXT3-fs (mmcblk0p2): using internal journal
[  412.495605] EXT3-fs (mmcblk0p2): mounted filesystem with ordered data mode
#


# cd /mmcfs/
#
#
# ls
bin                   omap3_usb_prcm.sh     usb_prcm.sh
dev                   omap3_usbhs_off.sh    usb_uhh_show.sh
etc                   omap3_usbhs_on.sh     usb_uhh_tll.sh
init                  proc                  usbhs_clk_disable.sh
lib                   readmem.dat           usbhs_clk_enable.sh
lost+found            root                  usbhs_set_sm.sh
mnt                   sbin                  usbhs_show.sh
modules               sys                   usr
msc                   tmp                   var
omap3_ehcidump.sh     usb_omap3.sh
#
#
# echo mem > /sys/power/state
[  464.785461] PM: Syncing filesystems ... done.
[  464.791442] PM: Preparing system for mem sleep
[  464.798034] Freezing user space processes ... (elapsed 0.02 seconds) done.
[  464.827301] Freezing remaining freezable tasks ... (elapsed 0.02
seconds) done.
[  464.858703] PM: Entering mem sleep
[  464.862304] Suspending console(s) (use no_console_suspend to debug)
[  464.994415] PM: suspend of devices complete after 121.002 msecs
[  464.998107] PM: late suspend of devices complete after 3.662 msecs
[  465.003173] PM: noirq suspend of devices complete after 5.004 msecs
[  465.003173] Disabling non-boot CPUs ...
[  466.225585] Successfully put all powerdomains to target state
[  466.228942] PM: noirq resume of devices complete after 3.051 msecs
[  466.232421] PM: early resume of devices complete after 2.349 msecs
[  467.492645] PM: resume of devices complete after 1260.131 msecs
[  467.546936] PM: Finishing wakeup.
[  467.550415] Restarting tasks ... done.
#
#
# cat /debug/pm_debug/count | grep per_pwrdm
per_pwrdm (ON),OFF:7,RET:0,INA:0,ON:8,RET-LOGIC-OFF:0,RET-MEMBANK1-OFF:0
per_clkdm->per_pwrdm (17)
# echo mem > /sys/power/state
[ 1492.225311] PM: Syncing filesystems ... done.
[ 1492.232177] PM: Preparing system for mem sleep
[ 1492.238830] Freezing user space processes ... (elapsed 0.02 seconds) done.
[ 1492.268188] Freezing remaining freezable tasks ... (elapsed 0.02
seconds) done.
[ 1492.299804] PM: Entering mem sleep
[ 1492.303375] Suspending console(s) (use no_console_suspend to debug)
[ 1492.435333] PM: suspend of devices complete after 120.880 msecs
[ 1492.439025] PM: late suspend of devices complete after 3.692 msecs
[ 1492.444091] PM: noirq suspend of devices complete after 5.004 msecs
[ 1492.444091] Disabling non-boot CPUs ...
[ 1493.745544] Successfully put all powerdomains to target state
[ 1493.748901] PM: noirq resume of devices complete after 3.051 msecs
[ 1493.752319] PM: early resume of devices complete after 2.319 msecs
[ 1494.794067] PM: resume of devices complete after 1041.625 msecs
[ 1494.848388] PM: Finishing wakeup.
[ 1494.851867] Restarting tasks ... done.
#
#
# cat /debug/pm_debug/count | grep per_pwrdm
per_pwrdm (ON),OFF:8,RET:0,INA:0,ON:9,RET-LOGIC-OFF:0,RET-MEMBANK1-OFF:0
per_clkdm->per_pwrdm (17)
#

Anyways will retry with fs on mmc.
Felipe Balbi Oct. 16, 2012, 1:33 p.m. UTC | #4
Hi,

+ Thomas Gleixner

On Tue, Oct 16, 2012 at 06:28:13PM +0530, Shubhrajyoti Datta wrote:
> On Mon, Oct 15, 2012 at 7:21 AM, Paul Walmsley <paul@pwsan.com> wrote:
> >
> > Commit 3b2f8f82dad7d1f79cdc8fc05bd1c94baf109bde ("i2c: omap: switch to
> > threaded IRQ support") causes communication with I2C devices to fail
> > after system suspend/resume on all OMAP3 devices:
> >
> Could you tell me which  omap3 platform
> 
> On Beagle Xm
> after
> mount /dev/mmcblk  /mmcfs
> 
> 
> # mount /dev/mmcblk0p2 /mmcfs/
> [  412.480041] kjournald starting.  Commit interval 5 seconds
> [  412.490020] EXT3-fs (mmcblk0p2): using internal journal
> [  412.495605] EXT3-fs (mmcblk0p2): mounted filesystem with ordered data mode
> #
> 
> 
> # cd /mmcfs/
> #
> #
> # ls
> bin                   omap3_usb_prcm.sh     usb_prcm.sh
> dev                   omap3_usbhs_off.sh    usb_uhh_show.sh
> etc                   omap3_usbhs_on.sh     usb_uhh_tll.sh
> init                  proc                  usbhs_clk_disable.sh
> lib                   readmem.dat           usbhs_clk_enable.sh
> lost+found            root                  usbhs_set_sm.sh
> mnt                   sbin                  usbhs_show.sh
> modules               sys                   usr
> msc                   tmp                   var
> omap3_ehcidump.sh     usb_omap3.sh
> #
> #
> # echo mem > /sys/power/state
> [  464.785461] PM: Syncing filesystems ... done.
> [  464.791442] PM: Preparing system for mem sleep
> [  464.798034] Freezing user space processes ... (elapsed 0.02 seconds) done.
> [  464.827301] Freezing remaining freezable tasks ... (elapsed 0.02
> seconds) done.
> [  464.858703] PM: Entering mem sleep
> [  464.862304] Suspending console(s) (use no_console_suspend to debug)
> [  464.994415] PM: suspend of devices complete after 121.002 msecs
> [  464.998107] PM: late suspend of devices complete after 3.662 msecs
> [  465.003173] PM: noirq suspend of devices complete after 5.004 msecs
> [  465.003173] Disabling non-boot CPUs ...
> [  466.225585] Successfully put all powerdomains to target state
> [  466.228942] PM: noirq resume of devices complete after 3.051 msecs
> [  466.232421] PM: early resume of devices complete after 2.349 msecs
> [  467.492645] PM: resume of devices complete after 1260.131 msecs
> [  467.546936] PM: Finishing wakeup.
> [  467.550415] Restarting tasks ... done.
> #
> #
> # cat /debug/pm_debug/count | grep per_pwrdm
> per_pwrdm (ON),OFF:7,RET:0,INA:0,ON:8,RET-LOGIC-OFF:0,RET-MEMBANK1-OFF:0
> per_clkdm->per_pwrdm (17)
> # echo mem > /sys/power/state
> [ 1492.225311] PM: Syncing filesystems ... done.
> [ 1492.232177] PM: Preparing system for mem sleep
> [ 1492.238830] Freezing user space processes ... (elapsed 0.02 seconds) done.
> [ 1492.268188] Freezing remaining freezable tasks ... (elapsed 0.02
> seconds) done.
> [ 1492.299804] PM: Entering mem sleep
> [ 1492.303375] Suspending console(s) (use no_console_suspend to debug)
> [ 1492.435333] PM: suspend of devices complete after 120.880 msecs
> [ 1492.439025] PM: late suspend of devices complete after 3.692 msecs
> [ 1492.444091] PM: noirq suspend of devices complete after 5.004 msecs
> [ 1492.444091] Disabling non-boot CPUs ...
> [ 1493.745544] Successfully put all powerdomains to target state
> [ 1493.748901] PM: noirq resume of devices complete after 3.051 msecs
> [ 1493.752319] PM: early resume of devices complete after 2.319 msecs
> [ 1494.794067] PM: resume of devices complete after 1041.625 msecs
> [ 1494.848388] PM: Finishing wakeup.
> [ 1494.851867] Restarting tasks ... done.
> #
> #
> # cat /debug/pm_debug/count | grep per_pwrdm
> per_pwrdm (ON),OFF:8,RET:0,INA:0,ON:9,RET-LOGIC-OFF:0,RET-MEMBANK1-OFF:0
> per_clkdm->per_pwrdm (17)
> #
> 
> Anyways will retry with fs on mmc.

rootfs has to be on MMC to trigger this. The problem happens because
omap_hsmmc calls enable_irq() on its resume method. That IRQ line is
actually a GPIO from TWL4030, so
twl4030-irq.c::twl4030_sih_bus_sync_unlock() will be called, which will
trigger an I2C transfer.

The problem I see is that even though we properly return IRQ_WAKE_THREAD
and wake_up_process() manages to wakeup the IRQ thread (it returns 1),
the thread is never scheduled. To make things even worse, ouw irq thread
runs once, but doesn't run on a consecutive call. Here's some (rather
nasty) debug prints showing the problem:

> [   78.709381] omap_i2c omap_i2c.1: omap_i2c_isr_thread 913
> [   78.715026] omap_i2c omap_i2c.1: omap_i2c_isr_thread 1038
> [   78.720733] omap_i2c omap_i2c.1: omap_i2c_xfer 655
> [   78.725769] omap_i2c omap_i2c.1: omap_i2c_xfer 659
> [   78.730804] omap_i2c omap_i2c.1: omap_i2c_xfer 663
> [   78.735870] omap_i2c omap_i2c.1: omap_i2c_xfer 668
> [   78.850708] PM: suspend of devices complete after 1287.841 msecs
> [   78.860870] PM: late suspend of devices complete after 3.753 msecs
> [   78.872283] try_to_wake_up 1411
> [   78.875701] try_to_wake_up 1411
> [   78.879028] try_to_wake_up 1411
> [   78.882537] omap_i2c omap_i2c.1: omap_i2c_runtime_suspend 1359
> [   78.888763] omap_i2c omap_i2c.1: omap_i2c_low_level_suspend 1261
> [   78.895416] PM: noirq suspend of devices complete after 28.015 msecs
> [   78.902160] Disabling non-boot CPUs ...
> [   88.568664] Powerdomain (per_pwrdm) didn't enter target state 1
> [   88.574859] Powerdomain (core_pwrdm) didn't enter target state 1
> [   88.581115] Could not enter target state in pm_suspend
> [   88.586975] omap_i2c omap_i2c.1: omap_i2c_runtime_resume 1373
> [   88.592987] omap_i2c omap_i2c.1: omap_i2c_low_level_resume 1287
> [   88.599243] try_to_wake_up 1411
> [   88.602569] try_to_wake_up 1411
> [   88.608459] PM: noirq resume of devices complete after 21.759 msecs
> [   88.615814] try_to_wake_up 1411
> [   88.622497] PM: early resume of devices complete after 2.380 msecs
> [   88.632965] omap_i2c omap_i2c.1: omap_i2c_xfer 626
> [   88.638092] omap_i2c omap_i2c.1: omap_i2c_xfer 632
> [   88.643188] omap_i2c omap_i2c.1: omap_i2c_xfer 648
> [   88.648193] omap_i2c omap_i2c.1: addr: 0x0049, len: 4, flags: 0x0, stop: 1
> [   88.655456] omap_i2c omap_i2c.1: omap_i2c_xfer_msg 537
> [   88.660858] omap_i2c omap_i2c.1: omap_i2c_isr 885
> [   88.665802] omap_i2c omap_i2c.1: omap_i2c_isr 891: mask 601f stat 1510
> [   88.672637] omap_i2c omap_i2c.1: omap_i2c_isr 894
> [   88.677551] omap_i2c omap_i2c.1: omap_i2c_isr 899
> [   88.682495] ===> irq_wake_thread 139: IRQ 72 wake_up_process 1
> [   88.688751] omap_i2c omap_i2c.1: omap_i2c_isr_thread 913
> [   88.694335] omap_i2c omap_i2c.1: omap_i2c_isr_thread 1038
> [   88.700347] omap_i2c omap_i2c.1: omap_i2c_isr 885
> [   88.705291] omap_i2c omap_i2c.1: omap_i2c_isr 891: mask 601f stat 0104
> [   88.712097] omap_i2c omap_i2c.1: omap_i2c_isr 894
> [   88.717010] omap_i2c omap_i2c.1: omap_i2c_isr 899
> [   88.721923] try_to_wake_up 1411
> [   88.725189] ===> irq_wake_thread 139: IRQ 72 wake_up_process 0
> [   88.731292] [sched_delayed] sched: RT throttling activated
> [   88.737091] omap_i2c omap_i2c.1: omap_i2c_isr_thread 913
> [   88.742706] omap_i2c omap_i2c.1: omap_i2c_isr_thread 1038

this is the last time our omap_i2c_isr_thread() runs. Note that the
thread was already running when wake_up_process() was called.

> [   88.749206] omap_i2c omap_i2c.1: omap_i2c_xfer 655
> [   88.754302] omap_i2c omap_i2c.1: omap_i2c_xfer 659
> [   88.759368] omap_i2c omap_i2c.1: omap_i2c_xfer 663
> [   88.764373] omap_i2c omap_i2c.1: omap_i2c_xfer 668
> [   88.769531] omap_i2c omap_i2c.1: omap_i2c_xfer 626
> [   88.774597] omap_i2c omap_i2c.1: omap_i2c_xfer 632
> [   88.779602] omap_i2c omap_i2c.1: omap_i2c_xfer 648
> [   88.784667] omap_i2c omap_i2c.1: addr: 0x004b, len: 1, flags: 0x0, stop: 0
> [   88.791900] omap_i2c omap_i2c.1: omap_i2c_xfer_msg 537
> [   88.797271] omap_i2c omap_i2c.1: omap_i2c_isr 885
> [   88.802185] omap_i2c omap_i2c.1: omap_i2c_isr 891: mask 601f stat 1510
> [   88.809020] omap_i2c omap_i2c.1: omap_i2c_isr 894
> [   88.813934] omap_i2c omap_i2c.1: omap_i2c_isr 899
> [   88.818847] ===> irq_wake_thread 139: IRQ 72 wake_up_process 1

notice here that our omap_i2c_isr_thread() never runs. I'm still
debugging, trying to pin point what the real issue is, but it's
definitely not the fact that we have a threaded ISR, since it runs at
least once.

> [   90.610107] try_to_wake_up 1411
> [   93.821044] try_to_wake_up 1411
> [   93.824768] omap_i2c omap_i2c.1: controller timed out
> [   93.830169] [<c001c118>] (unwind_backtrace+0x0/0xf0) from [<c040c738>] (omap_i2c_xfer_msg+0x314/0x360)
> [   93.839935] [<c040c738>] (omap_i2c_xfer_msg+0x314/0x360) from [<c040d26c>] (omap_i2c_xfer+0xac/0x220)
> [   93.849639] [<c040d26c>] (omap_i2c_xfer+0xac/0x220) from [<c040884c>] (__i2c_transfer+0x40/0x80)
> [   93.858886] [<c040884c>] (__i2c_transfer+0x40/0x80) from [<c0409da8>] (i2c_transfer+0x1f8/0x26c)
> [   93.868103] [<c0409da8>] (i2c_transfer+0x1f8/0x26c) from [<c035dab8>] (twl_i2c_read+0xc4/0x15c)
> [   93.877288] [<c035dab8>] (twl_i2c_read+0xc4/0x15c) from [<c03189f4>] (twl4030ldo_get_voltage+0x28/0x60)
> [   93.887145] [<c03189f4>] (twl4030ldo_get_voltage+0x28/0x60) from [<c03120b0>] (_regulator_get_voltage+0x68/0x84)
> [   93.897827] [<c03120b0>] (_regulator_get_voltage+0x68/0x84) from [<c03125a0>] (regulator_get_voltage+0x20/0x38)
> [   93.908447] [<c03125a0>] (regulator_get_voltage+0x20/0x38) from [<c0411bcc>] (mmc_regulator_set_ocr+0x40/0x12c)
> [   93.919036] [<c0411bcc>] (mmc_regulator_set_ocr+0x40/0x12c) from [<c0426418>] (omap_hsmmc_set_power+0xe4/0x11c)
> [   93.929626] [<c0426418>] (omap_hsmmc_set_power+0xe4/0x11c) from [<c042582c>] (omap_hsmmc_set_ios+0x140/0x150)
> [   93.940032] [<c042582c>] (omap_hsmmc_set_ios+0x140/0x150) from [<c04135c4>] (mmc_power_up+0x80/0xc4)
> [   93.949615] [<c04135c4>] (mmc_power_up+0x80/0xc4) from [<c04136d8>] (mmc_resume_host+0xd0/0x150)
> [   93.958862] [<c04136d8>] (mmc_resume_host+0xd0/0x150) from [<c0426b5c>] (omap_hsmmc_resume+0x7c/0xc8)
> [   93.968536] [<c0426b5c>] (omap_hsmmc_resume+0x7c/0xc8) from [<c0347a78>] (platform_pm_resume+0x2c/0x50)
> [   93.978424] [<c0347a78>] (platform_pm_resume+0x2c/0x50) from [<c034bca4>] (dpm_run_callback.isra.4+0x2c/0x64)
> [   93.988830] [<c034bca4>] (dpm_run_callback.isra.4+0x2c/0x64) from [<c034ca48>] (device_resume+0xdc/0x18c)
> [   93.998870] [<c034ca48>] (device_resume+0xdc/0x18c) from [<c034ce8c>] (dpm_resume+0xfc/0x21c)
> [   94.007812] [<c034ce8c>] (dpm_resume+0xfc/0x21c) from [<c034d094>] (dpm_resume_end+0xc/0x18)
> [   94.016723] [<c034d094>] (dpm_resume_end+0xc/0x18) from [<c0087b14>] (suspend_devices_and_enter+0xe8/0x1b0)
> [   94.026947] [<c0087b14>] (suspend_devices_and_enter+0xe8/0x1b0) from [<c0087c78>] (enter_state+0x9c/0xdc)
> [   94.036987] [<c0087c78>] (enter_state+0x9c/0xdc) from [<c0087ccc>] (pm_suspend+0x14/0x70)
> [   94.045593] [<c0087ccc>] (pm_suspend+0x14/0x70) from [<c0086d34>] (state_store+0x30/0x3c)
> [   94.054199] [<c0086d34>] (state_store+0x30/0x3c) from [<c02d39b8>] (kobj_attr_store+0x14/0x20)
> [   94.063262] [<c02d39b8>] (kobj_attr_store+0x14/0x20) from [<c017bcd0>] (sysfs_write_file+0x80/0xb4)
> [   94.072784] [<c017bcd0>] (sysfs_write_file+0x80/0xb4) from [<c01174c4>] (vfs_write+0xa8/0x138)
> [   94.081817] [<c01174c4>] (vfs_write+0xa8/0x138) from [<c0117730>] (sys_write+0x40/0x68)
> [   94.090240] [<c0117730>] (sys_write+0x40/0x68) from [<c0013f40>] (ret_fast_syscall+0x0/0x3c)
> [   94.099334] omap_i2c omap_i2c.1: omap_i2c_xfer 655
> [   94.104431] omap_i2c omap_i2c.1: omap_i2c_xfer 659
> [   94.109466] omap_i2c omap_i2c.1: omap_i2c_xfer 663
> [   94.114532] omap_i2c omap_i2c.1: omap_i2c_xfer 668
> [   94.119567] twl: i2c_read failed to transfer all messages
> [   94.125244] omap_hsmmc omap_hsmmc.0: could not set regulator OCR (-110)
> [   94.286773] mmc0: error -110 during resume (card was removed?)
Felipe Balbi Oct. 16, 2012, 1:37 p.m. UTC | #5
Hi again,

On Tue, Oct 16, 2012 at 04:33:56PM +0300, Felipe Balbi wrote:
> Hi,
> 
> + Thomas Gleixner
> 
> On Tue, Oct 16, 2012 at 06:28:13PM +0530, Shubhrajyoti Datta wrote:
> > On Mon, Oct 15, 2012 at 7:21 AM, Paul Walmsley <paul@pwsan.com> wrote:
> > >
> > > Commit 3b2f8f82dad7d1f79cdc8fc05bd1c94baf109bde ("i2c: omap: switch to
> > > threaded IRQ support") causes communication with I2C devices to fail
> > > after system suspend/resume on all OMAP3 devices:
> > >
> > Could you tell me which  omap3 platform
> > 
> > On Beagle Xm
> > after
> > mount /dev/mmcblk  /mmcfs
> > 
> > 
> > # mount /dev/mmcblk0p2 /mmcfs/
> > [  412.480041] kjournald starting.  Commit interval 5 seconds
> > [  412.490020] EXT3-fs (mmcblk0p2): using internal journal
> > [  412.495605] EXT3-fs (mmcblk0p2): mounted filesystem with ordered data mode
> > #
> > 
> > 
> > # cd /mmcfs/
> > #
> > #
> > # ls
> > bin                   omap3_usb_prcm.sh     usb_prcm.sh
> > dev                   omap3_usbhs_off.sh    usb_uhh_show.sh
> > etc                   omap3_usbhs_on.sh     usb_uhh_tll.sh
> > init                  proc                  usbhs_clk_disable.sh
> > lib                   readmem.dat           usbhs_clk_enable.sh
> > lost+found            root                  usbhs_set_sm.sh
> > mnt                   sbin                  usbhs_show.sh
> > modules               sys                   usr
> > msc                   tmp                   var
> > omap3_ehcidump.sh     usb_omap3.sh
> > #
> > #
> > # echo mem > /sys/power/state
> > [  464.785461] PM: Syncing filesystems ... done.
> > [  464.791442] PM: Preparing system for mem sleep
> > [  464.798034] Freezing user space processes ... (elapsed 0.02 seconds) done.
> > [  464.827301] Freezing remaining freezable tasks ... (elapsed 0.02
> > seconds) done.
> > [  464.858703] PM: Entering mem sleep
> > [  464.862304] Suspending console(s) (use no_console_suspend to debug)
> > [  464.994415] PM: suspend of devices complete after 121.002 msecs
> > [  464.998107] PM: late suspend of devices complete after 3.662 msecs
> > [  465.003173] PM: noirq suspend of devices complete after 5.004 msecs
> > [  465.003173] Disabling non-boot CPUs ...
> > [  466.225585] Successfully put all powerdomains to target state
> > [  466.228942] PM: noirq resume of devices complete after 3.051 msecs
> > [  466.232421] PM: early resume of devices complete after 2.349 msecs
> > [  467.492645] PM: resume of devices complete after 1260.131 msecs
> > [  467.546936] PM: Finishing wakeup.
> > [  467.550415] Restarting tasks ... done.
> > #
> > #
> > # cat /debug/pm_debug/count | grep per_pwrdm
> > per_pwrdm (ON),OFF:7,RET:0,INA:0,ON:8,RET-LOGIC-OFF:0,RET-MEMBANK1-OFF:0
> > per_clkdm->per_pwrdm (17)
> > # echo mem > /sys/power/state
> > [ 1492.225311] PM: Syncing filesystems ... done.
> > [ 1492.232177] PM: Preparing system for mem sleep
> > [ 1492.238830] Freezing user space processes ... (elapsed 0.02 seconds) done.
> > [ 1492.268188] Freezing remaining freezable tasks ... (elapsed 0.02
> > seconds) done.
> > [ 1492.299804] PM: Entering mem sleep
> > [ 1492.303375] Suspending console(s) (use no_console_suspend to debug)
> > [ 1492.435333] PM: suspend of devices complete after 120.880 msecs
> > [ 1492.439025] PM: late suspend of devices complete after 3.692 msecs
> > [ 1492.444091] PM: noirq suspend of devices complete after 5.004 msecs
> > [ 1492.444091] Disabling non-boot CPUs ...
> > [ 1493.745544] Successfully put all powerdomains to target state
> > [ 1493.748901] PM: noirq resume of devices complete after 3.051 msecs
> > [ 1493.752319] PM: early resume of devices complete after 2.319 msecs
> > [ 1494.794067] PM: resume of devices complete after 1041.625 msecs
> > [ 1494.848388] PM: Finishing wakeup.
> > [ 1494.851867] Restarting tasks ... done.
> > #
> > #
> > # cat /debug/pm_debug/count | grep per_pwrdm
> > per_pwrdm (ON),OFF:8,RET:0,INA:0,ON:9,RET-LOGIC-OFF:0,RET-MEMBANK1-OFF:0
> > per_clkdm->per_pwrdm (17)
> > #
> > 
> > Anyways will retry with fs on mmc.
> 
> rootfs has to be on MMC to trigger this. The problem happens because
> omap_hsmmc calls enable_irq() on its resume method. That IRQ line is
> actually a GPIO from TWL4030, so
> twl4030-irq.c::twl4030_sih_bus_sync_unlock() will be called, which will
> trigger an I2C transfer.
> 
> The problem I see is that even though we properly return IRQ_WAKE_THREAD
> and wake_up_process() manages to wakeup the IRQ thread (it returns 1),
> the thread is never scheduled. To make things even worse, ouw irq thread
> runs once, but doesn't run on a consecutive call. Here's some (rather

another detail here:

if I drop the disable_irq()/enable_irq() from omap_hsmmc driver,
everything ends up being fine, so I'm wondering if we have a race
between omap_hsmmc, twl4030 card detect GPIO and I2C, but I'm not sure
yet.

> nasty) debug prints showing the problem:
> 
> > [   78.709381] omap_i2c omap_i2c.1: omap_i2c_isr_thread 913
> > [   78.715026] omap_i2c omap_i2c.1: omap_i2c_isr_thread 1038
> > [   78.720733] omap_i2c omap_i2c.1: omap_i2c_xfer 655
> > [   78.725769] omap_i2c omap_i2c.1: omap_i2c_xfer 659
> > [   78.730804] omap_i2c omap_i2c.1: omap_i2c_xfer 663
> > [   78.735870] omap_i2c omap_i2c.1: omap_i2c_xfer 668
> > [   78.850708] PM: suspend of devices complete after 1287.841 msecs
> > [   78.860870] PM: late suspend of devices complete after 3.753 msecs
> > [   78.872283] try_to_wake_up 1411
> > [   78.875701] try_to_wake_up 1411
> > [   78.879028] try_to_wake_up 1411
> > [   78.882537] omap_i2c omap_i2c.1: omap_i2c_runtime_suspend 1359
> > [   78.888763] omap_i2c omap_i2c.1: omap_i2c_low_level_suspend 1261
> > [   78.895416] PM: noirq suspend of devices complete after 28.015 msecs
> > [   78.902160] Disabling non-boot CPUs ...
> > [   88.568664] Powerdomain (per_pwrdm) didn't enter target state 1
> > [   88.574859] Powerdomain (core_pwrdm) didn't enter target state 1
> > [   88.581115] Could not enter target state in pm_suspend
> > [   88.586975] omap_i2c omap_i2c.1: omap_i2c_runtime_resume 1373
> > [   88.592987] omap_i2c omap_i2c.1: omap_i2c_low_level_resume 1287
> > [   88.599243] try_to_wake_up 1411
> > [   88.602569] try_to_wake_up 1411
> > [   88.608459] PM: noirq resume of devices complete after 21.759 msecs
> > [   88.615814] try_to_wake_up 1411
> > [   88.622497] PM: early resume of devices complete after 2.380 msecs
> > [   88.632965] omap_i2c omap_i2c.1: omap_i2c_xfer 626
> > [   88.638092] omap_i2c omap_i2c.1: omap_i2c_xfer 632
> > [   88.643188] omap_i2c omap_i2c.1: omap_i2c_xfer 648
> > [   88.648193] omap_i2c omap_i2c.1: addr: 0x0049, len: 4, flags: 0x0, stop: 1
> > [   88.655456] omap_i2c omap_i2c.1: omap_i2c_xfer_msg 537
> > [   88.660858] omap_i2c omap_i2c.1: omap_i2c_isr 885
> > [   88.665802] omap_i2c omap_i2c.1: omap_i2c_isr 891: mask 601f stat 1510
> > [   88.672637] omap_i2c omap_i2c.1: omap_i2c_isr 894
> > [   88.677551] omap_i2c omap_i2c.1: omap_i2c_isr 899
> > [   88.682495] ===> irq_wake_thread 139: IRQ 72 wake_up_process 1
> > [   88.688751] omap_i2c omap_i2c.1: omap_i2c_isr_thread 913
> > [   88.694335] omap_i2c omap_i2c.1: omap_i2c_isr_thread 1038
> > [   88.700347] omap_i2c omap_i2c.1: omap_i2c_isr 885
> > [   88.705291] omap_i2c omap_i2c.1: omap_i2c_isr 891: mask 601f stat 0104
> > [   88.712097] omap_i2c omap_i2c.1: omap_i2c_isr 894
> > [   88.717010] omap_i2c omap_i2c.1: omap_i2c_isr 899
> > [   88.721923] try_to_wake_up 1411
> > [   88.725189] ===> irq_wake_thread 139: IRQ 72 wake_up_process 0
> > [   88.731292] [sched_delayed] sched: RT throttling activated
> > [   88.737091] omap_i2c omap_i2c.1: omap_i2c_isr_thread 913
> > [   88.742706] omap_i2c omap_i2c.1: omap_i2c_isr_thread 1038
> 
> this is the last time our omap_i2c_isr_thread() runs. Note that the
> thread was already running when wake_up_process() was called.
> 
> > [   88.749206] omap_i2c omap_i2c.1: omap_i2c_xfer 655
> > [   88.754302] omap_i2c omap_i2c.1: omap_i2c_xfer 659
> > [   88.759368] omap_i2c omap_i2c.1: omap_i2c_xfer 663
> > [   88.764373] omap_i2c omap_i2c.1: omap_i2c_xfer 668
> > [   88.769531] omap_i2c omap_i2c.1: omap_i2c_xfer 626
> > [   88.774597] omap_i2c omap_i2c.1: omap_i2c_xfer 632
> > [   88.779602] omap_i2c omap_i2c.1: omap_i2c_xfer 648
> > [   88.784667] omap_i2c omap_i2c.1: addr: 0x004b, len: 1, flags: 0x0, stop: 0
> > [   88.791900] omap_i2c omap_i2c.1: omap_i2c_xfer_msg 537
> > [   88.797271] omap_i2c omap_i2c.1: omap_i2c_isr 885
> > [   88.802185] omap_i2c omap_i2c.1: omap_i2c_isr 891: mask 601f stat 1510
> > [   88.809020] omap_i2c omap_i2c.1: omap_i2c_isr 894
> > [   88.813934] omap_i2c omap_i2c.1: omap_i2c_isr 899
> > [   88.818847] ===> irq_wake_thread 139: IRQ 72 wake_up_process 1
> 
> notice here that our omap_i2c_isr_thread() never runs. I'm still
> debugging, trying to pin point what the real issue is, but it's
> definitely not the fact that we have a threaded ISR, since it runs at
> least once.
> 
> > [   90.610107] try_to_wake_up 1411
> > [   93.821044] try_to_wake_up 1411
> > [   93.824768] omap_i2c omap_i2c.1: controller timed out
> > [   93.830169] [<c001c118>] (unwind_backtrace+0x0/0xf0) from [<c040c738>] (omap_i2c_xfer_msg+0x314/0x360)
> > [   93.839935] [<c040c738>] (omap_i2c_xfer_msg+0x314/0x360) from [<c040d26c>] (omap_i2c_xfer+0xac/0x220)
> > [   93.849639] [<c040d26c>] (omap_i2c_xfer+0xac/0x220) from [<c040884c>] (__i2c_transfer+0x40/0x80)
> > [   93.858886] [<c040884c>] (__i2c_transfer+0x40/0x80) from [<c0409da8>] (i2c_transfer+0x1f8/0x26c)
> > [   93.868103] [<c0409da8>] (i2c_transfer+0x1f8/0x26c) from [<c035dab8>] (twl_i2c_read+0xc4/0x15c)
> > [   93.877288] [<c035dab8>] (twl_i2c_read+0xc4/0x15c) from [<c03189f4>] (twl4030ldo_get_voltage+0x28/0x60)
> > [   93.887145] [<c03189f4>] (twl4030ldo_get_voltage+0x28/0x60) from [<c03120b0>] (_regulator_get_voltage+0x68/0x84)
> > [   93.897827] [<c03120b0>] (_regulator_get_voltage+0x68/0x84) from [<c03125a0>] (regulator_get_voltage+0x20/0x38)
> > [   93.908447] [<c03125a0>] (regulator_get_voltage+0x20/0x38) from [<c0411bcc>] (mmc_regulator_set_ocr+0x40/0x12c)
> > [   93.919036] [<c0411bcc>] (mmc_regulator_set_ocr+0x40/0x12c) from [<c0426418>] (omap_hsmmc_set_power+0xe4/0x11c)
> > [   93.929626] [<c0426418>] (omap_hsmmc_set_power+0xe4/0x11c) from [<c042582c>] (omap_hsmmc_set_ios+0x140/0x150)
> > [   93.940032] [<c042582c>] (omap_hsmmc_set_ios+0x140/0x150) from [<c04135c4>] (mmc_power_up+0x80/0xc4)
> > [   93.949615] [<c04135c4>] (mmc_power_up+0x80/0xc4) from [<c04136d8>] (mmc_resume_host+0xd0/0x150)
> > [   93.958862] [<c04136d8>] (mmc_resume_host+0xd0/0x150) from [<c0426b5c>] (omap_hsmmc_resume+0x7c/0xc8)
> > [   93.968536] [<c0426b5c>] (omap_hsmmc_resume+0x7c/0xc8) from [<c0347a78>] (platform_pm_resume+0x2c/0x50)
> > [   93.978424] [<c0347a78>] (platform_pm_resume+0x2c/0x50) from [<c034bca4>] (dpm_run_callback.isra.4+0x2c/0x64)
> > [   93.988830] [<c034bca4>] (dpm_run_callback.isra.4+0x2c/0x64) from [<c034ca48>] (device_resume+0xdc/0x18c)
> > [   93.998870] [<c034ca48>] (device_resume+0xdc/0x18c) from [<c034ce8c>] (dpm_resume+0xfc/0x21c)
> > [   94.007812] [<c034ce8c>] (dpm_resume+0xfc/0x21c) from [<c034d094>] (dpm_resume_end+0xc/0x18)
> > [   94.016723] [<c034d094>] (dpm_resume_end+0xc/0x18) from [<c0087b14>] (suspend_devices_and_enter+0xe8/0x1b0)
> > [   94.026947] [<c0087b14>] (suspend_devices_and_enter+0xe8/0x1b0) from [<c0087c78>] (enter_state+0x9c/0xdc)
> > [   94.036987] [<c0087c78>] (enter_state+0x9c/0xdc) from [<c0087ccc>] (pm_suspend+0x14/0x70)
> > [   94.045593] [<c0087ccc>] (pm_suspend+0x14/0x70) from [<c0086d34>] (state_store+0x30/0x3c)
> > [   94.054199] [<c0086d34>] (state_store+0x30/0x3c) from [<c02d39b8>] (kobj_attr_store+0x14/0x20)
> > [   94.063262] [<c02d39b8>] (kobj_attr_store+0x14/0x20) from [<c017bcd0>] (sysfs_write_file+0x80/0xb4)
> > [   94.072784] [<c017bcd0>] (sysfs_write_file+0x80/0xb4) from [<c01174c4>] (vfs_write+0xa8/0x138)
> > [   94.081817] [<c01174c4>] (vfs_write+0xa8/0x138) from [<c0117730>] (sys_write+0x40/0x68)
> > [   94.090240] [<c0117730>] (sys_write+0x40/0x68) from [<c0013f40>] (ret_fast_syscall+0x0/0x3c)
> > [   94.099334] omap_i2c omap_i2c.1: omap_i2c_xfer 655
> > [   94.104431] omap_i2c omap_i2c.1: omap_i2c_xfer 659
> > [   94.109466] omap_i2c omap_i2c.1: omap_i2c_xfer 663
> > [   94.114532] omap_i2c omap_i2c.1: omap_i2c_xfer 668
> > [   94.119567] twl: i2c_read failed to transfer all messages
> > [   94.125244] omap_hsmmc omap_hsmmc.0: could not set regulator OCR (-110)
> > [   94.286773] mmc0: error -110 during resume (card was removed?)
> 
> -- 
> balbi
Kevin Hilman Oct. 16, 2012, 9:39 p.m. UTC | #6
+ peterz, tglx

Felipe Balbi <balbi@ti.com> writes:

[...]

> The problem I see is that even though we properly return IRQ_WAKE_THREAD
> and wake_up_process() manages to wakeup the IRQ thread (it returns 1),
> the thread is never scheduled. To make things even worse, ouw irq thread
> runs once, but doesn't run on a consecutive call. Here's some (rather
> nasty) debug prints showing the problem:

[...]

>> [   88.721923] try_to_wake_up 1411
>> [   88.725189] ===> irq_wake_thread 139: IRQ 72 wake_up_process 0
>> [   88.731292] [sched_delayed] sched: RT throttling activated

This throttling message is the key one.

With RT throttling activated, the IRQ thread will not be run (it
eventually will be allowed much later on, but by then, the I2C xfers
have timed out.)

As a quick hack, the throttling can be disabled by seeting the
sched_rt_runtime to RUNTIME_INF:

        # sysctl -w kernel.sched_rt_runtime_us=-1

and a quick test shows that things go back to working as expected.  But
we still need to figure out why the throttling is hapenning...

So I started digging into why the RT runtime was so high, and noticed
that time spent in suspend was being counted as RT runtime!

So spending time in suspend anywhere near sched_rt_runtime (0.95s) will
cause the RT throttling to always be triggered, and thus prevent IRQ
threads from running in the resume path.  Ouch.

I think I'm already in over my head in the RT runtime stuff, but
counting the time spent in suspend as RT runtime smells like a bug to
me. no?

Peter? Thomas?

Kevin
Felipe Balbi Oct. 17, 2012, 2 p.m. UTC | #7
Hi,

On Tue, Oct 16, 2012 at 02:39:50PM -0700, Kevin Hilman wrote:
> + peterz, tglx
> 
> Felipe Balbi <balbi@ti.com> writes:
> 
> [...]
> 
> > The problem I see is that even though we properly return IRQ_WAKE_THREAD
> > and wake_up_process() manages to wakeup the IRQ thread (it returns 1),
> > the thread is never scheduled. To make things even worse, ouw irq thread
> > runs once, but doesn't run on a consecutive call. Here's some (rather
> > nasty) debug prints showing the problem:
> 
> [...]
> 
> >> [   88.721923] try_to_wake_up 1411
> >> [   88.725189] ===> irq_wake_thread 139: IRQ 72 wake_up_process 0
> >> [   88.731292] [sched_delayed] sched: RT throttling activated
> 
> This throttling message is the key one.
> 
> With RT throttling activated, the IRQ thread will not be run (it
> eventually will be allowed much later on, but by then, the I2C xfers
> have timed out.)
> 
> As a quick hack, the throttling can be disabled by seeting the
> sched_rt_runtime to RUNTIME_INF:
> 
>         # sysctl -w kernel.sched_rt_runtime_us=-1
> 
> and a quick test shows that things go back to working as expected.  But
> we still need to figure out why the throttling is hapenning...
> 
> So I started digging into why the RT runtime was so high, and noticed
> that time spent in suspend was being counted as RT runtime!
> 
> So spending time in suspend anywhere near sched_rt_runtime (0.95s) will
> cause the RT throttling to always be triggered, and thus prevent IRQ
> threads from running in the resume path.  Ouch.
> 
> I think I'm already in over my head in the RT runtime stuff, but
> counting the time spent in suspend as RT runtime smells like a bug to
> me. no?
> 
> Peter? Thomas?

it looks like removing console output completely (echo 0 >
/proc/sysrq-trigger) I don't see the issue anymore. Let me just run for
a few more iterations to make sure what I'm saying is correct.
Felipe Balbi Oct. 17, 2012, 2:35 p.m. UTC | #8
Hi,

On Wed, Oct 17, 2012 at 05:00:02PM +0300, Felipe Balbi wrote:
> Hi,
> 
> On Tue, Oct 16, 2012 at 02:39:50PM -0700, Kevin Hilman wrote:
> > + peterz, tglx
> > 
> > Felipe Balbi <balbi@ti.com> writes:
> > 
> > [...]
> > 
> > > The problem I see is that even though we properly return IRQ_WAKE_THREAD
> > > and wake_up_process() manages to wakeup the IRQ thread (it returns 1),
> > > the thread is never scheduled. To make things even worse, ouw irq thread
> > > runs once, but doesn't run on a consecutive call. Here's some (rather
> > > nasty) debug prints showing the problem:
> > 
> > [...]
> > 
> > >> [   88.721923] try_to_wake_up 1411
> > >> [   88.725189] ===> irq_wake_thread 139: IRQ 72 wake_up_process 0
> > >> [   88.731292] [sched_delayed] sched: RT throttling activated
> > 
> > This throttling message is the key one.
> > 
> > With RT throttling activated, the IRQ thread will not be run (it
> > eventually will be allowed much later on, but by then, the I2C xfers
> > have timed out.)
> > 
> > As a quick hack, the throttling can be disabled by seeting the
> > sched_rt_runtime to RUNTIME_INF:
> > 
> >         # sysctl -w kernel.sched_rt_runtime_us=-1
> > 
> > and a quick test shows that things go back to working as expected.  But
> > we still need to figure out why the throttling is hapenning...
> > 
> > So I started digging into why the RT runtime was so high, and noticed
> > that time spent in suspend was being counted as RT runtime!
> > 
> > So spending time in suspend anywhere near sched_rt_runtime (0.95s) will
> > cause the RT throttling to always be triggered, and thus prevent IRQ
> > threads from running in the resume path.  Ouch.
> > 
> > I think I'm already in over my head in the RT runtime stuff, but
> > counting the time spent in suspend as RT runtime smells like a bug to
> > me. no?
> > 
> > Peter? Thomas?
> 
> it looks like removing console output completely (echo 0 >
> /proc/sysrq-trigger) I don't see the issue anymore. Let me just run for
> a few more iterations to make sure what I'm saying is correct.

Yeah, really looks like removing console output makes the problem go
away. Ran a few iterations and it always worked fine. Full logs attached

BTW, In the meantime I think I might have found some problems with
omap_device's PM implementation. I'll test the patchset a little longer
and send an RFC.
diff mbox

Patch

diff --git a/drivers/i2c/busses/i2c-omap.c b/drivers/i2c/busses/i2c-omap.c
index db31eae..e001c2a 100644
--- a/drivers/i2c/busses/i2c-omap.c
+++ b/drivers/i2c/busses/i2c-omap.c
@@ -180,7 +180,6 @@  enum {
 #define I2C_OMAP_ERRATA_I462		(1 << 1)
 
 struct omap_i2c_dev {
-	spinlock_t		lock;		/* IRQ synchronization */
 	struct device		*dev;
 	void __iomem		*base;		/* virtual */
 	int			irq;
@@ -865,35 +864,13 @@  static int omap_i2c_transmit_data(struct omap_i2c_dev *dev, u8 num_bytes,
 }
 
 static irqreturn_t
-omap_i2c_isr(int irq, void *dev_id)
+omap_i2c_isr(int this_irq, void *dev_id)
 {
 	struct omap_i2c_dev *dev = dev_id;
-	irqreturn_t ret = IRQ_HANDLED;
-	u16 mask;
-	u16 stat;
-
-	spin_lock(&dev->lock);
-	mask = omap_i2c_read_reg(dev, OMAP_I2C_IE_REG);
-	stat = omap_i2c_read_reg(dev, OMAP_I2C_STAT_REG);
-
-	if (stat & mask)
-		ret = IRQ_WAKE_THREAD;
-
-	spin_unlock(&dev->lock);
-
-	return ret;
-}
-
-static irqreturn_t
-omap_i2c_isr_thread(int this_irq, void *dev_id)
-{
-	struct omap_i2c_dev *dev = dev_id;
-	unsigned long flags;
 	u16 bits;
 	u16 stat;
 	int err = 0, count = 0;
 
-	spin_lock_irqsave(&dev->lock, flags);
 	do {
 		bits = omap_i2c_read_reg(dev, OMAP_I2C_IE_REG);
 		stat = omap_i2c_read_reg(dev, OMAP_I2C_STAT_REG);
@@ -907,7 +884,7 @@  omap_i2c_isr_thread(int this_irq, void *dev_id)
 
 		if (!stat) {
 			/* my work here is done */
-			goto out;
+			return IRQ_HANDLED;
 		}
 
 		dev_dbg(dev->dev, "IRQ (ISR = 0x%04x)\n", stat);
@@ -1016,8 +993,6 @@  omap_i2c_isr_thread(int this_irq, void *dev_id)
 	omap_i2c_complete_cmd(dev, err);
 
 out:
-	spin_unlock_irqrestore(&dev->lock, flags);
-
 	return IRQ_HANDLED;
 }
 
@@ -1062,6 +1037,7 @@  omap_i2c_probe(struct platform_device *pdev)
 		pdev->dev.platform_data;
 	struct device_node	*node = pdev->dev.of_node;
 	const struct of_device_id *match;
+	irq_handler_t isr;
 	int irq;
 	int r;
 
@@ -1110,8 +1086,6 @@  omap_i2c_probe(struct platform_device *pdev)
 	dev->dev = &pdev->dev;
 	dev->irq = irq;
 
-	spin_lock_init(&dev->lock);
-
 	platform_set_drvdata(pdev, dev);
 	init_completion(&dev->cmd_complete);
 
@@ -1166,14 +1140,10 @@  omap_i2c_probe(struct platform_device *pdev)
 	/* reset ASAP, clearing any IRQs */
 	omap_i2c_init(dev);
 
-	if (dev->rev < OMAP_I2C_OMAP1_REV_2)
-		r = devm_request_irq(&pdev->dev, dev->irq, omap_i2c_omap1_isr,
-				IRQF_NO_SUSPEND, pdev->name, dev);
-	else
-		r = devm_request_threaded_irq(&pdev->dev, dev->irq,
-				omap_i2c_isr, omap_i2c_isr_thread,
-				IRQF_NO_SUSPEND | IRQF_ONESHOT,
-				pdev->name, dev);
+	isr = (dev->rev < OMAP_I2C_OMAP1_REV_2) ? omap_i2c_omap1_isr :
+								   omap_i2c_isr;
+	r = devm_request_irq(&pdev->dev, dev->irq, isr, IRQF_NO_SUSPEND,
+			     pdev->name, dev);
 
 	if (r) {
 		dev_err(dev->dev, "failure requesting irq %i\n", dev->irq);