OMAP baseline test results for v3.8-rc3

[Felipe Balbi]

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.

-- 
balbi
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 836 bytes
Desc: Digital signature
URL: <http://lists.infradead.org/pipermail/linux-arm-kernel/attachments/20130115/263fe819/attachment-0001.sig>