i2c: at91: fix write transfers by clearing pending interrupt first
diff mbox

Message ID 1444746104-20615-1-git-send-email-ludovic.desroches@atmel.com
State Superseded
Headers show

Commit Message

ludovic.desroches@atmel.com Oct. 13, 2015, 2:21 p.m. UTC
From: Cyrille Pitchen <cyrille.pitchen@atmel.com>

In some cases a NACK interrupt may be pending in the Status Register (SR)
as a result of a previous transfer. However at91_do_twi_transfer() did not
read the SR to clear pending interruptions before starting a new transfer.
Hence a NACK interrupt rose as soon as it was enabled again at the I2C
controller level, resulting in a wrong sequence of operations and strange
patterns of behaviour on the I2C bus, such as a clock stretch followed by
a restart of the transfer.

This first issue occurred with both DMA and PIO write transfers.

Also when a NACK error was detected during a PIO write transfer, the
interrupt handler used to wrongly start a new transfer by writing into the
Transmit Holding Register (THR). Then the I2C slave was likely to reply
with a second NACK.

This second issue is fixed in atmel_twi_interrupt() by handling the TXRDY
status bit only if both the TXCOMP and NACK status bits are cleared.

Tested with a at24 eeprom on sama5d36ek board running a linux-4.1-at91
kernel image. Adapted to linux-next.

Signed-off-by: Cyrille Pitchen <cyrille.pitchen@atmel.com>
Fixes: 93563a6a71bb ("i2c: at91: fix a race condition when using the DMA controller")
Reported-by: Peter Rosin <peda@lysator.liu.se>
Signed-off-by: Ludovic Desroches <ludovic.desroches@atmel.com>
Cc: stable@vger.kernel.org #4.1
---
 drivers/i2c/busses/i2c-at91.c | 58 +++++++++++++++++++++++++++++++++++++------
 1 file changed, 50 insertions(+), 8 deletions(-)

Comments

Peter Rosin Oct. 13, 2015, 3:19 p.m. UTC | #1
On 2015-10-13 16:21, Ludovic Desroches wrote:
> From: Cyrille Pitchen <cyrille.pitchen@atmel.com>
> 
> In some cases a NACK interrupt may be pending in the Status Register (SR)
> as a result of a previous transfer. However at91_do_twi_transfer() did not
> read the SR to clear pending interruptions before starting a new transfer.
> Hence a NACK interrupt rose as soon as it was enabled again at the I2C
> controller level, resulting in a wrong sequence of operations and strange
> patterns of behaviour on the I2C bus, such as a clock stretch followed by
> a restart of the transfer.
> 
> This first issue occurred with both DMA and PIO write transfers.
> 
> Also when a NACK error was detected during a PIO write transfer, the
> interrupt handler used to wrongly start a new transfer by writing into the
> Transmit Holding Register (THR). Then the I2C slave was likely to reply
> with a second NACK.
> 
> This second issue is fixed in atmel_twi_interrupt() by handling the TXRDY
> status bit only if both the TXCOMP and NACK status bits are cleared.
> 
> Tested with a at24 eeprom on sama5d36ek board running a linux-4.1-at91
> kernel image. Adapted to linux-next.
> 
> Signed-off-by: Cyrille Pitchen <cyrille.pitchen@atmel.com>
> Fixes: 93563a6a71bb ("i2c: at91: fix a race condition when using the DMA controller")
> Reported-by: Peter Rosin <peda@lysator.liu.se>
> Signed-off-by: Ludovic Desroches <ludovic.desroches@atmel.com>
> Cc: stable@vger.kernel.org #4.1

The regression is gone with this patch (vanilla 4.2), thank you!

However, looking at the bus, there are two NACKs after each
successful chunk of memory written by the eeprom driver.

Looking at the eeprom driver, I expect this on the bus:

S 0x50 0x00 "hello there guys" P
S 0x50 NACK P
delay for at least 1 ms (since the eeprom driver has a msleep(1) call).
S 0x50 NACK P
delay for at least 1 ms
...
...
S 0x50 NACK P
delay for at least 1 ms
S 0x50 0x10 "and girls\n" P

This is not what I observe on the bus, most of the time there is a
second NACK immediately following the first. I suspect that it is
the i2c bus driver that somehow confuses itself and reissues the
command for some reason?

But this behavior has been there since the beginning, so it's probably
orthogonal, and killing the data corrupting regression is much more
important to me than fussing over a surplus failed transfer. Hence

Tested-by: Peter Rosin <peda@lysator.liu.se>

Cheers,
Peter

--
To unsubscribe from this list: send the line "unsubscribe linux-i2c" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Cyrille Pitchen Oct. 13, 2015, 4:47 p.m. UTC | #2
Le 13/10/2015 17:19, Peter Rosin a écrit :
> On 2015-10-13 16:21, Ludovic Desroches wrote:
>> From: Cyrille Pitchen <cyrille.pitchen@atmel.com>
>>
>> In some cases a NACK interrupt may be pending in the Status Register (SR)
>> as a result of a previous transfer. However at91_do_twi_transfer() did not
>> read the SR to clear pending interruptions before starting a new transfer.
>> Hence a NACK interrupt rose as soon as it was enabled again at the I2C
>> controller level, resulting in a wrong sequence of operations and strange
>> patterns of behaviour on the I2C bus, such as a clock stretch followed by
>> a restart of the transfer.
>>
>> This first issue occurred with both DMA and PIO write transfers.
>>
>> Also when a NACK error was detected during a PIO write transfer, the
>> interrupt handler used to wrongly start a new transfer by writing into the
>> Transmit Holding Register (THR). Then the I2C slave was likely to reply
>> with a second NACK.
>>
>> This second issue is fixed in atmel_twi_interrupt() by handling the TXRDY
>> status bit only if both the TXCOMP and NACK status bits are cleared.
>>
>> Tested with a at24 eeprom on sama5d36ek board running a linux-4.1-at91
>> kernel image. Adapted to linux-next.
>>
>> Signed-off-by: Cyrille Pitchen <cyrille.pitchen@atmel.com>
>> Fixes: 93563a6a71bb ("i2c: at91: fix a race condition when using the DMA controller")
>> Reported-by: Peter Rosin <peda@lysator.liu.se>
>> Signed-off-by: Ludovic Desroches <ludovic.desroches@atmel.com>
>> Cc: stable@vger.kernel.org #4.1
> 
> The regression is gone with this patch (vanilla 4.2), thank you!
> 
> However, looking at the bus, there are two NACKs after each
> successful chunk of memory written by the eeprom driver.
> 
> Looking at the eeprom driver, I expect this on the bus:
> 
> S 0x50 0x00 "hello there guys" P
> S 0x50 NACK P
> delay for at least 1 ms (since the eeprom driver has a msleep(1) call).
> S 0x50 NACK P
> delay for at least 1 ms
> ...
> ...
> S 0x50 NACK P
> delay for at least 1 ms
> S 0x50 0x10 "and girls\n" P
> 
> This is not what I observe on the bus, most of the time there is a
> second NACK immediately following the first. I suspect that it is
> the i2c bus driver that somehow confuses itself and reissues the
> command for some reason?
> 
> But this behavior has been there since the beginning, so it's probably
> orthogonal, and killing the data corrupting regression is much more
> important to me than fussing over a surplus failed transfer. Hence
> 
> Tested-by: Peter Rosin <peda@lysator.liu.se>
> 
> Cheers,
> Peter
> 

Hi Peter,

sama5d3x and sama5d4x don't support the so called "Alternative Command mode"
whereas sama5d2x do. The Alternative Command mode comes with a new hardware
mechanism inside the I2C controller which locks the transmission of data on
the I2C bus when a NACK is detected. It means that even if a data is written
into the THR, the I2C controller doesn't push this data on the I2C bus but
retains the data in the THR (and its associated FIFO for sama5d2x and future
SoCs) until the driver unlocks the transmitter by writing the LOCKCLR (Lock
Clear) bit in the Control Register. Then and only then, the transmitter outputs
pending data again.
This new mechanism was introduced to cope with an unwanted DMA write into the
THR after a NACK. Indeed, as I've tried to explain in my patch, when a first
NACK is detected, the I2C controller sets the TXCOMP, NACK and TXRDY bits
alltogether in the Status Register. However setting the TXRDY bit also triggers
the DMA controller to write the next data into the THR. Pitifully, WITHOUT the
new lock mechanism, writing into the THR starts a new I2C frame. Since the
eeprom is likely not to be ready yet, it replies by a second NACK. So you
see on the scope two consecutive NACKs.

On sama5d3x and sama5d4x, which do not support this lock mechanism, you are
likely to see a successful write transfer followed by two NACKs then a delay
and finally a new successful write transfer. This is the case 2b:

1 - A successfull write transfer is completed.
2 - The at24 driver immediately tries to perform the next write transfer...
3 - ... but the eeprom is not ready yet and replies with a first NACK.
4 - The I2C controller detects this NACK and sets the NACK, TXCOMP and TXRDY
    bits in its Status Register (and interrupts the CPU).
5 - The DMA controller is triggered by the TXRDY bit to write the next data
    into the THR.
6 - WITHTOUT the lock mechanism, the I2C controller starts a new frame because
   of the write into the THR by the DMA controller...
7 - ... but the eeprom is still not ready and replies with a second NACK.

8 - starting from 4, the CPU handles the interrupt generated by the first NACK.
    Depending on the timing, it has already masked the interrupted before the
    second NACK. In such a case, the NACK bit is pending in the Status
    Register. Then it reports the first NACK error to the at24 driver.
9 - The at24 driver handles the NACK error: it sleeps for a while before
    retrying to perform the write operation.
10 - With the new patch, the I2C controller reads the Status Register to clear
     pending (NACK) interrupts before actually starting this new (retried)
     transfer.


So if you are using DMA transfers on a sama5d3x board, you're are likely to
see, as I did see, a valid write transfer followed by 2 NACKs, then a delay and
finally a new write transfer.
The 2nd NACK is not wanted but expected. Without the lock mechanism, there is
nothing we can do at the I2C controller level. However a workaround may exist:
inserting a small delay after a successful write transfer should give the
eeprom enough time to be ready to process the next write so even the first NACK
would disappear.
This is what I saw while debugging with dev_info() traces. Those traces had the
side effect of inserting delays hence changing the timing.

As you see, we have to deal with some known hardware design quirks, which are
fixed by the lock mechanism. Without the lock mechanism, the interrupt handler
and the CPU are likely to come too late to cancel the DMA transfer before the
DMA controller writes a new byte into the THR, hence generating an unwanted
frame.

Best Regards,

Cyrille
--
To unsubscribe from this list: send the line "unsubscribe linux-i2c" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Peter Rosin Oct. 13, 2015, 6:01 p.m. UTC | #3
On 2015-10-13 18:47, Cyrille Pitchen wrote:
> Le 13/10/2015 17:19, Peter Rosin a écrit :
>> On 2015-10-13 16:21, Ludovic Desroches wrote:
>>> From: Cyrille Pitchen <cyrille.pitchen@atmel.com>
>>>
>>> In some cases a NACK interrupt may be pending in the Status Register (SR)
>>> as a result of a previous transfer. However at91_do_twi_transfer() did not
>>> read the SR to clear pending interruptions before starting a new transfer.
>>> Hence a NACK interrupt rose as soon as it was enabled again at the I2C
>>> controller level, resulting in a wrong sequence of operations and strange
>>> patterns of behaviour on the I2C bus, such as a clock stretch followed by
>>> a restart of the transfer.
>>>
>>> This first issue occurred with both DMA and PIO write transfers.
>>>
>>> Also when a NACK error was detected during a PIO write transfer, the
>>> interrupt handler used to wrongly start a new transfer by writing into the
>>> Transmit Holding Register (THR). Then the I2C slave was likely to reply
>>> with a second NACK.
>>>
>>> This second issue is fixed in atmel_twi_interrupt() by handling the TXRDY
>>> status bit only if both the TXCOMP and NACK status bits are cleared.
>>>
>>> Tested with a at24 eeprom on sama5d36ek board running a linux-4.1-at91
>>> kernel image. Adapted to linux-next.
>>>
>>> Signed-off-by: Cyrille Pitchen <cyrille.pitchen@atmel.com>
>>> Fixes: 93563a6a71bb ("i2c: at91: fix a race condition when using the DMA controller")
>>> Reported-by: Peter Rosin <peda@lysator.liu.se>
>>> Signed-off-by: Ludovic Desroches <ludovic.desroches@atmel.com>
>>> Cc: stable@vger.kernel.org #4.1
>>
>> The regression is gone with this patch (vanilla 4.2), thank you!
>>
>> However, looking at the bus, there are two NACKs after each
>> successful chunk of memory written by the eeprom driver.
>>
>> Looking at the eeprom driver, I expect this on the bus:
>>
>> S 0x50 0x00 "hello there guys" P
>> S 0x50 NACK P
>> delay for at least 1 ms (since the eeprom driver has a msleep(1) call).
>> S 0x50 NACK P
>> delay for at least 1 ms
>> ...
>> ...
>> S 0x50 NACK P
>> delay for at least 1 ms
>> S 0x50 0x10 "and girls\n" P
>>
>> This is not what I observe on the bus, most of the time there is a
>> second NACK immediately following the first. I suspect that it is
>> the i2c bus driver that somehow confuses itself and reissues the
>> command for some reason?
>>
>> But this behavior has been there since the beginning, so it's probably
>> orthogonal, and killing the data corrupting regression is much more
>> important to me than fussing over a surplus failed transfer. Hence
>>
>> Tested-by: Peter Rosin <peda@lysator.liu.se>
>>
>> Cheers,
>> Peter
>>
> 
> Hi Peter,
> 
> sama5d3x and sama5d4x don't support the so called "Alternative Command mode"
> whereas sama5d2x do. The Alternative Command mode comes with a new hardware
> mechanism inside the I2C controller which locks the transmission of data on
> the I2C bus when a NACK is detected. It means that even if a data is written
> into the THR, the I2C controller doesn't push this data on the I2C bus but
> retains the data in the THR (and its associated FIFO for sama5d2x and future
> SoCs) until the driver unlocks the transmitter by writing the LOCKCLR (Lock
> Clear) bit in the Control Register. Then and only then, the transmitter outputs
> pending data again.
> This new mechanism was introduced to cope with an unwanted DMA write into the
> THR after a NACK. Indeed, as I've tried to explain in my patch, when a first
> NACK is detected, the I2C controller sets the TXCOMP, NACK and TXRDY bits
> alltogether in the Status Register. However setting the TXRDY bit also triggers
> the DMA controller to write the next data into the THR. Pitifully, WITHOUT the
> new lock mechanism, writing into the THR starts a new I2C frame. Since the
> eeprom is likely not to be ready yet, it replies by a second NACK. So you
> see on the scope two consecutive NACKs.
> 
> On sama5d3x and sama5d4x, which do not support this lock mechanism, you are
> likely to see a successful write transfer followed by two NACKs then a delay
> and finally a new successful write transfer. This is the case 2b:
> 
> 1 - A successfull write transfer is completed.
> 2 - The at24 driver immediately tries to perform the next write transfer...
> 3 - ... but the eeprom is not ready yet and replies with a first NACK.
> 4 - The I2C controller detects this NACK and sets the NACK, TXCOMP and TXRDY
>     bits in its Status Register (and interrupts the CPU).
> 5 - The DMA controller is triggered by the TXRDY bit to write the next data
>     into the THR.
> 6 - WITHTOUT the lock mechanism, the I2C controller starts a new frame because
>    of the write into the THR by the DMA controller...
> 7 - ... but the eeprom is still not ready and replies with a second NACK.
> 
> 8 - starting from 4, the CPU handles the interrupt generated by the first NACK.
>     Depending on the timing, it has already masked the interrupted before the
>     second NACK. In such a case, the NACK bit is pending in the Status
>     Register. Then it reports the first NACK error to the at24 driver.
> 9 - The at24 driver handles the NACK error: it sleeps for a while before
>     retrying to perform the write operation.
> 10 - With the new patch, the I2C controller reads the Status Register to clear
>      pending (NACK) interrupts before actually starting this new (retried)
>      transfer.
> 
> 
> So if you are using DMA transfers on a sama5d3x board, you're are likely to
> see, as I did see, a valid write transfer followed by 2 NACKs, then a delay and
> finally a new write transfer.
> The 2nd NACK is not wanted but expected. Without the lock mechanism, there is
> nothing we can do at the I2C controller level. However a workaround may exist:
> inserting a small delay after a successful write transfer should give the
> eeprom enough time to be ready to process the next write so even the first NACK
> would disappear.
> This is what I saw while debugging with dev_info() traces. Those traces had the
> side effect of inserting delays hence changing the timing.
> 
> As you see, we have to deal with some known hardware design quirks, which are
> fixed by the lock mechanism. Without the lock mechanism, the interrupt handler
> and the CPU are likely to come too late to cancel the DMA transfer before the
> DMA controller writes a new byte into the THR, hence generating an unwanted
> frame.

Ok, now I get it, I should have been reading the source code comments instead
of the commit message. My bad. That 2a) case from the atmel_twi_interrupt comment
seems very nasty indeed! Is it clear what will happen if the second frame after
the first NACKed frame isn't NACKed too? May that transfer be canceled half way
through at a later point, or will it be a complete transfer as specified by the
issuing driver? What will be reported to the issuing driver for such an i2c
transfer that was first NACKed but then wasn't in the second trailing frame?

My guess is that the issuing driver will get the result of the first NACK, and
that anything after that didn't really happen as far as the rest of the kernel
is concerned? And while that is OK for my eeprom case, it might not be for any
other i2c device, where a spurious access might destruct important state such
as bits that are cleared on read, or something like that. Or am I missing
something?

Some warning about using DMA for i2c on sama5d[34]x might be in place if
I'm correct, no?

Cheers,
Peter

--
To unsubscribe from this list: send the line "unsubscribe linux-i2c" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
ludovic.desroches@atmel.com Oct. 14, 2015, 5:43 a.m. UTC | #4
On Tue, Oct 13, 2015 at 08:01:34PM +0200, Peter Rosin wrote:
> On 2015-10-13 18:47, Cyrille Pitchen wrote:
> > Le 13/10/2015 17:19, Peter Rosin a écrit :
> >> On 2015-10-13 16:21, Ludovic Desroches wrote:
> >>> From: Cyrille Pitchen <cyrille.pitchen@atmel.com>
> >>>
> >>> In some cases a NACK interrupt may be pending in the Status Register (SR)
> >>> as a result of a previous transfer. However at91_do_twi_transfer() did not
> >>> read the SR to clear pending interruptions before starting a new transfer.
> >>> Hence a NACK interrupt rose as soon as it was enabled again at the I2C
> >>> controller level, resulting in a wrong sequence of operations and strange
> >>> patterns of behaviour on the I2C bus, such as a clock stretch followed by
> >>> a restart of the transfer.
> >>>
> >>> This first issue occurred with both DMA and PIO write transfers.
> >>>
> >>> Also when a NACK error was detected during a PIO write transfer, the
> >>> interrupt handler used to wrongly start a new transfer by writing into the
> >>> Transmit Holding Register (THR). Then the I2C slave was likely to reply
> >>> with a second NACK.
> >>>
> >>> This second issue is fixed in atmel_twi_interrupt() by handling the TXRDY
> >>> status bit only if both the TXCOMP and NACK status bits are cleared.
> >>>
> >>> Tested with a at24 eeprom on sama5d36ek board running a linux-4.1-at91
> >>> kernel image. Adapted to linux-next.
> >>>
> >>> Signed-off-by: Cyrille Pitchen <cyrille.pitchen@atmel.com>
> >>> Fixes: 93563a6a71bb ("i2c: at91: fix a race condition when using the DMA controller")
> >>> Reported-by: Peter Rosin <peda@lysator.liu.se>
> >>> Signed-off-by: Ludovic Desroches <ludovic.desroches@atmel.com>
> >>> Cc: stable@vger.kernel.org #4.1
> >>
> >> The regression is gone with this patch (vanilla 4.2), thank you!
> >>
> >> However, looking at the bus, there are two NACKs after each
> >> successful chunk of memory written by the eeprom driver.
> >>
> >> Looking at the eeprom driver, I expect this on the bus:
> >>
> >> S 0x50 0x00 "hello there guys" P
> >> S 0x50 NACK P
> >> delay for at least 1 ms (since the eeprom driver has a msleep(1) call).
> >> S 0x50 NACK P
> >> delay for at least 1 ms
> >> ...
> >> ...
> >> S 0x50 NACK P
> >> delay for at least 1 ms
> >> S 0x50 0x10 "and girls\n" P
> >>
> >> This is not what I observe on the bus, most of the time there is a
> >> second NACK immediately following the first. I suspect that it is
> >> the i2c bus driver that somehow confuses itself and reissues the
> >> command for some reason?
> >>
> >> But this behavior has been there since the beginning, so it's probably
> >> orthogonal, and killing the data corrupting regression is much more
> >> important to me than fussing over a surplus failed transfer. Hence
> >>
> >> Tested-by: Peter Rosin <peda@lysator.liu.se>
> >>
> >> Cheers,
> >> Peter
> >>
> > 
> > Hi Peter,
> > 
> > sama5d3x and sama5d4x don't support the so called "Alternative Command mode"
> > whereas sama5d2x do. The Alternative Command mode comes with a new hardware
> > mechanism inside the I2C controller which locks the transmission of data on
> > the I2C bus when a NACK is detected. It means that even if a data is written
> > into the THR, the I2C controller doesn't push this data on the I2C bus but
> > retains the data in the THR (and its associated FIFO for sama5d2x and future
> > SoCs) until the driver unlocks the transmitter by writing the LOCKCLR (Lock
> > Clear) bit in the Control Register. Then and only then, the transmitter outputs
> > pending data again.
> > This new mechanism was introduced to cope with an unwanted DMA write into the
> > THR after a NACK. Indeed, as I've tried to explain in my patch, when a first
> > NACK is detected, the I2C controller sets the TXCOMP, NACK and TXRDY bits
> > alltogether in the Status Register. However setting the TXRDY bit also triggers
> > the DMA controller to write the next data into the THR. Pitifully, WITHOUT the
> > new lock mechanism, writing into the THR starts a new I2C frame. Since the
> > eeprom is likely not to be ready yet, it replies by a second NACK. So you
> > see on the scope two consecutive NACKs.
> > 
> > On sama5d3x and sama5d4x, which do not support this lock mechanism, you are
> > likely to see a successful write transfer followed by two NACKs then a delay
> > and finally a new successful write transfer. This is the case 2b:
> > 
> > 1 - A successfull write transfer is completed.
> > 2 - The at24 driver immediately tries to perform the next write transfer...
> > 3 - ... but the eeprom is not ready yet and replies with a first NACK.
> > 4 - The I2C controller detects this NACK and sets the NACK, TXCOMP and TXRDY
> >     bits in its Status Register (and interrupts the CPU).
> > 5 - The DMA controller is triggered by the TXRDY bit to write the next data
> >     into the THR.
> > 6 - WITHTOUT the lock mechanism, the I2C controller starts a new frame because
> >    of the write into the THR by the DMA controller...
> > 7 - ... but the eeprom is still not ready and replies with a second NACK.
> > 
> > 8 - starting from 4, the CPU handles the interrupt generated by the first NACK.
> >     Depending on the timing, it has already masked the interrupted before the
> >     second NACK. In such a case, the NACK bit is pending in the Status
> >     Register. Then it reports the first NACK error to the at24 driver.
> > 9 - The at24 driver handles the NACK error: it sleeps for a while before
> >     retrying to perform the write operation.
> > 10 - With the new patch, the I2C controller reads the Status Register to clear
> >      pending (NACK) interrupts before actually starting this new (retried)
> >      transfer.
> > 
> > 
> > So if you are using DMA transfers on a sama5d3x board, you're are likely to
> > see, as I did see, a valid write transfer followed by 2 NACKs, then a delay and
> > finally a new write transfer.
> > The 2nd NACK is not wanted but expected. Without the lock mechanism, there is
> > nothing we can do at the I2C controller level. However a workaround may exist:
> > inserting a small delay after a successful write transfer should give the
> > eeprom enough time to be ready to process the next write so even the first NACK
> > would disappear.
> > This is what I saw while debugging with dev_info() traces. Those traces had the
> > side effect of inserting delays hence changing the timing.
> > 
> > As you see, we have to deal with some known hardware design quirks, which are
> > fixed by the lock mechanism. Without the lock mechanism, the interrupt handler
> > and the CPU are likely to come too late to cancel the DMA transfer before the
> > DMA controller writes a new byte into the THR, hence generating an unwanted
> > frame.
> 
> Ok, now I get it, I should have been reading the source code comments instead
> of the commit message. My bad. That 2a) case from the atmel_twi_interrupt comment
> seems very nasty indeed! Is it clear what will happen if the second frame after
> the first NACKed frame isn't NACKed too? May that transfer be canceled half way
> through at a later point, or will it be a complete transfer as specified by the
> issuing driver? What will be reported to the issuing driver for such an i2c
> transfer that was first NACKed but then wasn't in the second trailing frame?
> 

We were discussing about this case and we are worried that it simply
hangs the transfer wihout sending a stop command. We never get this case
yet so we keep it in mind but we don't correct it since we are not sure
of the behavior and on side effects it can introduce. I think the
i2c-at91 driver will return a spurious error to the eeprom driver but it won't
let the physical i2c bus in a proper state.

> My guess is that the issuing driver will get the result of the first NACK, and
> that anything after that didn't really happen as far as the rest of the kernel
> is concerned? And while that is OK for my eeprom case, it might not be for any
> other i2c device, where a spurious access might destruct important state such
> as bits that are cleared on read, or something like that. Or am I missing
> something?
> 
> Some warning about using DMA for i2c on sama5d[34]x might be in place if
> I'm correct, no?
> 
> Cheers,
> Peter
> 
--
To unsubscribe from this list: send the line "unsubscribe linux-i2c" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Peter Rosin Oct. 15, 2015, 11:47 p.m. UTC | #5
On 2015-10-14 07:43, Ludovic Desroches wrote:
> On Tue, Oct 13, 2015 at 08:01:34PM +0200, Peter Rosin wrote:
>> On 2015-10-13 18:47, Cyrille Pitchen wrote:
>>> Le 13/10/2015 17:19, Peter Rosin a écrit :
>>>> On 2015-10-13 16:21, Ludovic Desroches wrote:
>>>>> From: Cyrille Pitchen <cyrille.pitchen@atmel.com>
>>>>>
>>>>> In some cases a NACK interrupt may be pending in the Status Register (SR)
>>>>> as a result of a previous transfer. However at91_do_twi_transfer() did not
>>>>> read the SR to clear pending interruptions before starting a new transfer.
>>>>> Hence a NACK interrupt rose as soon as it was enabled again at the I2C
>>>>> controller level, resulting in a wrong sequence of operations and strange
>>>>> patterns of behaviour on the I2C bus, such as a clock stretch followed by
>>>>> a restart of the transfer.
>>>>>
>>>>> This first issue occurred with both DMA and PIO write transfers.
>>>>>
>>>>> Also when a NACK error was detected during a PIO write transfer, the
>>>>> interrupt handler used to wrongly start a new transfer by writing into the
>>>>> Transmit Holding Register (THR). Then the I2C slave was likely to reply
>>>>> with a second NACK.
>>>>>
>>>>> This second issue is fixed in atmel_twi_interrupt() by handling the TXRDY
>>>>> status bit only if both the TXCOMP and NACK status bits are cleared.
>>>>>
>>>>> Tested with a at24 eeprom on sama5d36ek board running a linux-4.1-at91
>>>>> kernel image. Adapted to linux-next.
>>>>>
>>>>> Signed-off-by: Cyrille Pitchen <cyrille.pitchen@atmel.com>
>>>>> Fixes: 93563a6a71bb ("i2c: at91: fix a race condition when using the DMA controller")
>>>>> Reported-by: Peter Rosin <peda@lysator.liu.se>
>>>>> Signed-off-by: Ludovic Desroches <ludovic.desroches@atmel.com>
>>>>> Cc: stable@vger.kernel.org #4.1
>>>>
>>>> The regression is gone with this patch (vanilla 4.2), thank you!
>>>>
>>>> However, looking at the bus, there are two NACKs after each
>>>> successful chunk of memory written by the eeprom driver.
>>>>
>>>> Looking at the eeprom driver, I expect this on the bus:
>>>>
>>>> S 0x50 0x00 "hello there guys" P
>>>> S 0x50 NACK P
>>>> delay for at least 1 ms (since the eeprom driver has a msleep(1) call).
>>>> S 0x50 NACK P
>>>> delay for at least 1 ms
>>>> ...
>>>> ...
>>>> S 0x50 NACK P
>>>> delay for at least 1 ms
>>>> S 0x50 0x10 "and girls\n" P
>>>>
>>>> This is not what I observe on the bus, most of the time there is a
>>>> second NACK immediately following the first. I suspect that it is
>>>> the i2c bus driver that somehow confuses itself and reissues the
>>>> command for some reason?
>>>>
>>>> But this behavior has been there since the beginning, so it's probably
>>>> orthogonal, and killing the data corrupting regression is much more
>>>> important to me than fussing over a surplus failed transfer. Hence
>>>>
>>>> Tested-by: Peter Rosin <peda@lysator.liu.se>
>>>>
>>>> Cheers,
>>>> Peter
>>>>
>>>
>>> Hi Peter,
>>>
>>> sama5d3x and sama5d4x don't support the so called "Alternative Command mode"
>>> whereas sama5d2x do. The Alternative Command mode comes with a new hardware
>>> mechanism inside the I2C controller which locks the transmission of data on
>>> the I2C bus when a NACK is detected. It means that even if a data is written
>>> into the THR, the I2C controller doesn't push this data on the I2C bus but
>>> retains the data in the THR (and its associated FIFO for sama5d2x and future
>>> SoCs) until the driver unlocks the transmitter by writing the LOCKCLR (Lock
>>> Clear) bit in the Control Register. Then and only then, the transmitter outputs
>>> pending data again.
>>> This new mechanism was introduced to cope with an unwanted DMA write into the
>>> THR after a NACK. Indeed, as I've tried to explain in my patch, when a first
>>> NACK is detected, the I2C controller sets the TXCOMP, NACK and TXRDY bits
>>> alltogether in the Status Register. However setting the TXRDY bit also triggers
>>> the DMA controller to write the next data into the THR. Pitifully, WITHOUT the
>>> new lock mechanism, writing into the THR starts a new I2C frame. Since the
>>> eeprom is likely not to be ready yet, it replies by a second NACK. So you
>>> see on the scope two consecutive NACKs.
>>>
>>> On sama5d3x and sama5d4x, which do not support this lock mechanism, you are
>>> likely to see a successful write transfer followed by two NACKs then a delay
>>> and finally a new successful write transfer. This is the case 2b:
>>>
>>> 1 - A successfull write transfer is completed.
>>> 2 - The at24 driver immediately tries to perform the next write transfer...
>>> 3 - ... but the eeprom is not ready yet and replies with a first NACK.
>>> 4 - The I2C controller detects this NACK and sets the NACK, TXCOMP and TXRDY
>>>     bits in its Status Register (and interrupts the CPU).
>>> 5 - The DMA controller is triggered by the TXRDY bit to write the next data
>>>     into the THR.
>>> 6 - WITHTOUT the lock mechanism, the I2C controller starts a new frame because
>>>    of the write into the THR by the DMA controller...
>>> 7 - ... but the eeprom is still not ready and replies with a second NACK.
>>>
>>> 8 - starting from 4, the CPU handles the interrupt generated by the first NACK.
>>>     Depending on the timing, it has already masked the interrupted before the
>>>     second NACK. In such a case, the NACK bit is pending in the Status
>>>     Register. Then it reports the first NACK error to the at24 driver.
>>> 9 - The at24 driver handles the NACK error: it sleeps for a while before
>>>     retrying to perform the write operation.
>>> 10 - With the new patch, the I2C controller reads the Status Register to clear
>>>      pending (NACK) interrupts before actually starting this new (retried)
>>>      transfer.
>>>
>>>
>>> So if you are using DMA transfers on a sama5d3x board, you're are likely to
>>> see, as I did see, a valid write transfer followed by 2 NACKs, then a delay and
>>> finally a new write transfer.
>>> The 2nd NACK is not wanted but expected. Without the lock mechanism, there is
>>> nothing we can do at the I2C controller level. However a workaround may exist:
>>> inserting a small delay after a successful write transfer should give the
>>> eeprom enough time to be ready to process the next write so even the first NACK
>>> would disappear.
>>> This is what I saw while debugging with dev_info() traces. Those traces had the
>>> side effect of inserting delays hence changing the timing.
>>>
>>> As you see, we have to deal with some known hardware design quirks, which are
>>> fixed by the lock mechanism. Without the lock mechanism, the interrupt handler
>>> and the CPU are likely to come too late to cancel the DMA transfer before the
>>> DMA controller writes a new byte into the THR, hence generating an unwanted
>>> frame.
>>
>> Ok, now I get it, I should have been reading the source code comments instead
>> of the commit message. My bad. That 2a) case from the atmel_twi_interrupt comment
>> seems very nasty indeed! Is it clear what will happen if the second frame after
>> the first NACKed frame isn't NACKed too? May that transfer be canceled half way
>> through at a later point, or will it be a complete transfer as specified by the
>> issuing driver? What will be reported to the issuing driver for such an i2c
>> transfer that was first NACKed but then wasn't in the second trailing frame?
>>
> 
> We were discussing about this case and we are worried that it simply
> hangs the transfer wihout sending a stop command. We never get this case
> yet so we keep it in mind but we don't correct it since we are not sure
> of the behavior and on side effects it can introduce. I think the
> i2c-at91 driver will return a spurious error to the eeprom driver but it won't
> let the physical i2c bus in a proper state.

I have started to get this when I run with this patch:

[   73.310000] at91_i2c f0014000.i2c: RXRDY still set!
[  198.200000] at91_i2c f0014000.i2c: RXRDY still set!
[  509.880000] at91_i2c f0014000.i2c: RXRDY still set!
[  615.750000] at91_i2c f0014000.i2c: RXRDY still set!
[  617.750000] at91_i2c f0014000.i2c: RXRDY still set!
[ 1766.640000] at91_i2c f0014000.i2c: RXRDY still set!
[ 2035.380000] at91_i2c f0014000.i2c: RXRDY still set!
[ 2227.190000] at91_i2c f0014000.i2c: RXRDY still set!
[ 2313.100000] at91_i2c f0014000.i2c: RXRDY still set!

My USB serial dongle was hung which was why I didn't notice until just now.

This is probably not when communication with the eeprom though, and certainly not
writing to it, but perhpaps when polling the temperature (using the jc42 driver).
I'll investigate further in the morning to see if I can pinpoint it.

Cheers,
Peter

--
To unsubscribe from this list: send the line "unsubscribe linux-i2c" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Peter Rosin Oct. 16, 2015, 9:08 a.m. UTC | #6
On 2015-10-16 01:47, Peter Rosin wrote:
> On 2015-10-14 07:43, Ludovic Desroches wrote:
>> On Tue, Oct 13, 2015 at 08:01:34PM +0200, Peter Rosin wrote:
>>> On 2015-10-13 18:47, Cyrille Pitchen wrote:
>>>> Le 13/10/2015 17:19, Peter Rosin a écrit :
>>>>> On 2015-10-13 16:21, Ludovic Desroches wrote:
>>>>>> From: Cyrille Pitchen <cyrille.pitchen@atmel.com>
>>>>>>
>>>>>> In some cases a NACK interrupt may be pending in the Status Register (SR)
>>>>>> as a result of a previous transfer. However at91_do_twi_transfer() did not
>>>>>> read the SR to clear pending interruptions before starting a new transfer.
>>>>>> Hence a NACK interrupt rose as soon as it was enabled again at the I2C
>>>>>> controller level, resulting in a wrong sequence of operations and strange
>>>>>> patterns of behaviour on the I2C bus, such as a clock stretch followed by
>>>>>> a restart of the transfer.
>>>>>>
>>>>>> This first issue occurred with both DMA and PIO write transfers.
>>>>>>
>>>>>> Also when a NACK error was detected during a PIO write transfer, the
>>>>>> interrupt handler used to wrongly start a new transfer by writing into the
>>>>>> Transmit Holding Register (THR). Then the I2C slave was likely to reply
>>>>>> with a second NACK.
>>>>>>
>>>>>> This second issue is fixed in atmel_twi_interrupt() by handling the TXRDY
>>>>>> status bit only if both the TXCOMP and NACK status bits are cleared.
>>>>>>
>>>>>> Tested with a at24 eeprom on sama5d36ek board running a linux-4.1-at91
>>>>>> kernel image. Adapted to linux-next.
>>>>>>
>>>>>> Signed-off-by: Cyrille Pitchen <cyrille.pitchen@atmel.com>
>>>>>> Fixes: 93563a6a71bb ("i2c: at91: fix a race condition when using the DMA controller")
>>>>>> Reported-by: Peter Rosin <peda@lysator.liu.se>
>>>>>> Signed-off-by: Ludovic Desroches <ludovic.desroches@atmel.com>
>>>>>> Cc: stable@vger.kernel.org #4.1
>>>>>
>>>>> The regression is gone with this patch (vanilla 4.2), thank you!
>>>>>
>>>>> However, looking at the bus, there are two NACKs after each
>>>>> successful chunk of memory written by the eeprom driver.
>>>>>
>>>>> Looking at the eeprom driver, I expect this on the bus:
>>>>>
>>>>> S 0x50 0x00 "hello there guys" P
>>>>> S 0x50 NACK P
>>>>> delay for at least 1 ms (since the eeprom driver has a msleep(1) call).
>>>>> S 0x50 NACK P
>>>>> delay for at least 1 ms
>>>>> ...
>>>>> ...
>>>>> S 0x50 NACK P
>>>>> delay for at least 1 ms
>>>>> S 0x50 0x10 "and girls\n" P
>>>>>
>>>>> This is not what I observe on the bus, most of the time there is a
>>>>> second NACK immediately following the first. I suspect that it is
>>>>> the i2c bus driver that somehow confuses itself and reissues the
>>>>> command for some reason?
>>>>>
>>>>> But this behavior has been there since the beginning, so it's probably
>>>>> orthogonal, and killing the data corrupting regression is much more
>>>>> important to me than fussing over a surplus failed transfer. Hence
>>>>>
>>>>> Tested-by: Peter Rosin <peda@lysator.liu.se>
>>>>>
>>>>> Cheers,
>>>>> Peter
>>>>>
>>>>
>>>> Hi Peter,
>>>>
>>>> sama5d3x and sama5d4x don't support the so called "Alternative Command mode"
>>>> whereas sama5d2x do. The Alternative Command mode comes with a new hardware
>>>> mechanism inside the I2C controller which locks the transmission of data on
>>>> the I2C bus when a NACK is detected. It means that even if a data is written
>>>> into the THR, the I2C controller doesn't push this data on the I2C bus but
>>>> retains the data in the THR (and its associated FIFO for sama5d2x and future
>>>> SoCs) until the driver unlocks the transmitter by writing the LOCKCLR (Lock
>>>> Clear) bit in the Control Register. Then and only then, the transmitter outputs
>>>> pending data again.
>>>> This new mechanism was introduced to cope with an unwanted DMA write into the
>>>> THR after a NACK. Indeed, as I've tried to explain in my patch, when a first
>>>> NACK is detected, the I2C controller sets the TXCOMP, NACK and TXRDY bits
>>>> alltogether in the Status Register. However setting the TXRDY bit also triggers
>>>> the DMA controller to write the next data into the THR. Pitifully, WITHOUT the
>>>> new lock mechanism, writing into the THR starts a new I2C frame. Since the
>>>> eeprom is likely not to be ready yet, it replies by a second NACK. So you
>>>> see on the scope two consecutive NACKs.
>>>>
>>>> On sama5d3x and sama5d4x, which do not support this lock mechanism, you are
>>>> likely to see a successful write transfer followed by two NACKs then a delay
>>>> and finally a new successful write transfer. This is the case 2b:
>>>>
>>>> 1 - A successfull write transfer is completed.
>>>> 2 - The at24 driver immediately tries to perform the next write transfer...
>>>> 3 - ... but the eeprom is not ready yet and replies with a first NACK.
>>>> 4 - The I2C controller detects this NACK and sets the NACK, TXCOMP and TXRDY
>>>>     bits in its Status Register (and interrupts the CPU).
>>>> 5 - The DMA controller is triggered by the TXRDY bit to write the next data
>>>>     into the THR.
>>>> 6 - WITHTOUT the lock mechanism, the I2C controller starts a new frame because
>>>>    of the write into the THR by the DMA controller...
>>>> 7 - ... but the eeprom is still not ready and replies with a second NACK.
>>>>
>>>> 8 - starting from 4, the CPU handles the interrupt generated by the first NACK.
>>>>     Depending on the timing, it has already masked the interrupted before the
>>>>     second NACK. In such a case, the NACK bit is pending in the Status
>>>>     Register. Then it reports the first NACK error to the at24 driver.
>>>> 9 - The at24 driver handles the NACK error: it sleeps for a while before
>>>>     retrying to perform the write operation.
>>>> 10 - With the new patch, the I2C controller reads the Status Register to clear
>>>>      pending (NACK) interrupts before actually starting this new (retried)
>>>>      transfer.
>>>>
>>>>
>>>> So if you are using DMA transfers on a sama5d3x board, you're are likely to
>>>> see, as I did see, a valid write transfer followed by 2 NACKs, then a delay and
>>>> finally a new write transfer.
>>>> The 2nd NACK is not wanted but expected. Without the lock mechanism, there is
>>>> nothing we can do at the I2C controller level. However a workaround may exist:
>>>> inserting a small delay after a successful write transfer should give the
>>>> eeprom enough time to be ready to process the next write so even the first NACK
>>>> would disappear.
>>>> This is what I saw while debugging with dev_info() traces. Those traces had the
>>>> side effect of inserting delays hence changing the timing.
>>>>
>>>> As you see, we have to deal with some known hardware design quirks, which are
>>>> fixed by the lock mechanism. Without the lock mechanism, the interrupt handler
>>>> and the CPU are likely to come too late to cancel the DMA transfer before the
>>>> DMA controller writes a new byte into the THR, hence generating an unwanted
>>>> frame.
>>>
>>> Ok, now I get it, I should have been reading the source code comments instead
>>> of the commit message. My bad. That 2a) case from the atmel_twi_interrupt comment
>>> seems very nasty indeed! Is it clear what will happen if the second frame after
>>> the first NACKed frame isn't NACKed too? May that transfer be canceled half way
>>> through at a later point, or will it be a complete transfer as specified by the
>>> issuing driver? What will be reported to the issuing driver for such an i2c
>>> transfer that was first NACKed but then wasn't in the second trailing frame?
>>>
>>
>> We were discussing about this case and we are worried that it simply
>> hangs the transfer wihout sending a stop command. We never get this case
>> yet so we keep it in mind but we don't correct it since we are not sure
>> of the behavior and on side effects it can introduce. I think the
>> i2c-at91 driver will return a spurious error to the eeprom driver but it won't
>> let the physical i2c bus in a proper state.
> 
> I have started to get this when I run with this patch:
> 
> [   73.310000] at91_i2c f0014000.i2c: RXRDY still set!
> [  198.200000] at91_i2c f0014000.i2c: RXRDY still set!
> [  509.880000] at91_i2c f0014000.i2c: RXRDY still set!
> [  615.750000] at91_i2c f0014000.i2c: RXRDY still set!
> [  617.750000] at91_i2c f0014000.i2c: RXRDY still set!
> [ 1766.640000] at91_i2c f0014000.i2c: RXRDY still set!
> [ 2035.380000] at91_i2c f0014000.i2c: RXRDY still set!
> [ 2227.190000] at91_i2c f0014000.i2c: RXRDY still set!
> [ 2313.100000] at91_i2c f0014000.i2c: RXRDY still set!
> 
> My USB serial dongle was hung which was why I didn't notice until just now.
> 
> This is probably not when communication with the eeprom though, and certainly not
> writing to it, but perhpaps when polling the temperature (using the jc42 driver).
> I'll investigate further in the morning to see if I can pinpoint it.

Yep, it's the jc42 accesses that triggers this (to the same chip as the
eeprom, but a different block of transistors I suppose).

Looking at the i2c bus, the accesses normally go like this:

[0.000000] S 0x18 W 0x05 S 0x18 R 0xc1 0xbe NACK P
[0.000521] S 0x18 W 0x04 S 0x18 R 0x00 0x00 NACK P
[0.001024] S 0x18 W 0x03 S 0x18 R 0x00 0x00 NACK P
[0.001524] S 0x18 W 0x02 S 0x18 R 0x00 0x00 NACK P
[0.196991] S 0x18 W 0x05 S 0x18 R 0xc1 0xbe NACK P
[0.197514] S 0x18 W 0x04 S 0x18 R 0x00 0x00 NACK P
[0.198019] S 0x18 W 0x03 S 0x18 R 0x00 0x00 NACK P
[0.198520] S 0x18 W 0x02 S 0x18 R 0x00 0x00 NACK P

I.e. chunks of four transfers every ~200 ms (I removed the 1Hz rate
limiter in the jc42 driver to get more frequent incidents).

But when the diagnostic (RXRDY still set!) is output it continues
with this:

[0.399755] S 0x18 W 0x05 S 0x18 R 0xc1 0xbe NACK P
[0.404998] S 0x18 W 0x04 S 0x18 R 0x00 0x00 NACK P
[0.405508] S 0x18 W 0x03 S 0x18 R 0x00 0x00 NACK P
[0.406008] S 0x18 W 0x02 S 0x18 R 0x00 0x00 NACK P

Notice the ~5 ms delay (about the time it should take to output
the diagnostic at 115200 baud) after the access to register 0x05
at 0.399755.

This is the only thing that I can observe on the bus, so it appears
to be harmless.

It appears that the i2c access at 0.399755 finds the TWI
registers in an odd state, but nothing from the access at
0.198520 appears to have gone wrong. Is this a race? Anyway,
the diagnostic is pretty frequent and annoying. printk_once?

Cheers,
Peter

--
To unsubscribe from this list: send the line "unsubscribe linux-i2c" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
ludovic.desroches@atmel.com Oct. 19, 2015, 8:51 a.m. UTC | #7
Hi Peter,

On Fri, Oct 16, 2015 at 11:08:42AM +0200, Peter Rosin wrote:
> On 2015-10-16 01:47, Peter Rosin wrote:
> > On 2015-10-14 07:43, Ludovic Desroches wrote:
> >> On Tue, Oct 13, 2015 at 08:01:34PM +0200, Peter Rosin wrote:
> >>> On 2015-10-13 18:47, Cyrille Pitchen wrote:
> >>>> Le 13/10/2015 17:19, Peter Rosin a écrit :
> >>>>> On 2015-10-13 16:21, Ludovic Desroches wrote:

[...]

> > I have started to get this when I run with this patch:
> > 
> > [   73.310000] at91_i2c f0014000.i2c: RXRDY still set!
> > [  198.200000] at91_i2c f0014000.i2c: RXRDY still set!
> > [  509.880000] at91_i2c f0014000.i2c: RXRDY still set!
> > [  615.750000] at91_i2c f0014000.i2c: RXRDY still set!
> > [  617.750000] at91_i2c f0014000.i2c: RXRDY still set!
> > [ 1766.640000] at91_i2c f0014000.i2c: RXRDY still set!
> > [ 2035.380000] at91_i2c f0014000.i2c: RXRDY still set!
> > [ 2227.190000] at91_i2c f0014000.i2c: RXRDY still set!
> > [ 2313.100000] at91_i2c f0014000.i2c: RXRDY still set!
> > 
> > My USB serial dongle was hung which was why I didn't notice until just now.
> > 
> > This is probably not when communication with the eeprom though, and certainly not
> > writing to it, but perhpaps when polling the temperature (using the jc42 driver).
> > I'll investigate further in the morning to see if I can pinpoint it.
> 
> Yep, it's the jc42 accesses that triggers this (to the same chip as the
> eeprom, but a different block of transistors I suppose).
> 
> Looking at the i2c bus, the accesses normally go like this:
> 
> [0.000000] S 0x18 W 0x05 S 0x18 R 0xc1 0xbe NACK P
> [0.000521] S 0x18 W 0x04 S 0x18 R 0x00 0x00 NACK P
> [0.001024] S 0x18 W 0x03 S 0x18 R 0x00 0x00 NACK P
> [0.001524] S 0x18 W 0x02 S 0x18 R 0x00 0x00 NACK P
> [0.196991] S 0x18 W 0x05 S 0x18 R 0xc1 0xbe NACK P
> [0.197514] S 0x18 W 0x04 S 0x18 R 0x00 0x00 NACK P
> [0.198019] S 0x18 W 0x03 S 0x18 R 0x00 0x00 NACK P
> [0.198520] S 0x18 W 0x02 S 0x18 R 0x00 0x00 NACK P
> 
> I.e. chunks of four transfers every ~200 ms (I removed the 1Hz rate
> limiter in the jc42 driver to get more frequent incidents).
> 
> But when the diagnostic (RXRDY still set!) is output it continues
> with this:
> 
> [0.399755] S 0x18 W 0x05 S 0x18 R 0xc1 0xbe NACK P
> [0.404998] S 0x18 W 0x04 S 0x18 R 0x00 0x00 NACK P
> [0.405508] S 0x18 W 0x03 S 0x18 R 0x00 0x00 NACK P
> [0.406008] S 0x18 W 0x02 S 0x18 R 0x00 0x00 NACK P
> 
> Notice the ~5 ms delay (about the time it should take to output
> the diagnostic at 115200 baud) after the access to register 0x05
> at 0.399755.
> 
> This is the only thing that I can observe on the bus, so it appears
> to be harmless.
> 
> It appears that the i2c access at 0.399755 finds the TWI
> registers in an odd state, but nothing from the access at
> 0.198520 appears to have gone wrong. Is this a race? Anyway,
> the diagnostic is pretty frequent and annoying. printk_once?

I'll try to reproduce it on my side. The only issue you have is having
the message about RXRDY? I mean no issue with i2c transfers?

It is not the possible bug we had in mind, this bug will prevent the
master device to release the i2c bus. It will stop the transfer but
without sending a stop on the bus.

Regards

Ludovic
--
To unsubscribe from this list: send the line "unsubscribe linux-i2c" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Peter Rosin Oct. 19, 2015, 10:49 a.m. UTC | #8
On 2015-10-19 10:51, Ludovic Desroches wrote:
> Hi Peter,
> 
> On Fri, Oct 16, 2015 at 11:08:42AM +0200, Peter Rosin wrote:
>> On 2015-10-16 01:47, Peter Rosin wrote:
>>> On 2015-10-14 07:43, Ludovic Desroches wrote:
>>>> On Tue, Oct 13, 2015 at 08:01:34PM +0200, Peter Rosin wrote:
>>>>> On 2015-10-13 18:47, Cyrille Pitchen wrote:
>>>>>> Le 13/10/2015 17:19, Peter Rosin a écrit :
>>>>>>> On 2015-10-13 16:21, Ludovic Desroches wrote:
> 
> [...]
> 
>>> I have started to get this when I run with this patch:
>>>
>>> [   73.310000] at91_i2c f0014000.i2c: RXRDY still set!
>>> [  198.200000] at91_i2c f0014000.i2c: RXRDY still set!
>>> [  509.880000] at91_i2c f0014000.i2c: RXRDY still set!
>>> [  615.750000] at91_i2c f0014000.i2c: RXRDY still set!
>>> [  617.750000] at91_i2c f0014000.i2c: RXRDY still set!
>>> [ 1766.640000] at91_i2c f0014000.i2c: RXRDY still set!
>>> [ 2035.380000] at91_i2c f0014000.i2c: RXRDY still set!
>>> [ 2227.190000] at91_i2c f0014000.i2c: RXRDY still set!
>>> [ 2313.100000] at91_i2c f0014000.i2c: RXRDY still set!
>>>
>>> My USB serial dongle was hung which was why I didn't notice until just now.
>>>
>>> This is probably not when communication with the eeprom though, and certainly not
>>> writing to it, but perhpaps when polling the temperature (using the jc42 driver).
>>> I'll investigate further in the morning to see if I can pinpoint it.
>>
>> Yep, it's the jc42 accesses that triggers this (to the same chip as the
>> eeprom, but a different block of transistors I suppose).
>>
>> Looking at the i2c bus, the accesses normally go like this:
>>
>> [0.000000] S 0x18 W 0x05 S 0x18 R 0xc1 0xbe NACK P
>> [0.000521] S 0x18 W 0x04 S 0x18 R 0x00 0x00 NACK P
>> [0.001024] S 0x18 W 0x03 S 0x18 R 0x00 0x00 NACK P
>> [0.001524] S 0x18 W 0x02 S 0x18 R 0x00 0x00 NACK P
>> [0.196991] S 0x18 W 0x05 S 0x18 R 0xc1 0xbe NACK P
>> [0.197514] S 0x18 W 0x04 S 0x18 R 0x00 0x00 NACK P
>> [0.198019] S 0x18 W 0x03 S 0x18 R 0x00 0x00 NACK P
>> [0.198520] S 0x18 W 0x02 S 0x18 R 0x00 0x00 NACK P
>>
>> I.e. chunks of four transfers every ~200 ms (I removed the 1Hz rate
>> limiter in the jc42 driver to get more frequent incidents).
>>
>> But when the diagnostic (RXRDY still set!) is output it continues
>> with this:
>>
>> [0.399755] S 0x18 W 0x05 S 0x18 R 0xc1 0xbe NACK P
>> [0.404998] S 0x18 W 0x04 S 0x18 R 0x00 0x00 NACK P
>> [0.405508] S 0x18 W 0x03 S 0x18 R 0x00 0x00 NACK P
>> [0.406008] S 0x18 W 0x02 S 0x18 R 0x00 0x00 NACK P
>>
>> Notice the ~5 ms delay (about the time it should take to output
>> the diagnostic at 115200 baud) after the access to register 0x05
>> at 0.399755.
>>
>> This is the only thing that I can observe on the bus, so it appears
>> to be harmless.
>>
>> It appears that the i2c access at 0.399755 finds the TWI
>> registers in an odd state, but nothing from the access at
>> 0.198520 appears to have gone wrong. Is this a race? Anyway,
>> the diagnostic is pretty frequent and annoying. printk_once?
> 
> I'll try to reproduce it on my side. The only issue you have is having
> the message about RXRDY? I mean no issue with i2c transfers?

Exactly, the only issue is the message, the bus looks good and transfers
work as they should AFAICT.

> It is not the possible bug we had in mind, this bug will prevent the
> master device to release the i2c bus. It will stop the transfer but
> without sending a stop on the bus.

Agreed, this is not about the extra frame caused by the spurious write
to the THR register. This is something else.

One suspicion is that the driver gets an unexpected irq from its own
NACK (the one that it puts out to end the read) and races with the
expected interrupt at TXCOMP?

Cheers,
Peter

--
To unsubscribe from this list: send the line "unsubscribe linux-i2c" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Patch
diff mbox

diff --git a/drivers/i2c/busses/i2c-at91.c b/drivers/i2c/busses/i2c-at91.c
index 1c758cd..94c087b 100644
--- a/drivers/i2c/busses/i2c-at91.c
+++ b/drivers/i2c/busses/i2c-at91.c
@@ -465,19 +465,57 @@  static irqreturn_t atmel_twi_interrupt(int irq, void *dev_id)
 
 	if (!irqstatus)
 		return IRQ_NONE;
-	else if (irqstatus & AT91_TWI_RXRDY)
-		at91_twi_read_next_byte(dev);
-	else if (irqstatus & AT91_TWI_TXRDY)
-		at91_twi_write_next_byte(dev);
-
-	/* catch error flags */
-	dev->transfer_status |= status;
 
+	/*
+	 * When a NACK condition is detected, the I2C controller sets the NACK,
+	 * TXCOMP and TXRDY bits all together in the Status Register (SR).
+	 *
+	 * 1 - Handling NACK errors with CPU write transfer.
+	 *
+	 * In such case, we should not write the next byte into the Transmit
+	 * Holding Register (THR) otherwise the I2C controller would start a new
+	 * transfer and the I2C slave is likely to reply by another NACK.
+	 *
+	 * 2 - Handling NACK errors with DMA write transfer.
+	 *
+	 * By setting the TXRDY bit in the SR, the I2C controller also triggers
+	 * the DMA controller to write the next data into the THR. Then the
+	 * result depends on the hardware version of the I2C controller.
+	 *
+	 * 2a - Without support of the Alternative Command mode.
+	 *
+	 * This is the worst case: the DMA controller is triggered to write the
+	 * next data into the THR, hence starting a new transfer: the I2C slave
+	 * is likely to reply by another NACK.
+	 * Concurrently, this interrupt handler is likely to be called to manage
+	 * the first NACK before the I2C controller detects the second NACK and
+	 * sets once again the NACK bit into the SR.
+	 * When handling the first NACK, this interrupt handler disables the I2C
+	 * controller interruptions, especially the NACK interrupt.
+	 * Hence, the NACK bit is pending into the SR. This is why we should
+	 * read the SR to clear all pending interrupts at the beginning of
+	 * at91_do_twi_transfer() before actually starting a new transfer.
+	 *
+	 * 2b - With support of the Alternative Command mode.
+	 *
+	 * When a NACK condition is detected, the I2C controller also locks the
+	 * THR (and sets the LOCK bit in the SR): even though the DMA controller
+	 * is triggered by the TXRDY bit to write the next data into the THR,
+	 * this data actually won't go on the I2C bus hence a second NACK is not
+	 * generated.
+	 */
 	if (irqstatus & (AT91_TWI_TXCOMP | AT91_TWI_NACK)) {
 		at91_disable_twi_interrupts(dev);
 		complete(&dev->cmd_complete);
+	} else if (irqstatus & AT91_TWI_RXRDY) {
+		at91_twi_read_next_byte(dev);
+	} else if (irqstatus & AT91_TWI_TXRDY) {
+		at91_twi_write_next_byte(dev);
 	}
 
+	/* catch error flags */
+	dev->transfer_status |= status;
+
 	return IRQ_HANDLED;
 }
 
@@ -487,6 +525,7 @@  static int at91_do_twi_transfer(struct at91_twi_dev *dev)
 	unsigned long time_left;
 	bool has_unre_flag = dev->pdata->has_unre_flag;
 	bool has_alt_cmd = dev->pdata->has_alt_cmd;
+	unsigned sr;
 
 	/*
 	 * WARNING: the TXCOMP bit in the Status Register is NOT a clear on
@@ -537,6 +576,9 @@  static int at91_do_twi_transfer(struct at91_twi_dev *dev)
 	reinit_completion(&dev->cmd_complete);
 	dev->transfer_status = 0;
 
+	/* Clear pending interrupts, such as NACK. */
+	sr = at91_twi_read(dev, AT91_TWI_SR);
+
 	if (dev->fifo_size) {
 		unsigned fifo_mr = at91_twi_read(dev, AT91_TWI_FMR);
 
@@ -558,7 +600,7 @@  static int at91_do_twi_transfer(struct at91_twi_dev *dev)
 	} else if (dev->msg->flags & I2C_M_RD) {
 		unsigned start_flags = AT91_TWI_START;
 
-		if (at91_twi_read(dev, AT91_TWI_SR) & AT91_TWI_RXRDY) {
+		if (sr & AT91_TWI_RXRDY) {
 			dev_err(dev->dev, "RXRDY still set!");
 			at91_twi_read(dev, AT91_TWI_RHR);
 		}