i2c-powermac fails

i2c-powermac fails

[Jean Delvare]

Hi Ben, Paul,

I had a report by Tim Shepard (Cc'd) that the therm_adt746x driver
sometimes fails to initialize on his PowerBook G4 running kernel
2.6.31. The following error message can be seen in the logs when the
failure happens:

therm_adt746x 7-002e: Thermostat failed to read config!

After enabling low-level i2c debugging, it turns out that the problem
is caused by low-level errors at the I2C bus level:

PowerMac i2c bus pmu 2 registered
PowerMac i2c bus pmu 1 registered
PowerMac i2c bus mac-io 0 registered
low_i2c:xfer() chan=0, addrdir=0x5d, mode=4, subsize=1, subaddr=0x0, 1 bytes, bus /uni-n@f8000000/i2c@f8001000/i2c-bus@0
low_i2c:kw_handle_interrupt(state_addr, isr: 6)
low_i2c:KW: NAK on address
low_i2c:xfer error -6
i2c-adapter i2c-7: I2C transfer at 0x2e failed, size 2, err -6
therm_adt746x 7-002e: Thermostat failed to read config!
PowerMac i2c bus uni-n 0 registered

So apparently the I2C controller doesn't see the ack from the ADT7467.
However the ADT7467 is a SMBus-compliant device, so it must always ack
his address.

It is worth noting that many other I2C errors happen and go unnoticed.
Below is the log of a "successful" therm_adt746x registration:

PowerMac i2c bus pmu 2 registered
PowerMac i2c bus pmu 1 registered
PowerMac i2c bus mac-io 0 registered
low_i2c:xfer() chan=0, addrdir=0x5d, mode=4, subsize=1, subaddr=0x0, 1 bytes, bus /uni-n@f8000000/i2c@f8001000/i2c-bus@0
low_i2c:kw_handle_interrupt(state_addr, isr: 2)
low_i2c:kw_handle_interrupt(state_read, isr: 5)
adt746x: ADT7467 initializing
low_i2c:xfer() chan=0, addrdir=0x5d, mode=4, subsize=1, subaddr=0x6b, 1 bytes, bus /uni-n@f8000000/i2c@f8001000/i2c-bus@0
low_i2c:kw_handle_interrupt(state_addr, isr: 2)
low_i2c:kw_handle_interrupt(state_read, isr: 5)
low_i2c:xfer() chan=0, addrdir=0x5c, mode=3, subsize=1, subaddr=0x6b, 1 bytes, bus /uni-n@f8000000/i2c@f8001000/i2c-bus@0
low_i2c:kw_handle_interrupt(state_addr, isr: 6)
low_i2c:KW: NAK on address
low_i2c:xfer error -6
i2c-adapter i2c-7: I2C transfer at 0x2e failed, size 2, err -6
low_i2c:xfer() chan=0, addrdir=0x5d, mode=4, subsize=1, subaddr=0x6a, 1 bytes, bus /uni-n@f8000000/i2c@f8001000/i2c-bus@0
low_i2c:kw_handle_interrupt(state_addr, isr: 2)
low_i2c:kw_handle_interrupt(state_read, isr: 1)
low_i2c:kw_handle_interrupt(state_stop, isr: 4)
low_i2c:xfer() chan=0, addrdir=0x5c, mode=3, subsize=1, subaddr=0x6a, 1 bytes, bus /uni-n@f8000000/i2c@f8001000/i2c-bus@0
ieee1394: Host added: ID:BUS[0-00:1023]  GUID[001124fffed61a88]
low_i2c:kw_handle_interrupt(state_addr, isr: 6)
low_i2c:KW: NAK on address
low_i2c:xfer error -6
i2c-adapter i2c-7: I2C transfer at 0x2e failed, size 2, err -6
low_i2c:xfer() chan=0, addrdir=0x5d, mode=4, subsize=1, subaddr=0x6c, 1 bytes, bus /uni-n@f8000000/i2c@f8001000/i2c-bus@0
low_i2c:kw_handle_interrupt(state_addr, isr: 2)
low_i2c:kw_handle_interrupt(state_read, isr: 5)
low_i2c:xfer() chan=0, addrdir=0x5c, mode=3, subsize=1, subaddr=0x6c, 1 bytes, bus /uni-n@f8000000/i2c@f8001000/i2c-bus@0
low_i2c:kw_handle_interrupt(state_addr, isr: 2)
low_i2c:kw_handle_interrupt(state_write, isr: 1)
low_i2c:kw_handle_interrupt(state_stop, isr: 4)
adt746x: Lowering max temperatures from 81, 80, 87 to 70, 50, 70
low_i2c:xfer() chan=0, addrdir=0x5d, mode=4, subsize=1, subaddr=0x5c, 1 bytes, bus /uni-n@f8000000/i2c@f8001000/i2c-bus@0
eth0: Link is up at 1000 Mbps, full-duplex.
low_i2c:kw_handle_interrupt(state_addr, isr: 6)
low_i2c:KW: NAK on address
low_i2c:xfer error -6
i2c-adapter i2c-7: I2C transfer at 0x2e failed, size 2, err -6
low_i2c:xfer() chan=0, addrdir=0x5c, mode=3, subsize=1, subaddr=0x5c, 1 bytes, bus /uni-n@f8000000/i2c@f8001000/i2c-bus@0
low_i2c:kw_handle_interrupt(state_addr, isr: 6)
low_i2c:KW: NAK on address
low_i2c:xfer error -6
i2c-adapter i2c-7: I2C transfer at 0x2e failed, size 2, err -6
low_i2c:xfer() chan=0, addrdir=0x5c, mode=3, subsize=1, subaddr=0x30, 1 bytes, bus /uni-n@f8000000/i2c@f8001000/i2c-bus@0
low_i2c:kw_handle_interrupt(state_addr, isr: 2)
low_i2c:kw_handle_interrupt(state_write, isr: 1)
low_i2c:kw_handle_interrupt(state_stop, isr: 4)
PowerMac i2c bus uni-n 0 registered

As you can see there are 4 errors, but the config register read doesn't
fail so this is considered a success.

Ever heard of this problem?

One very interesting thing I've noticed is that therm_adt746x register
access _after_ the initialization works reliably. Errors only happen in
probe_thermostat(). This makes me suspect that the problem is either a
low level initialization happening too late, or another initialization
step happening in parallel and interfering with probe_thermostat().

Tim found evidences in older boot logs that the problem isn't new and
was already present back in kernel 2.6.24 at least.

Any idea what the problem can be and/or how to debug it further?

-- 
Jean Delvare

Re: i2c-powermac fails

[Benjamin Herrenschmidt]

On Tue, 2009-10-13 at 11:23 +0200, Jean Delvare wrote:
> Hi Ben, Paul,
> 
> I had a report by Tim Shepard (Cc'd) that the therm_adt746x driver
> sometimes fails to initialize on his PowerBook G4 running kernel
> 2.6.31. The following error message can be seen in the logs when the
> failure happens:
> 
> therm_adt746x 7-002e: Thermostat failed to read config!
> 
> After enabling low-level i2c debugging, it turns out that the problem
> is caused by low-level errors at the I2C bus level:

Nothing comes to mind immediately, but I'll have another look tomorrow.

Maybe we are configuring the i2c bus too fast ? Another possibility
would be that the device needs some retries ...

Ben.

Re: i2c-powermac fails

[Jean Delvare]

On Tue, 13 Oct 2009 20:32:28 +1100, Benjamin Herrenschmidt wrote:
> On Tue, 2009-10-13 at 11:23 +0200, Jean Delvare wrote:
> > Hi Ben, Paul,
> > 
> > I had a report by Tim Shepard (Cc'd) that the therm_adt746x driver
> > sometimes fails to initialize on his PowerBook G4 running kernel
> > 2.6.31. The following error message can be seen in the logs when the
> > failure happens:
> > 
> > therm_adt746x 7-002e: Thermostat failed to read config!
> > 
> > After enabling low-level i2c debugging, it turns out that the problem
> > is caused by low-level errors at the I2C bus level:
> 
> Nothing comes to mind immediately, but I'll have another look tomorrow.
> 
> Maybe we are configuring the i2c bus too fast ? Another possibility
> would be that the device needs some retries ...

I guess that retrying would work around the problem, yes. But I do not
think this is the proper solution. If retries were needed, they would
be needed all the time, not just at initialization time. And as I said,
the SMBus specification says that devices have to always ack their
slave address (they can always delay the transaction later if they need
more time) so I am reasonably certain that the ADT7467 does ack his
address always. If it seems otherwise, this suggests that either the
message was not properly sent on the bus (so the ADT7467 did not have
anything to ack), or the ADT7467's ack went on the bus but the I2C
master didn't see it.

I2C bus being setup too fast sounds more likely. It might be worth
adding an arbitrary delay after initialization, just to see if it
helps. Not sure where though, as I'm not familiar with the Powermac
initialization steps. Maybe right before i2c_add_adapter() in
i2c_powermac_probe?

-- 
Jean Delvare

Re: i2c-powermac fails

[Jean Delvare]

Hi all,

On Tue, 13 Oct 2009 11:49:48 +0200, Jean Delvare wrote:
> I2C bus being setup too fast sounds more likely. It might be worth
> adding an arbitrary delay after initialization, just to see if it
> helps. Not sure where though, as I'm not familiar with the Powermac
> initialization steps. Maybe right before i2c_add_adapter() in
> i2c_powermac_probe?

Tim, can you please give a try to this patch? Obviously your machine
will take 5 additional seconds to boot, and this isn't meant as a real
fix, but if it helps, this will be an interesting hint for further
debugging attempts.

--- kernel32.orig/drivers/macintosh/therm_adt746x.c
+++ kernel32/drivers/macintosh/therm_adt746x.c
@@ -380,6 +380,7 @@ static int probe_thermostat(struct i2c_c
 	if (thermostat)
 		return 0;
 
+	msleep(5000);
 	th = kzalloc(sizeof(struct thermostat), GFP_KERNEL);
 	if (!th)
 		return -ENOMEM;


-- 
Jean Delvare

Re: i2c-powermac fails

[Benjamin Herrenschmidt]

On Wed, 2009-10-14 at 23:02 +0200, Jean Delvare wrote:
> Hi all,
> 
> On Tue, 13 Oct 2009 11:49:48 +0200, Jean Delvare wrote:
> > I2C bus being setup too fast sounds more likely. It might be worth
> > adding an arbitrary delay after initialization, just to see if it
> > helps. Not sure where though, as I'm not familiar with the Powermac
> > initialization steps. Maybe right before i2c_add_adapter() in
> > i2c_powermac_probe?
> 
> Tim, can you please give a try to this patch? Obviously your machine
> will take 5 additional seconds to boot, and this isn't meant as a real
> fix, but if it helps, this will be an interesting hint for further
> debugging attempts.

Oh, I was actually thinking about the frequency of the I2C clock :-)

Cheers,
Ben.

> --- kernel32.orig/drivers/macintosh/therm_adt746x.c
> +++ kernel32/drivers/macintosh/therm_adt746x.c
> @@ -380,6 +380,7 @@ static int probe_thermostat(struct i2c_c
>  	if (thermostat)
>  		return 0;
>  
> +	msleep(5000);
>  	th = kzalloc(sizeof(struct thermostat), GFP_KERNEL);
>  	if (!th)
>  		return -ENOMEM;
> 
> 

Re: i2c-powermac fails

[Jean Delvare]

On Thu, 15 Oct 2009 08:26:15 +1100, Benjamin Herrenschmidt wrote:
> On Wed, 2009-10-14 at 23:02 +0200, Jean Delvare wrote:
> > Hi all,
> > 
> > On Tue, 13 Oct 2009 11:49:48 +0200, Jean Delvare wrote:
> > > I2C bus being setup too fast sounds more likely. It might be worth
> > > adding an arbitrary delay after initialization, just to see if it
> > > helps. Not sure where though, as I'm not familiar with the Powermac
> > > initialization steps. Maybe right before i2c_add_adapter() in
> > > i2c_powermac_probe?
> > 
> > Tim, can you please give a try to this patch? Obviously your machine
> > will take 5 additional seconds to boot, and this isn't meant as a real
> > fix, but if it helps, this will be an interesting hint for further
> > debugging attempts.
> 
> Oh, I was actually thinking about the frequency of the I2C clock :-)

Oh. Well, if that was the case, we would see errors all the time, not
just during initialization, right? Or does the I2C clock frequency
change over time somehow?

-- 
Jean Delvare

Re: i2c-powermac fails

[Benjamin Herrenschmidt]

On Thu, 2009-10-15 at 12:49 +0200, Jean Delvare wrote:
> Oh. Well, if that was the case, we would see errors all the time, not
> just during initialization, right? Or does the I2C clock frequency
> change over time somehow?

No but maybe we are a bit on the "limit" of the device and some
registers take long to respond than others ?

Cheers,
Ben.

Re: i2c-powermac fails

[Jean Delvare]

On Thu, 15 Oct 2009 22:19:19 +1100, Benjamin Herrenschmidt wrote:
> On Thu, 2009-10-15 at 12:49 +0200, Jean Delvare wrote:
> > Oh. Well, if that was the case, we would see errors all the time, not
> > just during initialization, right? Or does the I2C clock frequency
> > change over time somehow?
> 
> No but maybe we are a bit on the "limit" of the device and some
> registers take long to respond than others ?

Unlikely. The ADT7460 can run at I2C clock rates up to 400 kHz while
the Keywest I2C runs at 25, 50 or 100 kHz if I read the code properly.
I don't know what exact speed is used on Tim's system, apparently it is
read from the hardware in the device tree directly?

We could have low_i2c.c log the I2C clock frequency and/or try to force
the lowest speed (25 kHz) and see if it helps, but I very much doubt
it. And I'd rather wait for Tim to report the result with my last patch
first.

-- 
Jean Delvare

Re: i2c-powermac fails

[Jean Delvare]

On Thu, 15 Oct 2009 16:05:13 +0200, Jean Delvare wrote:
> On Thu, 15 Oct 2009 22:19:19 +1100, Benjamin Herrenschmidt wrote:
> > On Thu, 2009-10-15 at 12:49 +0200, Jean Delvare wrote:
> > > Oh. Well, if that was the case, we would see errors all the time, not
> > > just during initialization, right? Or does the I2C clock frequency
> > > change over time somehow?
> > 
> > No but maybe we are a bit on the "limit" of the device and some
> > registers take long to respond than others ?
> 
> Unlikely. The ADT7460 can run at I2C clock rates up to 400 kHz while
> the Keywest I2C runs at 25, 50 or 100 kHz if I read the code properly.
> I don't know what exact speed is used on Tim's system, apparently it is
> read from the hardware in the device tree directly?
> 
> We could have low_i2c.c log the I2C clock frequency and/or try to force
> the lowest speed (25 kHz) and see if it helps, but I very much doubt
> it. And I'd rather wait for Tim to report the result with my last patch
> first.

Ben, wouldn't this recent patch of yours be worth testing too?

http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-2.6.git;a=commitdiff;h=11a50873ef2b3c1c3fe99a661c22c08f35d93553

If it solves problems at resume time, I guess it might also solve
problems at boot time?

-- 
Jean Delvare

Re: i2c-powermac fails

[Benjamin Herrenschmidt]

On Fri, 2009-10-16 at 09:44 +0200, Jean Delvare wrote:
> On Thu, 15 Oct 2009 16:05:13 +0200, Jean Delvare wrote:
> > On Thu, 15 Oct 2009 22:19:19 +1100, Benjamin Herrenschmidt wrote:
> > > On Thu, 2009-10-15 at 12:49 +0200, Jean Delvare wrote:
> > > > Oh. Well, if that was the case, we would see errors all the time, not
> > > > just during initialization, right? Or does the I2C clock frequency
> > > > change over time somehow?
> > > 
> > > No but maybe we are a bit on the "limit" of the device and some
> > > registers take long to respond than others ?
> > 
> > Unlikely. The ADT7460 can run at I2C clock rates up to 400 kHz while
> > the Keywest I2C runs at 25, 50 or 100 kHz if I read the code properly.
> > I don't know what exact speed is used on Tim's system, apparently it is
> > read from the hardware in the device tree directly?
> > 
> > We could have low_i2c.c log the I2C clock frequency and/or try to force
> > the lowest speed (25 kHz) and see if it helps, but I very much doubt
> > it. And I'd rather wait for Tim to report the result with my last patch
> > first.
> 
> Ben, wouldn't this recent patch of yours be worth testing too?
> 
> http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-2.6.git;a=commitdiff;h=11a50873ef2b3c1c3fe99a661c22c08f35d93553
> 
> If it solves problems at resume time, I guess it might also solve
> problems at boot time?

I doubt it. The problem was related to the way interrupts get turned off
at suspend time by the generic code, which is unrelated to what happens
at boot.

Cheers,
Ben.