From: Matthias Fuchs <mfuchs@ma-fu.de>
To: Tim Sander <tim@krieglstein.org>
Cc: linux-rt-users <linux-rt-users@vger.kernel.org>
Subject: Re: 3.12.6-rt9 on AM335x (armv7)
Date: Wed, 08 Jan 2014 09:06:53 +0100 [thread overview]
Message-ID: <52CD071D.9060207@ma-fu.de> (raw)
In-Reply-To: <10785809.PZUZGWPMgY@hydra>
Hi Tim,
I already linked to trace for a 2508us run in a previous post. Here is the
most interesting section. A added two comments:
...
ksoftirq-3 0dN..311 83809806626us+: lock_acquire: c1194890 &rq->lock
#
# Typically rt_tuntime_lock is kept for only a few us:
#
ksoftirq-3 0dN..411 83809806633us+: lock_acquire: c1194cc8 &rt_rq->rt_runtime_lock
ksoftirq-3 0dN..411 83809806638us+: lock_release: c1194cc8 &rt_rq->rt_runtime_lock
ksoftirq-3 0d...311 83809806644us+: sched_switch: prev_comm=ksoftirqd/0 prev_pid=3 prev_prio=98 prev_state=R+ ==> next_comm=cyclictest next_pid=1126 next_prio=0
ksoftirq-3 0d...311 83809806649us+: lock_release: c1194890 &rq->lock
ksoftirq-3 0d...311 83809806653us+: lock_acquire: c0852178 read rcu_read_lock
ksoftirq-3 0d...311 83809806658us+: lock_release: c0852178 rcu_read_lock
cyclicte-1126 0d...3.. 83809806662us+: lock_acquire: c1194890 &rq->lock
cyclicte-1126 0d...3.. 83809806666us+: lock_release: c1194890 &rq->lock
cyclicte-1126 0d...2.. 83809806672us+: lock_acquire: c1191990 hrtimer_bases.lock
cyclicte-1126 0d...2.. 83809806677us+: lock_release: c1191990 hrtimer_bases.lock
cyclicte-1126 0....1.. 83809806681us+: sys_exit: NR 265 = 0
cyclicte-1126 0....1.. 83809806687us+: sys_enter: NR 263 (1, b6fc8840, 0, 0, 4c, 0)
cyclicte-1126 0....1.. 83809806691us+: sys_exit: NR 263 = 0
cyclicte-1126 0....1.. 83809806698us+: sys_enter: NR 265 (1, 1, b6fc8848, 0, 1, 0)
cyclicte-1126 0....1.. 83809806702us+: hrtimer_init: hrtimer=cd0a5f10 clockid=CLOCK_MONOTONIC mode=HRTIMER_MODE_ABS
cyclicte-1126 0d...2.. 83809806707us+: lock_acquire: c1191990 hrtimer_bases.lock
cyclicte-1126 0d...2.. 83809806712us+: hrtimer_start: hrtimer=cd0a5f10 function=hrtimer_wakeup expires=83809801188363 softexpires=83809801188363
cyclicte-1126 0d...2.. 83809806717us+: hrtimer_cancel: hrtimer=cd0a5f10
cyclicte-1126 0d...2.. 83809806721us+: lock_release: c1191990 hrtimer_bases.lock
cyclicte-1126 0d...2.. 83809806726us+: lock_acquire: c1191990 hrtimer_bases.lock
cyclicte-1126 0d...2.. 83809806730us+: lock_release: c1191990 hrtimer_bases.lock
cyclicte-1126 0....1.. 83809806734us+: sys_exit: NR 265 = 0
cyclicte-1126 0....1.. 83809806739us+: sys_enter: NR 263 (1, b6fc8840, 0, 0, bf, 0)
cyclicte-1126 0....1.. 83809806742us+: sys_exit: NR 263 = 0
cyclicte-1126 0....1.. 83809806747us+: sys_enter: NR 265 (1, 1, b6fc8848, 0, 1, 0)
cyclicte-1126 0....1.. 83809806750us+: hrtimer_init: hrtimer=cd0a5f10 clockid=CLOCK_MONOTONIC mode=HRTIMER_MODE_ABS
cyclicte-1126 0d...2.. 83809806754us+: lock_acquire: c1191990 hrtimer_bases.lock
cyclicte-1126 0d...2.. 83809806758us+: hrtimer_start: hrtimer=cd0a5f10 function=hrtimer_wakeup expires=83809801388363 softexpires=83809801388363
cyclicte-1126 0d...2.. 83809806764us+: lock_release: c1191990 hrtimer_bases.lock
cyclicte-1126 0....2.. 83809806769us+: rcu_utilization: Start context switch
cyclicte-1126 0....2.. 83809806772us+: rcu_utilization: End context switch
cyclicte-1126 0d...3.. 83809806775us+: lock_acquire: c1194890 &rq->lock
cyclicte-1126 0d...4.. 83809806781us+: lock_acquire: c1194cc8 &rt_rq->rt_runtime_lock
cyclicte-1126 0d...4.. 83809806786us+: lock_release: c1194cc8 &rt_rq->rt_runtime_lock
cyclicte-1126 0d...3.. 83809806797us+: sched_switch: prev_comm=cyclictest prev_pid=1126 prev_prio=0 prev_state=S ==> next_comm=ksoftirqd/0 next_pid=3 next_prio=98
cyclicte-1126 0d...3.. 83809806801us+: lock_release: c1194890 &rq->lock
cyclicte-1126 0d...3.. 83809806805us+: lock_acquire: c0852178 read rcu_read_lock
cyclicte-1126 0d...3.. 83809806810us+: lock_release: c0852178 rcu_read_lock
ksoftirq-3 0d...311 83809806814us+: lock_acquire: c1194890 &rq->lock
ksoftirq-3 0d...311 83809806819us+: lock_release: c1194890 &rq->lock
ksoftirq-3 0....111 83809806827us+: softirq_entry: vec=1 [action=TIMER]
ksoftirq-3 0d...212 83809806836us+: lock_acquire: c0893b50 &(&(&base->lock)->lock)->wait_lock
ksoftirq-3 0d...212 83809806841us+: lock_release: c0893b50 &(&(&base->lock)->lock)->wait_lock
ksoftirq-3 0d...112 83809806846us+: lock_acquire: c0893b74 &base->lock
ksoftirq-3 0....112 83809806855us+: timer_cancel: timer=c0888738
ksoftirq-3 0d...112 83809806858us+: lock_release: c0893b74 &base->lock
ksoftirq-3 0d...212 83809806862us+: lock_acquire: c0893b50 &(&(&base->lock)->lock)->wait_lock
ksoftirq-3 0d...212 83809806867us+: lock_release: c0893b50 &(&(&base->lock)->lock)->wait_lock
ksoftirq-3 0d...111 83809806873us+: lock_acquire: ce075e20 (&(&tbl->gc_work)->timer)
ksoftirq-3 0....111 83809806882us+: timer_expire_entry: timer=c0888738 function=delayed_work_timer_fn now=8350980
ksoftirq-3 0d...111 83809806888us+: lock_acquire: c0852178 read rcu_read_lock
ksoftirq-3 0d...212 83809806896us+: lock_acquire: c1194210 &(&(&pool->lock)->lock)->wait_lock
ksoftirq-3 0d..h312 83809806904us+: lock_acquire: ce009470 &irq_desc_lock_class
ksoftirq-3 0d..h412 83809806910us+: lock_acquire: ce00f210 &gc->lock
ksoftirq-3 0d..h412 83809806915us+: lock_release: ce00f210 &gc->lock
ksoftirq-3 0d..h412 83809806919us+: lock_acquire: ce00f210 &gc->lock
ksoftirq-3 0d..h412 83809806923us+: lock_release: ce00f210 &gc->lock
ksoftirq-3 0d..h312 83809806927us+: lock_release: ce009470 &irq_desc_lock_class
ksoftirq-3 0d..h212 83809806931us+: irq_handler_entry: irq=84 name=gp_timer
ksoftirq-3 0d..h312 83809806934us+: lock_acquire: c1191990 hrtimer_bases.lock
ksoftirq-3 0d..h312 83809806940us+: hrtimer_cancel: hrtimer=cd0a5f10
ksoftirq-3 0d..h312 83809806944us+: lock_release: c1191990 hrtimer_bases.lock
ksoftirq-3 0d..h212 83809806948us+: hrtimer_expire_entry: hrtimer=cd0a5f10 function=hrtimer_wakeup now=83809801429280
ksoftirq-3 0d..h312 83809806952us+: lock_acquire: ce08f2f4 &p->pi_lock
ksoftirq-3 0d..h412 83809806957us+: lock_acquire: c1194890 &rq->lock
ksoftirq-3 0dN.h412 83809806966us+: sched_wakeup: comm=cyclictest pid=1126 prio=0 success=1 target_cpu=000
ksoftirq-3 0dN.h412 83809806970us+: lock_release: c1194890 &rq->lock
ksoftirq-3 0dN.h312 83809806975us+: lock_release: ce08f2f4 &p->pi_lock
ksoftirq-3 0dN.h212 83809806979us+: hrtimer_expire_exit: hrtimer=cd0a5f10
ksoftirq-3 0dN.h312 83809806982us+: lock_acquire: c1191990 hrtimer_bases.lock
ksoftirq-3 0dN.h312 83809806987us+: lock_release: c1191990 hrtimer_bases.lock
ksoftirq-3 0dN.h212 83809806993us+: irq_handler_exit: irq=84 ret=handled
ksoftirq-3 0dN.h312 83809806997us+: lock_acquire: ce009470 &irq_desc_lock_class
ksoftirq-3 0dN.h412 83809807002us+: lock_acquire: ce00f210 &gc->lock
ksoftirq-3 0dN.h412 83809807006us+: lock_release: ce00f210 &gc->lock
ksoftirq-3 0dN.h312 83809807011us+: lock_release: ce009470 &irq_desc_lock_class
ksoftirq-3 0dN..212 83809807019us+: lock_release: c1194210 &(&(&pool->lock)->lock)->wait_lock
ksoftirq-3 0.N..212 83809807024us+: rcu_utilization: Start context switch
ksoftirq-3 0dN..312 83809807029us+: lock_acquire: c0854ed0 rcu_node_0
ksoftirq-3 0dN..312 83809807076us+: lock_release: c0854ed0 rcu_node_0
ksoftirq-3 0.N..212 83809807083us+: rcu_utilization: End context switch
ksoftirq-3 0dN..312 83809807087us+: lock_acquire: c1194890 &rq->lock
#
# Here comes the problem: rt_tuntime_lock is keept for more than 2000us:
#
ksoftirq-3 0dN..412 83809807130us!: lock_acquire: c1194cc8 &rt_rq->rt_runtime_lock
ksoftirq-3 0dN..412 83809809299us+: lock_release: c1194cc8 &rt_rq->rt_runtime_lock
ksoftirq-3 0d...312 83809809317us+: sched_switch: prev_comm=ksoftirqd/0 prev_pid=3 prev_prio=98 prev_state=R+ ==> next_comm=cyclictest next_pid=1126 next_prio=0
ksoftirq-3 0d...312 83809809328us+: lock_release: c1194890 &rq->lock
ksoftirq-3 0d...312 83809809338us+: lock_acquire: c0852178 read rcu_read_lock
ksoftirq-3 0d...312 83809809348us+: lock_release: c0852178 rcu_read_lock
cyclicte-1126 0d...3.. 83809809355us+: lock_acquire: c1194890 &rq->lock
cyclicte-1126 0d...3.. 83809809363us+: lock_release: c1194890 &rq->lock
cyclicte-1126 0d...2.. 83809809376us+: lock_acquire: c1191990 hrtimer_bases.lock
cyclicte-1126 0d...2.. 83809809382us+: lock_release: c1191990 hrtimer_bases.lock
cyclicte-1126 0....1.. 83809809390us+: sys_exit: NR 265 = 0
cyclicte-1126 0....1.. 83809809401us+: sys_enter: NR 263 (1, b6fc8840, 0, 0, 2b, 0)
cyclicte-1126 0....1.. 83809809411us!: sys_exit: NR 263 = 0
cyclicte-1126 0....1.. 83809809512us+: sys_enter: NR 4 (5, b6fc9538, 22, b6fc955a, 18de8, b6fc9538)
cyclicte-1126 0d...1.. 83809809520us+: lock_acquire: c0852178 read rcu_read_lock
cyclicte-1126 0d...1.. 83809809527us+: lock_release: c0852178 rcu_read_lock
cyclicte-1126 0d...1.. 83809809540us+: lock_acquire: ce037b6c read sb_writers
cyclicte-1126 0d...1.. 83809809553us+: lock_acquire: ce5a5968 &mm->mmap_sem
cyclicte-1126 0d...2.. 83809809561us+: lock_acquire: ce5a5944 &(&((&mm->mmap_sem))->lock)->wait_lock
cyclicte-1126 0d...2.. 83809809568us+: lock_release: ce5a5944 &(&((&mm->mmap_sem))->lock)->wait_lock
cyclicte-1126 0d...211 83809809586us+: lock_acquire: ce5a5900 &(&(&mm->page_table_lock)->lock)->wait_lock
cyclicte-1126 0d...211 83809809592us+: lock_release: ce5a5900 &(&(&mm->page_table_lock)->lock)->wait_lock
cyclicte-1126 0d...111 83809809597us+: lock_acquire: ce5a5924 &mm->page_table_lock
cyclicte-1126 0d...111 83809809606us+: lock_release: ce5a5924 &mm->page_table_lock
cyclicte-1126 0d...211 83809809610us+: lock_acquire: ce5a5900 &(&(&mm->page_table_lock)->lock)->wait_lock
cyclicte-1126 0d...211 83809809615us+: lock_release: ce5a5900 &(&(&mm->page_table_lock)->lock)->wait_lock
cyclicte-1126 0d...1.. 83809809633us+: lock_release: ce5a5968 &mm->mmap_sem
cyclicte-1126 0d...2.. 83809809638us+: lock_acquire: ce5a5944 &(&((&mm->mmap_sem))->lock)->wait_lock
cyclicte-1126 0d...2.. 83809809644us+: lock_release: ce5a5944 &(&((&mm->mmap_sem))->lock)->wait_lock
cyclicte-1126 0.....11 83809809650us+: tracing_mark_write: hit latency threshold (500 > 2508)
cyclicte-1126 0d...1.. 83809809663us+: lock_acquire: c0dd6b6c read &fsnotify_mark_srcu
cyclicte-1126 0d...1.. 83809809670us+: lock_release: c0dd6b6c &fsnotify_mark_srcu
cyclicte-1126 0d...1.. 83809809675us+: lock_release: ce037b6c sb_writers
cyclicte-1126 0....1.. 83809809681us+: sys_exit: NR 4 = 34
cyclicte-1126 0....1.. 83809809690us+: sys_enter: NR 4 (4, fb70, 1, 18de8, 9cc, 0)
cyclicte-1126 0d...1.. 83809809693us+: lock_acquire: c0852178 read rcu_read_lock
cyclicte-1126 0d...1.. 83809809708us+: lock_release: c0852178 rcu_read_lock
cyclicte-1126 0d...1.. 83809809714us+: lock_acquire: ce037b6c read sb_writers
cyclicte-1126 0d...1.. 83809809727us+: lock_acquire: c0855794 trace_types_lock
cyclicte-1126 0d...2.. 83809809734us+: lock_acquire: c0855774 trace_types_lock.lock.wait_lock
cyclicte-1126 0d...2.. 83809809747us : lock_release: c0855774 trace_types_lock.lock.wait_lock
Matthias
On 07.01.2014 23:58, Tim Sander wrote:
> Hi Matthias
>> without hackbench and frieds (idle system) I get a max. latency of about
>> 4ms. Running hackbench (default arguments, -l 1000), it still increases up
>> to 5ms:
>>
>> ...
>> # Total: 000000193
>> # Min Latencies: 00024
>> # Avg Latencies: 00205
>> # Max Latencies: 05058
>> ...
>>
>> The obvious PM stuff is disabled. No dynamic frequency scaling, etc.
>> Really weired stuff. I already mentioned the 3.2 system with the same CPU in
>> the OSADL lab. It comes with max. latency of 118us. So I really expect
>> something similiar.
> Yeah 118 µs should be the right ballpark, while still a little high for my
> taste. All cortex a8 seem to have rather high latency. The A9's seem much
> better in this respect.
>
> Have you seen the following:
> https://www.osadl.org/Realtime-Preempt-Kernel.kernel-rt.0.html#latencyfighting
>
> Cyclictest has tracing support which might help finding the cause of the long
> latency.
>
> Best regards
> Tim
> --
> To unsubscribe from this list: send the line "unsubscribe linux-rt-users" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at http://vger.kernel.org/majordomo-info.html
>
--
To unsubscribe from this list: send the line "unsubscribe linux-rt-users" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
next prev parent reply other threads:[~2014-01-08 8:06 UTC|newest]
Thread overview: 9+ messages / expand[flat|nested] mbox.gz Atom feed top
2014-01-01 16:37 3.12.6-rt9 on AM335x (armv7) Matthias Fuchs
2014-01-06 19:48 ` Matthias Fuchs
2014-01-07 8:38 ` Tim Sander
2014-01-07 21:20 ` Matthias Fuchs
2014-01-07 22:58 ` Tim Sander
2014-01-07 23:46 ` Pavel Vasilyev
2014-01-08 8:08 ` Matthias Fuchs
2014-01-08 8:06 ` Matthias Fuchs [this message]
2014-02-07 16:07 ` Sebastian Andrzej Siewior
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=52CD071D.9060207@ma-fu.de \
--to=mfuchs@ma-fu.de \
--cc=linux-rt-users@vger.kernel.org \
--cc=tim@krieglstein.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 an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.