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 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).