debug needed: twl4030 RTC wakeups: repeated attempts fail on Beagle

debug needed: twl4030 RTC wakeups: repeated attempts fail on Beagle

[Kevin Hilman]

Hello,

In doing some automated testing of suspend/resume I noticed that
repeated attempts to suspend and resume via RTC wakeup fail on
3530/Beagle and 3730/Beagle-xM, but work fine on 3430/n900, 3530/Overo,
3730/OveroSTORM and 4430/Panda.

When RTC wakeup fails, a UART wakeup will work, and in the logs, you'll
see this:

[  316.036132] twl: i2c_read failed to transfer all messages
[  316.036163] twl4030: I2C error -13 reading PIH ISR

My guess about what might be happening is that very late in the suspend
process (during the noirq hooks), a PMIC interrupt fires, but by this
time the I2C driver is runtime suspended (and clock gated.)  Since
runtime PM is disabled at this point, I2C reads fail, so the twl4030 IRQ
driver cannot talk over I2C to the PMIC to determine the interrupt
source.

The real mystery is why this happens on Beagle and Beagle-xM, but none
of the other OMAP3 boards (at least the ones I have.)

Reproducing is easy.  Simply run rtcwake in a loop:

  # while true; do rtcwake -m mem -s 1; done

In my tests, this happens using omap2plus_defconfig (+ initramfs) on
v3.6-rc1, v3.5, v3.4, v3.3 but seems to work fine on v3.2.

I'm going on vacation for a few weeks, so any help debugging this would
be greatly appreciated. 

Thanks,

Kevin

Re: debug needed: twl4030 RTC wakeups: repeated attempts fail on Beagle

[NeilBrown]

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

On Fri, 10 Aug 2012 11:49:27 -0700 Kevin Hilman <khilman@ti.com> wrote:

> Hello,
> 
> In doing some automated testing of suspend/resume I noticed that
> repeated attempts to suspend and resume via RTC wakeup fail on
> 3530/Beagle and 3730/Beagle-xM, but work fine on 3430/n900, 3530/Overo,
> 3730/OveroSTORM and 4430/Panda.
> 
> When RTC wakeup fails, a UART wakeup will work, and in the logs, you'll
> see this:
> 
> [  316.036132] twl: i2c_read failed to transfer all messages
> [  316.036163] twl4030: I2C error -13 reading PIH ISR
> 
> My guess about what might be happening is that very late in the suspend
> process (during the noirq hooks), a PMIC interrupt fires, but by this
> time the I2C driver is runtime suspended (and clock gated.)  Since
> runtime PM is disabled at this point, I2C reads fail, so the twl4030 IRQ
> driver cannot talk over I2C to the PMIC to determine the interrupt
> source.

This area seems to be rife with opportunity for bugs.  I wrote about some of
it here:  https://lwn.net/Articles/482345/

I don't know that I saw quite what you are seeing though.

If a PMIC interrupt fires during the noirq phase, the interrupt handler
shouldn't be run (it isn't marked NOSUSPEND).  However there is probably room
for a race between the 'suspend' phase and the 'noirq' phase.

When the suspend processing handles the I2C device, the last thing that
__device_suspend does is

		__pm_runtime_disable(dev, false);

which will freeze the current runtime_pm state of the I2C device.  If it is
off, it stays off.  If on, it stays on.

As the noirq phase hasn't been entered yet an interrupt from the PMIC could
still be handled.  If it is, you get exactly the error you see.

I'm not convinced that the __pm_runtime_disable call is correct.  It think we
need to stop async runtime_suspends, but we don't need to stop sync
runtime_resumes. So just a pm_runtime_get should be enough.  But there  is
possibly an important point I am missing.

However if my analysis is correct, then this can be 'fixed' by changing the
omap i2c suspend routine to do a pm_runtime_get, and the resume routine to do
a pm_runtime_put.  The I2C will still be put to sleep during suspend by the
noirq suspend handler, but we will be sure of it being awake during the
crucial suspend and resume transition.
See also https://lwn.net/Articles/505683/.  Particularly (towards the end)

    If the device might be needed to power down other devices, such as an I2C
    controller that might be needed to tell some regulator to turn off, then the
    device should be activated for runtime PM purposes so that it will still be
    active when runtime PM is disabled. 

(Rafael reviewed this article so it shouldn't be very far from the mark).


> 
> The real mystery is why this happens on Beagle and Beagle-xM, but none
> of the other OMAP3 boards (at least the ones I have.)

Maybe didn't components of the PMIC are active and have the potential to
generate an interrupt at an awkward time.  USB and battery chargers seem good
at that.

Or maybe due to the particular components active and the particular timing,
the pm_runtime_disable ends up freezing the runtime_pm state in 'on' rather
than 'off'.

> 
> Reproducing is easy.  Simply run rtcwake in a loop:
> 
>   # while true; do rtcwake -m mem -s 1; done
> 
> In my tests, this happens using omap2plus_defconfig (+ initramfs) on
> v3.6-rc1, v3.5, v3.4, v3.3 but seems to work fine on v3.2.
> 
> I'm going on vacation for a few weeks, so any help debugging this would
> be greatly appreciated. 

Enjoy your vacation!   I don't suppose it ends up in San Diego in late August
for one of the multitude of conferences there?

NeilBrown



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

Re: debug needed: twl4030 RTC wakeups: repeated attempts fail on Beagle

[Kevin Hilman]

NeilBrown <neilb@suse.de> writes:

> On Fri, 10 Aug 2012 11:49:27 -0700 Kevin Hilman <khilman@ti.com> wrote:
>
>> Hello,
>> 
>> In doing some automated testing of suspend/resume I noticed that
>> repeated attempts to suspend and resume via RTC wakeup fail on
>> 3530/Beagle and 3730/Beagle-xM, but work fine on 3430/n900, 3530/Overo,
>> 3730/OveroSTORM and 4430/Panda.
>> 
>> When RTC wakeup fails, a UART wakeup will work, and in the logs, you'll
>> see this:
>> 
>> [  316.036132] twl: i2c_read failed to transfer all messages
>> [  316.036163] twl4030: I2C error -13 reading PIH ISR
>> 
>> My guess about what might be happening is that very late in the suspend
>> process (during the noirq hooks), a PMIC interrupt fires, but by this
>> time the I2C driver is runtime suspended (and clock gated.)  Since
>> runtime PM is disabled at this point, I2C reads fail, so the twl4030 IRQ
>> driver cannot talk over I2C to the PMIC to determine the interrupt
>> source.
>
> This area seems to be rife with opportunity for bugs.  I wrote about some of
> it here:  https://lwn.net/Articles/482345/

Yeah, that was a great article.

> I don't know that I saw quite what you are seeing though.
>
> If a PMIC interrupt fires during the noirq phase, the interrupt handler
> shouldn't be run (it isn't marked NOSUSPEND).  However there is probably room
> for a race between the 'suspend' phase and the 'noirq' phase.
>
> When the suspend processing handles the I2C device, the last thing that
> __device_suspend does is
>
> 		__pm_runtime_disable(dev, false);
>
> which will freeze the current runtime_pm state of the I2C device.  If it is
> off, it stays off.  If on, it stays on.

Correct.

> As the noirq phase hasn't been entered yet an interrupt from the PMIC could
> still be handled.  If it is, you get exactly the error you see.

Right, this is what I suspect is happening.  I just haven't had the time
to confirm and/or fix.

> I'm not convinced that the __pm_runtime_disable call is correct.  It think we
> need to stop async runtime_suspends, but we don't need to stop sync
> runtime_resumes. So just a pm_runtime_get should be enough.  But there  is
> possibly an important point I am missing.

Yes, I went back and forth with Rafael on the interactions between
system PM and runtime PM and he pursuaded me that there were a handful
of reasons that system PM needed to block runtime PM transitions.  I
don't recall what they are at the moment (my brain is already being
pre-flushed in preparation for some time off.)

> However if my analysis is correct, then this can be 'fixed' by changing the
> omap i2c suspend routine to do a pm_runtime_get, and the resume routine to do
> a pm_runtime_put.  The I2C will still be put to sleep during suspend by the
> noirq suspend handler, but we will be sure of it being awake during the
> crucial suspend and resume transition.

Hmm, that's a good idea.  Hopefully someone can give it a try before I
get back from vacation. :)

Thanks for the suggestion.

> See also https://lwn.net/Articles/505683/.  Particularly (towards the end)
>
>     If the device might be needed to power down other devices, such as an I2C
>     controller that might be needed to tell some regulator to turn off, then the
>     device should be activated for runtime PM purposes so that it will still be
>     active when runtime PM is disabled. 
>
> (Rafael reviewed this article so it shouldn't be very far from the mark).
>
>
>> 
>> The real mystery is why this happens on Beagle and Beagle-xM, but none
>> of the other OMAP3 boards (at least the ones I have.)
>
> Maybe didn't components of the PMIC are active and have the potential to
> generate an interrupt at an awkward time.  USB and battery chargers seem good
> at that.
>
> Or maybe due to the particular components active and the particular timing,
> the pm_runtime_disable ends up freezing the runtime_pm state in 'on' rather
> than 'off'.
>
>> 
>> Reproducing is easy.  Simply run rtcwake in a loop:
>> 
>>   # while true; do rtcwake -m mem -s 1; done
>> 
>> In my tests, this happens using omap2plus_defconfig (+ initramfs) on
>> v3.6-rc1, v3.5, v3.4, v3.3 but seems to work fine on v3.2.
>> 
>> I'm going on vacation for a few weeks, so any help debugging this would
>> be greatly appreciated. 
>
> Enjoy your vacation!   I don't suppose it ends up in San Diego in late August
> for one of the multitude of conferences there?

No, I'll miss the summer conferences this year, this vacation will be
unplugged.

Kevin

Re: debug needed: twl4030 RTC wakeups: repeated attempts fail on Beagle

[Datta, Shubhrajyoti]

On Sat, Aug 11, 2012 at 12:19 AM, Kevin Hilman <khilman@ti.com> wrote:
> Hello,
>
> In doing some automated testing of suspend/resume I noticed that
> repeated attempts to suspend and resume via RTC wakeup fail on
> 3530/Beagle and 3730/Beagle-xM, but work fine on 3430/n900, 3530/Overo,
> 3730/OveroSTORM and 4430/Panda.
>
> When RTC wakeup fails, a UART wakeup will work, and in the logs, you'll
> see this:
>
> [  316.036132] twl: i2c_read failed to transfer all messages
> [  316.036163] twl4030: I2C error -13 reading PIH ISR

The  error value is is propagated from the i2c get_sync failure.

>
> My guess about what might be happening is that very late in the suspend
> process (during the noirq hooks), a PMIC interrupt fires, but by this
> time the I2C driver is runtime suspended (and clock gated.)  Since
> runtime PM is disabled at this point, I2C reads fail, so the twl4030 IRQ
> driver cannot talk over I2C to the PMIC to determine the interrupt
> source.

Agreed.

>
> The real mystery is why this happens on Beagle and Beagle-xM, but none
> of the other OMAP3 boards (at least the ones I have.)

Looks like some  race/ timing issue.
However I am not sure what is a good way to synchronise the i2c
requests from a client from an isr and
the device disable / runtime resumed.

However on merging the clean up series

http://www.mail-archive.com/linux-omap@vger.kernel.org/msg73870.html

Didn't see the above mentioned issue.

but there were some error's like timeout.

This may be because the controller was not fully enabled.

SYSC in case of I2C not only reflects the reset status from sysc
reset( register is reset)
but also controller enable ( controller reset ).

On checking the reset after controller didnt see the time out issue.

patch below.



diff --git a/drivers/i2c/busses/i2c-omap.c b/drivers/i2c/busses/i2c-omap.c
index 9aefd36..b35afa4 100644
--- a/drivers/i2c/busses/i2c-omap.c
+++ b/drivers/i2c/busses/i2c-omap.c
@@ -1254,6 +1254,7 @@ static int omap_i2c_runtime_resume(struct device *dev)
 {
 	struct platform_device *pdev = to_platform_device(dev);
 	struct omap_i2c_dev *_dev = platform_get_drvdata(pdev);
+	unsigned long timeout = 10000;

 	if (_dev->flags & OMAP_I2C_FLAG_RESET_REGS_POSTIDLE) {
 		omap_i2c_write_reg(_dev, OMAP_I2C_CON_REG, 0);
@@ -1266,6 +1267,15 @@ static int omap_i2c_runtime_resume(struct device *dev)
 		omap_i2c_write_reg(_dev, OMAP_I2C_CON_REG, OMAP_I2C_CON_EN);
 	}

+	while (!(omap_i2c_read_reg(_dev, OMAP_I2C_SYSS_REG) &
+			SYSS_RESETDONE_MASK)) {
+		if (time_after(jiffies, timeout)) {
+			dev_warn(dev, "timeout waiting for controller reset\n");
+				return -ETIMEDOUT;
+		}
+		msleep(1);
+	}
+
 	/*
 	 * Don't write to this register if the IE state is 0 as it can
 	 * cause deadlock.

>
> Reproducing is easy.  Simply run rtcwake in a loop:
>
>   # while true; do rtcwake -m mem -s 1; done
>
> In my tests, this happens using omap2plus_defconfig (+ initramfs) on
> v3.6-rc1, v3.5, v3.4, v3.3 but seems to work fine on v3.2.
>
> I'm going on vacation for a few weeks, so any help debugging this would
> be greatly appreciated.
>
> Thanks,
>
> Kevin
> --
> To unsubscribe from this list: send the line "unsubscribe linux-omap" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: debug needed: twl4030 RTC wakeups: repeated attempts fail on Beagle

[Felipe Balbi]

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

Hi,

On Wed, Aug 22, 2012 at 08:36:31PM +0530, Datta, Shubhrajyoti wrote:
> > The real mystery is why this happens on Beagle and Beagle-xM, but none
> > of the other OMAP3 boards (at least the ones I have.)
> 
> Looks like some  race/ timing issue.
> However I am not sure what is a good way to synchronise the i2c
> requests from a client from an isr and
> the device disable / runtime resumed.
> 
> However on merging the clean up series
> 
> http://www.mail-archive.com/linux-omap@vger.kernel.org/msg73870.html
> 
> Didn't see the above mentioned issue.
> 
> but there were some error's like timeout.
> 
> This may be because the controller was not fully enabled.
> 
> SYSC in case of I2C not only reflects the reset status from sysc
> reset( register is reset)
> but also controller enable ( controller reset ).
> 
> On checking the reset after controller didnt see the time out issue.
> 
> patch below.
> 
> 
> 
> diff --git a/drivers/i2c/busses/i2c-omap.c b/drivers/i2c/busses/i2c-omap.c
> index 9aefd36..b35afa4 100644
> --- a/drivers/i2c/busses/i2c-omap.c
> +++ b/drivers/i2c/busses/i2c-omap.c
> @@ -1254,6 +1254,7 @@ static int omap_i2c_runtime_resume(struct device *dev)
>  {
>  	struct platform_device *pdev = to_platform_device(dev);
>  	struct omap_i2c_dev *_dev = platform_get_drvdata(pdev);
> +	unsigned long timeout = 10000;
> 
>  	if (_dev->flags & OMAP_I2C_FLAG_RESET_REGS_POSTIDLE) {
>  		omap_i2c_write_reg(_dev, OMAP_I2C_CON_REG, 0);
> @@ -1266,6 +1267,15 @@ static int omap_i2c_runtime_resume(struct device *dev)
>  		omap_i2c_write_reg(_dev, OMAP_I2C_CON_REG, OMAP_I2C_CON_EN);
>  	}
> 
> +	while (!(omap_i2c_read_reg(_dev, OMAP_I2C_SYSS_REG) &
> +			SYSS_RESETDONE_MASK)) {
> +		if (time_after(jiffies, timeout)) {
> +			dev_warn(dev, "timeout waiting for controller reset\n");
> +				return -ETIMEDOUT;
> +		}
> +		msleep(1);
> +	}
> +
>  	/*
>  	 * Don't write to this register if the IE state is 0 as it can
>  	 * cause deadlock.

That's weird. i2c has SYSS_HAS_RESET_STATUS set, so hwmod framework
should be checking that for us. And, in fact, SYSS_HAS_RESET_STATUS is
set on all *data.c files.

When you wrote that patch, did you check that reset hasn't completed
yet ? I mean, was reset still asserted at that time ? If instead of your
patch, you just wait longer for reset to complete, will it work ?

diff --git a/arch/arm/mach-omap2/omap_hwmod.c b/arch/arm/mach-omap2/omap_hwmod.c
index 6ca8e51..7a39c72 100644
--- a/arch/arm/mach-omap2/omap_hwmod.c
+++ b/arch/arm/mach-omap2/omap_hwmod.c
@@ -156,7 +156,7 @@
 #include "pm.h"
 
 /* Maximum microseconds to wait for OMAP module to softreset */
-#define MAX_MODULE_SOFTRESET_WAIT	10000
+#define MAX_MODULE_SOFTRESET_WAIT	50000
 
 /* Name of the OMAP hwmod for the MPU */
 #define MPU_INITIATOR_NAME		"mpu"


If it does, then reset takes longer to complete on those particular
boards and it would be nice to know why, but one step at a time :-)

-- 
balbi

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 836 bytes --]

Re: debug needed: twl4030 RTC wakeups: repeated attempts fail on Beagle

[Shubhrajyoti]

On Thursday 23 August 2012 12:12 AM, Felipe Balbi wrote:
>> >  	if (_dev->flags & OMAP_I2C_FLAG_RESET_REGS_POSTIDLE) {
>> >  		omap_i2c_write_reg(_dev, OMAP_I2C_CON_REG, 0);
>> > @@ -1266,6 +1267,15 @@ static int omap_i2c_runtime_resume(struct device *dev)
>> >  		omap_i2c_write_reg(_dev, OMAP_I2C_CON_REG, OMAP_I2C_CON_EN);
>> >  	}
>> > 
>> > +	while (!(omap_i2c_read_reg(_dev, OMAP_I2C_SYSS_REG) &
>> > +			SYSS_RESETDONE_MASK)) {
>> > +		if (time_after(jiffies, timeout)) {
>> > +			dev_warn(dev, "timeout waiting for controller reset\n");
>> > +				return -ETIMEDOUT;
>> > +		}
>> > +		msleep(1);
>> > +	}
>> > +
>> >  	/*
>> >  	 * Don't write to this register if the IE state is 0 as it can
>> >  	 * cause deadlock.
> That's weird. i2c has SYSS_HAS_RESET_STATUS set, so hwmod framework
> should be checking that for us. And, in fact, SYSS_HAS_RESET_STATUS is
> set on all *data.c files.
Felipe just like writing to sysc reset.

writing

omap_i2c_write_reg(_dev, OMAP_I2C_CON_REG, 0);

[...]

omap_i2c_write_reg(_dev, OMAP_I2C_CON_REG, OMAP_I2C_CON_EN);

is also a reset() and the hwmod is not aware of that.

1.Hardware reset: A system bus reset (PIRSTNA = 0).
 A device reset causes the system bus reset.

2. Software reset: A software reset by setting the
	SRST bit in the I2C_SYSC register. This bit has exactly the same
	action on the module logic as the system bus reset. 

3.  Partial reset or controller reset. The I2C_EN bit in the I2C_CON
	register can also reset a part of the I^2 C module. When
	the system bus reset is removed (PIRSTNA  = 1), I2C_EN = 0 keeps the
	functional part of I^2 C module in reset state and all
	configuration registers can be accessed.


Since the case 3 is true in my case I am checking and hwmod is not aware
of this.

This read-only bit indicates the state of the reset in case of hardware
reset, global software reset (I2C_SYSC.SRST) or partial software reset
(I2C_CON.I2C_EN).

I am checking for case 3.


>
> When you wrote that patch, did you check that reset hasn't completed
> yet ? I mean, was reset still asserted at that time ? If instead of your
> patch, you just wait longer for reset to complete, will it work ?
>
> diff --git a/arch/arm/mach-omap2/omap_hwmod.c b/arch/arm/mach-omap2/omap_hwmod.c
> index 6ca8e51..7a39c72 100644
> --- a/arch/arm/mach-omap2/omap_hwmod.c
> +++ b/arch/arm/mach-omap2/omap_hwmod.c
> @@ -156,7 +156,7 @@
>  #include "pm.h"
>  
>  /* Maximum microseconds to wait for OMAP module to softreset */
> -#define MAX_MODULE_SOFTRESET_WAIT	10000
> +#define MAX_MODULE_SOFTRESET_WAIT	50000
>  
>  /* Name of the OMAP hwmod for the MPU */
>  #define MPU_INITIATOR_NAME		"mpu"
>
>
> If it does, then reset takes longer to complete on those particular
> boards and it would be nice to know why, but one step at a time :-)
>
> -- balbi

Re: debug needed: twl4030 RTC wakeups: repeated attempts fail on Beagle

[Felipe Balbi]

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

On Thu, Aug 23, 2012 at 04:51:41PM +0530, Shubhrajyoti wrote:
> On Thursday 23 August 2012 12:12 AM, Felipe Balbi wrote:
> >> >  	if (_dev->flags & OMAP_I2C_FLAG_RESET_REGS_POSTIDLE) {
> >> >  		omap_i2c_write_reg(_dev, OMAP_I2C_CON_REG, 0);
> >> > @@ -1266,6 +1267,15 @@ static int omap_i2c_runtime_resume(struct device *dev)
> >> >  		omap_i2c_write_reg(_dev, OMAP_I2C_CON_REG, OMAP_I2C_CON_EN);
> >> >  	}
> >> > 
> >> > +	while (!(omap_i2c_read_reg(_dev, OMAP_I2C_SYSS_REG) &
> >> > +			SYSS_RESETDONE_MASK)) {
> >> > +		if (time_after(jiffies, timeout)) {
> >> > +			dev_warn(dev, "timeout waiting for controller reset\n");
> >> > +				return -ETIMEDOUT;
> >> > +		}
> >> > +		msleep(1);
> >> > +	}
> >> > +
> >> >  	/*
> >> >  	 * Don't write to this register if the IE state is 0 as it can
> >> >  	 * cause deadlock.
> > That's weird. i2c has SYSS_HAS_RESET_STATUS set, so hwmod framework
> > should be checking that for us. And, in fact, SYSS_HAS_RESET_STATUS is
> > set on all *data.c files.
> Felipe just like writing to sysc reset.
> 
> writing
> 
> omap_i2c_write_reg(_dev, OMAP_I2C_CON_REG, 0);
> 
> [...]
> 
> omap_i2c_write_reg(_dev, OMAP_I2C_CON_REG, OMAP_I2C_CON_EN);
> 
> is also a reset() and the hwmod is not aware of that.
> 
> 1.Hardware reset: A system bus reset (PIRSTNA = 0).
>  A device reset causes the system bus reset.
> 
> 2. Software reset: A software reset by setting the
> 	SRST bit in the I2C_SYSC register. This bit has exactly the same
> 	action on the module logic as the system bus reset. 
> 
> 3.  Partial reset or controller reset. The I2C_EN bit in the I2C_CON
> 	register can also reset a part of the I^2 C module. When
> 	the system bus reset is removed (PIRSTNA  = 1), I2C_EN = 0 keeps the
> 	functional part of I^2 C module in reset state and all
> 	configuration registers can be accessed.
> 
> 
> Since the case 3 is true in my case I am checking and hwmod is not aware
> of this.
> 
> This read-only bit indicates the state of the reset in case of hardware
> reset, global software reset (I2C_SYSC.SRST) or partial software reset
> (I2C_CON.I2C_EN).
> 
> I am checking for case 3.

aha, ok. Very nice finding :-) I wasn't aware of that. Maybe that's all
we need then ?? But why only on a few boards ? probably some
timing-related behavior, who knows ;-)

-- 
balbi

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 836 bytes --]