diff mbox

OMAP baseline test results for v3.8-rc3

Message ID 20130114191459.GA9402@arwen.pp.htv.fi (mailing list archive)
State New, archived
Headers show

Pull-request

git://git.kernel.org/pub/scm/linux/kernel/git/balbi/usb.git i2c-deferred-STP

Commit Message

Felipe Balbi Jan. 14, 2013, 7:14 p.m. UTC 
Hi,

On Mon, Jan 14, 2013 at 08:40:18PM +0200, Aaro Koskinen wrote:
> On Mon, Jan 14, 2013 at 05:59:12PM +0000, Paul Walmsley wrote:
> > Here are some basic OMAP test results for Linux v3.8-rc3.
> > Logs and other details at:
> > 
> >     http://www.pwsan.com/omap/testlogs/test_v3.8-rc3/20130109222058/
> > 
> > 
> > Test summary
> > ------------
> > 
> > Boot to userspace:
> >     Pass ( 9/11): 2420n800, 2430sdp, 3517evm, 3530es3beagle,
> >   	   	  3730beaglexm, 37xxevm, 4430es2panda, 5912osk,
> > 		  4460pandaes
> >     FAIL ( 2/11): am335xbone, cmt3517 
> 
> N900 boot is unstable again, I2C issues are back.

damn!

> Boot succeeds and fails randomly. Let's see if this can be bisected.
> The same kernel works on N950.

fair enough, it might be something related to some errata fix which
might have been missed. Can you apply this small patch just so I know if
there is something pending in CNT reg ?



you might also want to try merging my latest i2c patches, which missed
the merge window, as they might help with this issue too.

The following changes since commit 9931faca02c604c22335f5a935a501bb2ace6e20:

  Linux 3.8-rc3 (2013-01-09 18:59:55 -0800)

are available in the git repository at:

  git://git.kernel.org/pub/scm/linux/kernel/git/balbi/usb.git i2c-deferred-STP

for you to fetch changes up to a7b1b41b270be84f6bf6e7d3654d74c873b3daf8:

  i2c: omap: get rid of b_hw flag (2013-01-14 21:04:16 +0200)

----------------------------------------------------------------
Felipe Balbi (6):
      i2c: omap: no need to access platform_device
      i2c: omap: also complete() when stat becomes zero
      i2c: omap: improve 'rev' a little bit
      i2c: omap: in case of VERSION_2 read IRQSTATUS_RAW but write to IRQSTATUS
      i2c: omap: wait for transfer completion before sending STP bit
      i2c: omap: get rid of b_hw flag

 drivers/i2c/busses/i2c-omap.c | 184 +++++++++++++++++++++---------------------
 1 file changed, 93 insertions(+), 91 deletions(-)

Comments

Aaro Koskinen Jan. 14, 2013, 8:46 p.m. UTC | #1 
On Mon, Jan 14, 2013 at 09:14:59PM +0200, Felipe Balbi wrote:
> On Mon, Jan 14, 2013 at 08:40:18PM +0200, Aaro Koskinen wrote:
> > On Mon, Jan 14, 2013 at 05:59:12PM +0000, Paul Walmsley wrote:
> > > Here are some basic OMAP test results for Linux v3.8-rc3.
> > > Logs and other details at:
> > > 
> > >     http://www.pwsan.com/omap/testlogs/test_v3.8-rc3/20130109222058/
> > > 
> > > 
> > > Test summary
> > > ------------
> > > 
> > > Boot to userspace:
> > >     Pass ( 9/11): 2420n800, 2430sdp, 3517evm, 3530es3beagle,
> > >   	   	  3730beaglexm, 37xxevm, 4430es2panda, 5912osk,
> > > 		  4460pandaes
> > >     FAIL ( 2/11): am335xbone, cmt3517 
> > 
> > N900 boot is unstable again, I2C issues are back.
> 
> damn!
> 
> > Boot succeeds and fails randomly. Let's see if this can be bisected.
> > The same kernel works on N950.
> 
> fair enough, it might be something related to some errata fix which
> might have been missed. Can you apply this small patch just so I know if
> there is something pending in CNT reg ?

[    0.207946] twl 1-0048: PIH (irq 23) chaining IRQs 338..346
[    0.208129] twl 1-0048: power (irq 343) chaining IRQs 346..353
[    0.209350] twl4030_gpio twl4030_gpio: gpio (irq 338) chaining IRQs 354..371
[    1.218749] omap_i2c omap_i2c.1: timeout waiting for bus ready
[    1.218811] omap_i2c omap_i2c.1: SA 0049 CON 9602 CNT 0004
[    2.234374] omap_i2c omap_i2c.1: timeout waiting for bus ready
[    2.234436] omap_i2c omap_i2c.1: SA 0049 CON 9602 CNT 0004
[    2.234466] twl: Write failed (mod 2, reg 0x12 count 1)
[    3.249999] omap_i2c omap_i2c.1: timeout waiting for bus ready
[    3.250030] omap_i2c omap_i2c.1: SA 0049 CON 9602 CNT 0004
[    3.250061] twl: Write failed (mod 2, reg 0x12 count 1)

> you might also want to try merging my latest i2c patches, which missed
> the merge window, as they might help with this issue too.
> 
> The following changes since commit 9931faca02c604c22335f5a935a501bb2ace6e20:
> 
>   Linux 3.8-rc3 (2013-01-09 18:59:55 -0800)
> 
> are available in the git repository at:
> 
>   git://git.kernel.org/pub/scm/linux/kernel/git/balbi/usb.git i2c-deferred-STP

I could not reproduce the issue with these. Tested around 20 boots.
There's a noticeable delay (over 4 secs!) around where I2C is initialized
and used for the first time, but no errors and the boot completes:

[    0.187530] SCSI subsystem initialized
[    0.188110] usbcore: registered new interface driver usbfs
[    0.188415] usbcore: registered new interface driver hub
[    0.188781] usbcore: registered new device driver usb
[    0.189453] musb-omap2430 musb-omap2430: invalid resource
[    4.296905] twl 1-0048: PIH (irq 23) chaining IRQs 338..346
[    4.297088] twl 1-0048: power (irq 343) chaining IRQs 346..353
[    4.329010] twl4030_gpio twl4030_gpio: gpio (irq 338) chaining IRQs 354..371
[    4.470123] VUSB1V5: 1500 mV normal standby
[    4.470916] VUSB1V8: 1800 mV normal standby

A.
Felipe Balbi Jan. 14, 2013, 9:18 p.m. UTC | #2 
Hi,

On Mon, Jan 14, 2013 at 10:46:54PM +0200, Aaro Koskinen wrote:
> On Mon, Jan 14, 2013 at 09:14:59PM +0200, Felipe Balbi wrote:
> > On Mon, Jan 14, 2013 at 08:40:18PM +0200, Aaro Koskinen wrote:
> > > On Mon, Jan 14, 2013 at 05:59:12PM +0000, Paul Walmsley wrote:
> > > > Here are some basic OMAP test results for Linux v3.8-rc3.
> > > > Logs and other details at:
> > > > 
> > > >     http://www.pwsan.com/omap/testlogs/test_v3.8-rc3/20130109222058/
> > > > 
> > > > 
> > > > Test summary
> > > > ------------
> > > > 
> > > > Boot to userspace:
> > > >     Pass ( 9/11): 2420n800, 2430sdp, 3517evm, 3530es3beagle,
> > > >   	   	  3730beaglexm, 37xxevm, 4430es2panda, 5912osk,
> > > > 		  4460pandaes
> > > >     FAIL ( 2/11): am335xbone, cmt3517 
> > > 
> > > N900 boot is unstable again, I2C issues are back.
> > 
> > damn!
> > 
> > > Boot succeeds and fails randomly. Let's see if this can be bisected.
> > > The same kernel works on N950.
> > 
> > fair enough, it might be something related to some errata fix which
> > might have been missed. Can you apply this small patch just so I know if
> > there is something pending in CNT reg ?
> 
> [    0.207946] twl 1-0048: PIH (irq 23) chaining IRQs 338..346
> [    0.208129] twl 1-0048: power (irq 343) chaining IRQs 346..353
> [    0.209350] twl4030_gpio twl4030_gpio: gpio (irq 338) chaining IRQs 354..371
> [    1.218749] omap_i2c omap_i2c.1: timeout waiting for bus ready
> [    1.218811] omap_i2c omap_i2c.1: SA 0049 CON 9602 CNT 0004

here's the issue, there is unloaded data in the FIFO. Can you enable
full I2C debugging logs ?

> > you might also want to try merging my latest i2c patches, which missed
> > the merge window, as they might help with this issue too.
> > 
> > The following changes since commit 9931faca02c604c22335f5a935a501bb2ace6e20:
> > 
> >   Linux 3.8-rc3 (2013-01-09 18:59:55 -0800)
> > 
> > are available in the git repository at:
> > 
> >   git://git.kernel.org/pub/scm/linux/kernel/git/balbi/usb.git i2c-deferred-STP
> 
> I could not reproduce the issue with these. Tested around 20 boots.
> There's a noticeable delay (over 4 secs!) around where I2C is initialized
> and used for the first time, but no errors and the boot completes:
> 
> [    0.187530] SCSI subsystem initialized
> [    0.188110] usbcore: registered new interface driver usbfs
> [    0.188415] usbcore: registered new interface driver hub
> [    0.188781] usbcore: registered new device driver usb
> [    0.189453] musb-omap2430 musb-omap2430: invalid resource
> [    4.296905] twl 1-0048: PIH (irq 23) chaining IRQs 338..346
> [    4.297088] twl 1-0048: power (irq 343) chaining IRQs 346..353
> [    4.329010] twl4030_gpio twl4030_gpio: gpio (irq 338) chaining IRQs 354..371
> [    4.470123] VUSB1V5: 1500 mV normal standby
> [    4.470916] VUSB1V8: 1800 mV normal standby

cool, at least it works, but looks like there is something still weird
going on. Can you enable full logs so I see what's happening ?

cheers
Aaro Koskinen Jan. 14, 2013, 10:42 p.m. UTC | #3 
On Mon, Jan 14, 2013 at 11:18:46PM +0200, Felipe Balbi wrote:
> On Mon, Jan 14, 2013 at 10:46:54PM +0200, Aaro Koskinen wrote:
> > [    0.207946] twl 1-0048: PIH (irq 23) chaining IRQs 338..346
> > [    0.208129] twl 1-0048: power (irq 343) chaining IRQs 346..353
> > [    0.209350] twl4030_gpio twl4030_gpio: gpio (irq 338) chaining IRQs 354..371
> > [    1.218749] omap_i2c omap_i2c.1: timeout waiting for bus ready
> > [    1.218811] omap_i2c omap_i2c.1: SA 0049 CON 9602 CNT 0004
> 
> here's the issue, there is unloaded data in the FIFO. Can you enable
> full I2C debugging logs ?

If I enable I2C DEBUGs, the problem is not reproducible. Everything
looks normal:

[    0.270141] twl 1-0048: PIH (irq 23) chaining IRQs 338..346
[    0.270294] twl 1-0048: power (irq 343) chaining IRQs 346..353
[    0.270477] i2c i2c-1: master_xfer[0] W, addr=0x49, len=1
[    0.270538] i2c i2c-1: master_xfer[1] R, addr=0x49, len=1
[    0.270568] omap_i2c omap_i2c.1: addr: 0x0049, len: 1, flags: 0x0, stop: 0
[    0.270629] omap_i2c omap_i2c.1: IRQ (ISR = 0x0010)
[    0.270690] omap_i2c omap_i2c.1: IRQ (ISR = 0x0004)
[    0.270751] omap_i2c omap_i2c.1: addr: 0x0049, len: 1, flags: 0x1, stop: 1
[    0.270843] omap_i2c omap_i2c.1: IRQ (ISR = 0x0008)
[    0.270874] omap_i2c omap_i2c.1: IRQ (ISR = 0x0004)
[    0.270935] i2c i2c-1: master_xfer[0] W, addr=0x49, len=2
[    0.270965] omap_i2c omap_i2c.1: addr: 0x0049, len: 2, flags: 0x0, stop: 1
[    0.271026] omap_i2c omap_i2c.1: IRQ (ISR = 0x0010)
[    0.271118] omap_i2c omap_i2c.1: IRQ (ISR = 0x0004)
[    0.272155] twl4030_gpio twl4030_gpio: gpio (irq 338) chaining IRQs 354..371

> > >   git://git.kernel.org/pub/scm/linux/kernel/git/balbi/usb.git i2c-deferred-STP
> > 
> > I could not reproduce the issue with these. Tested around 20 boots.
> > There's a noticeable delay (over 4 secs!) around where I2C is initialized
> > and used for the first time, but no errors and the boot completes:
> > 
> > [    0.187530] SCSI subsystem initialized
> > [    0.188110] usbcore: registered new interface driver usbfs
> > [    0.188415] usbcore: registered new interface driver hub
> > [    0.188781] usbcore: registered new device driver usb
> > [    0.189453] musb-omap2430 musb-omap2430: invalid resource
> > [    4.296905] twl 1-0048: PIH (irq 23) chaining IRQs 338..346
> > [    4.297088] twl 1-0048: power (irq 343) chaining IRQs 346..353
> > [    4.329010] twl4030_gpio twl4030_gpio: gpio (irq 338) chaining IRQs 354..371
> > [    4.470123] VUSB1V5: 1500 mV normal standby
> > [    4.470916] VUSB1V8: 1800 mV normal standby
> 
> cool, at least it works, but looks like there is something still weird
> going on. Can you enable full logs so I see what's happening ?

With your patches, all DEBUG logs are identical (there is same
amount I2C of transfers), except there is only a single interrupt per
transfer. Still, the transfers are taking considerably longer, and we
see those delays in the boot:

[    4.281280] twl 1-0048: PIH (irq 23) chaining IRQs 338..346
[    4.281433] twl 1-0048: power (irq 343) chaining IRQs 346..353
[    4.281616] i2c i2c-1: master_xfer[0] W, addr=0x49, len=1
[    4.281677] i2c i2c-1: master_xfer[1] R, addr=0x49, len=1
[    4.281707] omap_i2c omap_i2c.1: addr: 0x0049, len: 1, flags: 0x0, stop: 0
[    4.281799] omap_i2c omap_i2c.1: IRQ (ISR = 0x0010)
[    4.281829] omap_i2c omap_i2c.1: addr: 0x0049, len: 1, flags: 0x1, stop: 1
[    4.281921] omap_i2c omap_i2c.1: IRQ (ISR = 0x0008)
[    4.296905] i2c i2c-1: master_xfer[0] W, addr=0x49, len=2
[    4.296936] omap_i2c omap_i2c.1: addr: 0x0049, len: 2, flags: 0x0, stop: 1
[    4.296997] omap_i2c omap_i2c.1: IRQ (ISR = 0x0010)
[    4.313476] twl4030_gpio twl4030_gpio: gpio (irq 338) chaining IRQs 354..371

This log excerpt has only 3 transfers, but the time duration is already
10x longer compared to vanilla 3.8-rc3.

A.
Felipe Balbi Jan. 15, 2013, 7:32 a.m. UTC | #4 
Hi,

On Tue, Jan 15, 2013 at 12:42:22AM +0200, Aaro Koskinen wrote:
> On Mon, Jan 14, 2013 at 11:18:46PM +0200, Felipe Balbi wrote:
> > On Mon, Jan 14, 2013 at 10:46:54PM +0200, Aaro Koskinen wrote:
> > > [    0.207946] twl 1-0048: PIH (irq 23) chaining IRQs 338..346
> > > [    0.208129] twl 1-0048: power (irq 343) chaining IRQs 346..353
> > > [    0.209350] twl4030_gpio twl4030_gpio: gpio (irq 338) chaining IRQs 354..371
> > > [    1.218749] omap_i2c omap_i2c.1: timeout waiting for bus ready
> > > [    1.218811] omap_i2c omap_i2c.1: SA 0049 CON 9602 CNT 0004
> > 
> > here's the issue, there is unloaded data in the FIFO. Can you enable
> > full I2C debugging logs ?
> 
> If I enable I2C DEBUGs, the problem is not reproducible. Everything
> looks normal:
> 
> [    0.270141] twl 1-0048: PIH (irq 23) chaining IRQs 338..346
> [    0.270294] twl 1-0048: power (irq 343) chaining IRQs 346..353
> [    0.270477] i2c i2c-1: master_xfer[0] W, addr=0x49, len=1
> [    0.270538] i2c i2c-1: master_xfer[1] R, addr=0x49, len=1
> [    0.270568] omap_i2c omap_i2c.1: addr: 0x0049, len: 1, flags: 0x0, stop: 0
> [    0.270629] omap_i2c omap_i2c.1: IRQ (ISR = 0x0010)
> [    0.270690] omap_i2c omap_i2c.1: IRQ (ISR = 0x0004)
> [    0.270751] omap_i2c omap_i2c.1: addr: 0x0049, len: 1, flags: 0x1, stop: 1
> [    0.270843] omap_i2c omap_i2c.1: IRQ (ISR = 0x0008)
> [    0.270874] omap_i2c omap_i2c.1: IRQ (ISR = 0x0004)
> [    0.270935] i2c i2c-1: master_xfer[0] W, addr=0x49, len=2
> [    0.270965] omap_i2c omap_i2c.1: addr: 0x0049, len: 2, flags: 0x0, stop: 1
> [    0.271026] omap_i2c omap_i2c.1: IRQ (ISR = 0x0010)
> [    0.271118] omap_i2c omap_i2c.1: IRQ (ISR = 0x0004)
> [    0.272155] twl4030_gpio twl4030_gpio: gpio (irq 338) chaining IRQs 354..371

still another race ? I'll look into it.

> > > >   git://git.kernel.org/pub/scm/linux/kernel/git/balbi/usb.git i2c-deferred-STP
> > > 
> > > I could not reproduce the issue with these. Tested around 20 boots.
> > > There's a noticeable delay (over 4 secs!) around where I2C is initialized
> > > and used for the first time, but no errors and the boot completes:
> > > 
> > > [    0.187530] SCSI subsystem initialized
> > > [    0.188110] usbcore: registered new interface driver usbfs
> > > [    0.188415] usbcore: registered new interface driver hub
> > > [    0.188781] usbcore: registered new device driver usb
> > > [    0.189453] musb-omap2430 musb-omap2430: invalid resource
> > > [    4.296905] twl 1-0048: PIH (irq 23) chaining IRQs 338..346
> > > [    4.297088] twl 1-0048: power (irq 343) chaining IRQs 346..353
> > > [    4.329010] twl4030_gpio twl4030_gpio: gpio (irq 338) chaining IRQs 354..371
> > > [    4.470123] VUSB1V5: 1500 mV normal standby
> > > [    4.470916] VUSB1V8: 1800 mV normal standby
> > 
> > cool, at least it works, but looks like there is something still weird
> > going on. Can you enable full logs so I see what's happening ?
> 
> With your patches, all DEBUG logs are identical (there is same
> amount I2C of transfers), except there is only a single interrupt per
> transfer. Still, the transfers are taking considerably longer, and we
> see those delays in the boot:
> 
> [    4.281280] twl 1-0048: PIH (irq 23) chaining IRQs 338..346
> [    4.281433] twl 1-0048: power (irq 343) chaining IRQs 346..353
> [    4.281616] i2c i2c-1: master_xfer[0] W, addr=0x49, len=1
> [    4.281677] i2c i2c-1: master_xfer[1] R, addr=0x49, len=1
> [    4.281707] omap_i2c omap_i2c.1: addr: 0x0049, len: 1, flags: 0x0, stop: 0
> [    4.281799] omap_i2c omap_i2c.1: IRQ (ISR = 0x0010)
> [    4.281829] omap_i2c omap_i2c.1: addr: 0x0049, len: 1, flags: 0x1, stop: 1
> [    4.281921] omap_i2c omap_i2c.1: IRQ (ISR = 0x0008)
> [    4.296905] i2c i2c-1: master_xfer[0] W, addr=0x49, len=2
> [    4.296936] omap_i2c omap_i2c.1: addr: 0x0049, len: 2, flags: 0x0, stop: 1
> [    4.296997] omap_i2c omap_i2c.1: IRQ (ISR = 0x0010)
> [    4.313476] twl4030_gpio twl4030_gpio: gpio (irq 338) chaining IRQs 354..371
> 
> This log excerpt has only 3 transfers, but the time duration is already
> 10x longer compared to vanilla 3.8-rc3.

weird, there's nothing extremely expensive added by my patchset, I'll go
over them and try to figure out what's going on.

Thanks for notifying me about it.
Felipe Balbi Jan. 15, 2013, 8:55 a.m. UTC | #5 
Hi,

(quick parens here)

I think n900's problems will go away if you add omap_i2c_wait_for_ardy()
from my patchset.

On Tue, Jan 15, 2013 at 09:32:25AM +0200, Felipe Balbi wrote:
> > [    4.281280] twl 1-0048: PIH (irq 23) chaining IRQs 338..346
> > [    4.281433] twl 1-0048: power (irq 343) chaining IRQs 346..353
> > [    4.281616] i2c i2c-1: master_xfer[0] W, addr=0x49, len=1
> > [    4.281677] i2c i2c-1: master_xfer[1] R, addr=0x49, len=1
> > [    4.281707] omap_i2c omap_i2c.1: addr: 0x0049, len: 1, flags: 0x0, stop: 0
> > [    4.281799] omap_i2c omap_i2c.1: IRQ (ISR = 0x0010)
> > [    4.281829] omap_i2c omap_i2c.1: addr: 0x0049, len: 1, flags: 0x1, stop: 1
> > [    4.281921] omap_i2c omap_i2c.1: IRQ (ISR = 0x0008)
> > [    4.296905] i2c i2c-1: master_xfer[0] W, addr=0x49, len=2
> > [    4.296936] omap_i2c omap_i2c.1: addr: 0x0049, len: 2, flags: 0x0, stop: 1
> > [    4.296997] omap_i2c omap_i2c.1: IRQ (ISR = 0x0010)
> > [    4.313476] twl4030_gpio twl4030_gpio: gpio (irq 338) chaining IRQs 354..371
> > 
> > This log excerpt has only 3 transfers, but the time duration is already
> > 10x longer compared to vanilla 3.8-rc3.
> 
> weird, there's nothing extremely expensive added by my patchset, I'll go
> over them and try to figure out what's going on.
> 
> Thanks for notifying me about it.

Here's from v3.8-rc3 vanilla (just added two small prints):

[    1.688079] omap_i2c omap_i2c.1: addr: 0x0048, len: 1, flags: 0x0, stop: 0
[    1.688110] omap_i2c omap_i2c.1: starting transfer
[    1.688140] omap_i2c omap_i2c.1: IRQ (ISR = 0x0010)
[    1.688201] omap_i2c omap_i2c.1: IRQ (ISR = 0x0004)
[    1.688232] omap_i2c omap_i2c.1: finishing transfer
[    1.688232] omap_i2c omap_i2c.1: addr: 0x0048, len: 1, flags: 0x1, stop: 1
[    1.688262] omap_i2c omap_i2c.1: starting transfer
[    1.688354] omap_i2c omap_i2c.1: IRQ (ISR = 0x0008)
[    1.688354] omap_i2c omap_i2c.1: IRQ (ISR = 0x0004)
[    1.688385] omap_i2c omap_i2c.1: finishing transfer
[    1.688415] i2c i2c-1: master_xfer[0] W, addr=0x48, len=2
[    1.688446] omap_i2c omap_i2c.1: addr: 0x0048, len: 2, flags: 0x0, stop: 1
[    1.688446] omap_i2c omap_i2c.1: starting transfer
[    1.688476] omap_i2c omap_i2c.1: IRQ (ISR = 0x0010)
[    1.688568] omap_i2c omap_i2c.1: IRQ (ISR = 0x0004)
[    1.688598] omap_i2c omap_i2c.1: finishing transfer
[    1.688629] i2c i2c-1: master_xfer[0] W, addr=0x48, len=1
[    1.688659] i2c i2c-1: master_xfer[1] R, addr=0x48, len=6
[    1.688659] omap_i2c omap_i2c.1: addr: 0x0048, len: 1, flags: 0x0, stop: 0
[    1.688690] omap_i2c omap_i2c.1: starting transfer
[    1.688720] omap_i2c omap_i2c.1: IRQ (ISR = 0x0010)
[    1.688781] omap_i2c omap_i2c.1: IRQ (ISR = 0x0004)
[    1.688812] omap_i2c omap_i2c.1: finishing transfer
[    1.688812] omap_i2c omap_i2c.1: addr: 0x0048, len: 6, flags: 0x1, stop: 1

and here's from my patchset:

[    1.993865] omap_i2c omap_i2c.1: addr: 0x0049, len: 1, flags: 0x0, stop: 0
[    1.993896] omap_i2c omap_i2c.1: starting transfer
[    1.993927] omap_i2c omap_i2c.1: IRQ (ISR = 0x0010)
[    1.993957] omap_i2c omap_i2c.1: finished transfer
[    1.993988] omap_i2c omap_i2c.1: addr: 0x0049, len: 1, flags: 0x1, stop: 1
[    1.993988] omap_i2c omap_i2c.1: starting transfer
[    1.994079] omap_i2c omap_i2c.1: IRQ (ISR = 0x0008)
[    1.994110] omap_i2c omap_i2c.1: finished transfer
[    2.009490] i2c i2c-1: master_xfer[0] W, addr=0x49, len=2
[    2.009490] omap_i2c omap_i2c.1: addr: 0x0049, len: 2, flags: 0x0, stop: 1
[    2.009521] omap_i2c omap_i2c.1: starting transfer
[    2.009552] omap_i2c omap_i2c.1: IRQ (ISR = 0x0010)
[    2.009582] omap_i2c omap_i2c.1: finished transfer
[    2.025054] i2c i2c-1: master_xfer[0] W, addr=0x49, len=1
[    2.025054] i2c i2c-1: master_xfer[1] R, addr=0x49, len=1
[    2.025085] omap_i2c omap_i2c.1: addr: 0x0049, len: 1, flags: 0x0, stop: 0
[    2.025085] omap_i2c omap_i2c.1: starting transfer
[    2.025146] omap_i2c omap_i2c.1: IRQ (ISR = 0x0010)
[    2.025177] omap_i2c omap_i2c.1: finished transfer
[    2.025177] omap_i2c omap_i2c.1: addr: 0x0049, len: 1, flags: 0x1, stop: 1
[    2.025207] omap_i2c omap_i2c.1: starting transfer
[    2.025268] omap_i2c omap_i2c.1: IRQ (ISR = 0x0008)
[    2.025329] omap_i2c omap_i2c.1: finished transfer
[    2.040679] i2c i2c-1: master_xfer[0] W, addr=0x49, len=2
[    2.040710] omap_i2c omap_i2c.1: addr: 0x0049, len: 2, flags: 0x0, stop: 1
[    2.040710] omap_i2c omap_i2c.1: starting transfer
[    2.040771] omap_i2c omap_i2c.1: IRQ (ISR = 0x0010)
[    2.040802] omap_i2c omap_i2c.1: finished transfer

Looks like the transfer itself is faster with my patchset. I don't have
an idea of what's causing extra delay, for whatever reason client driver
seems to take longer to start more i2c transfers. I've added extra
prints to see what's going on:


| [    1.818725] omap_i2c omap_i2c.1: pm_runtime_get_sync()
| [    1.818725] omap_i2c omap_i2c.1: omap_i2c_wait_for_bb()
| [    1.818725] omap_i2c omap_i2c.1: omap_i2c_xfer_msg()
| [    1.818756] omap_i2c omap_i2c.1: addr: 0x0048, len: 1, flags: 0x0, stop: 0
| [    1.818756] omap_i2c omap_i2c.1: starting transfer
| [    1.818786] omap_i2c omap_i2c.1: IRQ (ISR = 0x0010)
| [    1.818847] omap_i2c omap_i2c.1: finished transfer
| [    1.818847] omap_i2c omap_i2c.1: addr: 0x0048, len: 1, flags: 0x1, stop: 1
| [    1.818847] omap_i2c omap_i2c.1: starting transfer
| [    1.818939] omap_i2c omap_i2c.1: IRQ (ISR = 0x0008)
| [    1.818969] omap_i2c omap_i2c.1: finished transfer
| [    1.819000] omap_i2c omap_i2c.1: waiting for ARDY
| [    1.819000] omap_i2c omap_i2c.1: ARDY
| [    1.819000] omap_i2c omap_i2c.1: 2. omap_i2c_wait_for_bb()
| [    1.819030] omap_i2c omap_i2c.1: pm_runtime_mark_last_busy()
| [    1.819030] omap_i2c omap_i2c.1: return
| [    1.819061] i2c i2c-1: master_xfer[0] W, addr=0x48, len=1
| [    1.819061] i2c i2c-1: master_xfer[1] R, addr=0x48, len=1
| [    1.819091] omap_i2c omap_i2c.1: pm_runtime_get_sync()
| [    1.819091] omap_i2c omap_i2c.1: omap_i2c_wait_for_bb()
| [    1.819122] omap_i2c omap_i2c.1: omap_i2c_xfer_msg()
| [    1.819122] omap_i2c omap_i2c.1: addr: 0x0048, len: 1, flags: 0x0, stop: 0
| [    1.819122] omap_i2c omap_i2c.1: starting transfer
| [    1.819183] omap_i2c omap_i2c.1: IRQ (ISR = 0x0010)
| [    1.819213] omap_i2c omap_i2c.1: finished transfer
| [    1.819213] omap_i2c omap_i2c.1: addr: 0x0048, len: 1, flags: 0x1, stop: 1
| [    1.819244] omap_i2c omap_i2c.1: starting transfer
| [    1.819305] omap_i2c omap_i2c.1: IRQ (ISR = 0x0008)
| [    1.819366] omap_i2c omap_i2c.1: finished transfer
| [    1.819366] omap_i2c omap_i2c.1: waiting for ARDY
| [    1.819366] omap_i2c omap_i2c.1: ARDY
| [    1.819396] omap_i2c omap_i2c.1: 2. omap_i2c_wait_for_bb()
| [    1.819396] omap_i2c omap_i2c.1: pm_runtime_mark_last_busy()
| [    1.819396] omap_i2c omap_i2c.1: return
| [    1.819427] i2c i2c-1: master_xfer[0] W, addr=0x48, len=1
| [    1.819458] i2c i2c-1: master_xfer[1] R, addr=0x48, len=1
| [    1.819458] omap_i2c omap_i2c.1: pm_runtime_get_sync()
| [    1.819458] omap_i2c omap_i2c.1: omap_i2c_wait_for_bb()
| [    1.819488] omap_i2c omap_i2c.1: omap_i2c_xfer_msg()
| [    1.819488] omap_i2c omap_i2c.1: addr: 0x0048, len: 1, flags: 0x0, stop: 0
| [    1.819519] omap_i2c omap_i2c.1: starting transfer
| [    1.819549] omap_i2c omap_i2c.1: IRQ (ISR = 0x0010)
| [    1.819580] omap_i2c omap_i2c.1: finished transfer
| [    1.819580] omap_i2c omap_i2c.1: addr: 0x0048, len: 1, flags: 0x1, stop: 1
| [    1.819610] omap_i2c omap_i2c.1: starting transfer
| [    1.819671] omap_i2c omap_i2c.1: IRQ (ISR = 0x0008)
| [    1.819732] omap_i2c omap_i2c.1: finished transfer
| [    1.819732] omap_i2c omap_i2c.1: waiting for ARDY
| [    1.819732] omap_i2c omap_i2c.1: ARDY
| [    1.819763] omap_i2c omap_i2c.1: 2. omap_i2c_wait_for_bb()
| [    1.819763] omap_i2c omap_i2c.1: pm_runtime_mark_last_busy()
| [    1.819793] omap_i2c omap_i2c.1: return

as you can see, from pm_runtime_get_sync() to return, the time spent is
about the same in all cases (around 305us).

one thing I note, however, is that after we start waiting for ARDY,
there's no point in "omap_i2c_wait_for_bb()" since I only exit
omap_i2c_xfer_msg() after all bytes have been unloaded on SDA line.

Removing that saves some extra time (about 30us):

[    1.751983] omap_i2c omap_i2c.1: pm_runtime_get_sync()
[    1.751983] omap_i2c omap_i2c.1: omap_i2c_xfer_msg()
[    1.751983] omap_i2c omap_i2c.1: addr: 0x0048, len: 1, flags: 0x0, stop: 0
[    1.752014] omap_i2c omap_i2c.1: starting transfer
[    1.752044] omap_i2c omap_i2c.1: IRQ (ISR = 0x0010)
[    1.752075] omap_i2c omap_i2c.1: finished transfer
[    1.752105] omap_i2c omap_i2c.1: addr: 0x0048, len: 1, flags: 0x1, stop: 1
[    1.752105] omap_i2c omap_i2c.1: starting transfer
[    1.752197] omap_i2c omap_i2c.1: IRQ (ISR = 0x0008)
[    1.752227] omap_i2c omap_i2c.1: finished transfer
[    1.752227] omap_i2c omap_i2c.1: waiting for ARDY
[    1.752258] omap_i2c omap_i2c.1: ARDY
[    1.752258] omap_i2c omap_i2c.1: pm_runtime_mark_last_busy()
[    1.752258] omap_i2c omap_i2c.1: return
[    1.752288] i2c i2c-1: master_xfer[0] W, addr=0x48, len=2
[    1.752319] omap_i2c omap_i2c.1: pm_runtime_get_sync()
[    1.752319] omap_i2c omap_i2c.1: omap_i2c_xfer_msg()
[    1.752349] omap_i2c omap_i2c.1: addr: 0x0048, len: 2, flags: 0x0, stop: 1
[    1.752349] omap_i2c omap_i2c.1: starting transfer
[    1.752380] omap_i2c omap_i2c.1: IRQ (ISR = 0x0010)
[    1.752410] omap_i2c omap_i2c.1: finished transfer
[    1.752441] omap_i2c omap_i2c.1: waiting for ARDY
[    1.752441] omap_i2c omap_i2c.1: ARDY
[    1.752471] omap_i2c omap_i2c.1: pm_runtime_mark_last_busy()
[    1.752471] omap_i2c omap_i2c.1: return

For whatever reason, in some cases client driver takes longer to
initiate a transfer and I don't think there's anything we can do about
that during boot up.

Anyway, whenever I can see a big delay, it's always from "return" to the
next "i2c i2c-1: master_xfer[0] W, addr=0x48, len=1" message.
diff mbox

Patch

diff --git a/drivers/i2c/busses/i2c-omap.c b/drivers/i2c/busses/i2c-omap.c
index 20d41bf..173e883 100644
--- a/drivers/i2c/busses/i2c-omap.c
+++ b/drivers/i2c/busses/i2c-omap.c
@@ -462,6 +462,10 @@  static int omap_i2c_wait_for_bb(struct omap_i2c_dev *dev)
 	while (omap_i2c_read_reg(dev, OMAP_I2C_STAT_REG) & OMAP_I2C_STAT_BB) {
 		if (time_after(jiffies, timeout)) {
 			dev_warn(dev->dev, "timeout waiting for bus ready\n");
+			dev_warn(dev->dev, "SA %04x CON %04x CNT %04x\n",
+					omap_i2c_read_reg(dev, OMAP_I2C_SA_REG),
+					omap_i2c_read_reg(dev, OMAP_I2C_CON_REG),
+					omap_i2c_read_reg(dev, OMAP_I2C_CNT_REG));
 			return -ETIMEDOUT;
 		}
 		msleep(1);