From: balbi@ti.com (Felipe Balbi)
To: linux-arm-kernel@lists.infradead.org
Subject: OMAP baseline test results for v3.8-rc3
Date: Tue, 15 Jan 2013 10:55:30 +0200 [thread overview]
Message-ID: <20130115085530.GA4350@arwen.pp.htv.fi> (raw)
In-Reply-To: <20130115073225.GB14505@arwen.pp.htv.fi>
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.
--
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/ed31a283/attachment.sig>
next prev parent reply other threads:[~2013-01-15 8:55 UTC|newest]
Thread overview: 12+ messages / expand[flat|nested] mbox.gz Atom feed top
2013-01-14 17:59 OMAP baseline test results for v3.8-rc3 Paul Walmsley
2013-01-14 18:40 ` Aaro Koskinen
2013-01-14 19:14 ` Felipe Balbi
2013-01-14 20:46 ` Aaro Koskinen
2013-01-14 21:18 ` Felipe Balbi
2013-01-14 22:42 ` Aaro Koskinen
2013-01-15 7:32 ` Felipe Balbi
2013-01-15 8:55 ` Felipe Balbi [this message]
2013-01-17 18:38 ` Paul Walmsley
2013-01-15 8:16 ` Peter Ujfalusi
2013-01-17 18:43 ` Paul Walmsley
2013-01-18 10:46 ` Peter Ujfalusi
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=20130115085530.GA4350@arwen.pp.htv.fi \
--to=balbi@ti.com \
--cc=linux-arm-kernel@lists.infradead.org \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).