3.12.6-rt9 on AM335x (armv7)

3.12.6-rt9 on AM335x (armv7)

[Matthias Fuchs]

Hi,

I did a setup with 3.12.6-rt9 kernel on a Beaglebone board
with an TI AM335x CPU running at fixed 720MHz. The kernel uses the 
omap2plus_defconfig configuration that comes with this kernel with 
additional CONFIG_PREEMPT_RT_FULL switched on.

I am observing some strange max. latencies when comparing with kernel 
3.2.45-rt66. The results of a similiar system can be found on the OSADL lab
site (https://www.osadl.org/Latency-plot-of-system-in-rack-7-slot.qa-latencyplot-r7s5.0.html).

With "cyclictest -p99 -m -n -i200 -h400 -q -l10000000" I get
...
# Min Latencies: 00013
# Avg Latencies: 00062
# Max Latencies: 04664
...

Also the latency does not differ much from that when doing a flood ping against 
the system as simple stress.

3.2.45-rt66 comes with a max. latency of 118us! So I expect something to be wrong with 3.12.6-rt9
at least on armv7 or especially this device (max. lat. 4664us).

I also noticed an issue with the on-chip ethernet when CONFIG_PREEMPT_RT_FULL is
switched on with this kernel:

I also noticed that the 3.12.6-rt9 with enabled 
[    2.817024] net eth0: initializing cpsw version 1.12 (0)
[    2.825269] net eth0: phy found : id is : 0x7c0f1
[    2.830713] libphy: PHY 4a101000.mdio:01 not found
[    2.835777] net eth0: phy 4a101000.mdio:01 not found on slave 1
[   12.846394] Waiting up to 110 more seconds for network.
[   22.846147] Waiting up to 100 more seconds for network.
...

Finally networking is fine. But I need to wait for 110 seconds :-)

Prior testing with 3.12.6-rt9 I did the same test with 3.12.5-rt7. Same results.
But without CONFIG_PREEMPT_RT_FULL I do not get this bringup delay. I could not do this 
test with rt9 because it does not build without CONFIG_PREEMPT_RT_FULL!

Any ideas?

Matthias

Re: 3.12.6-rt9 on AM335x (armv7)

[Matthias Fuchs]

Hi,

after some chatting with Nicholas and being sure that I didn't do anything totally stupid
I would like to provide my current kernel config and a trace generated by "cyclictest ... -b500".

kernel config -> https://www.dropbox.com/s/zsud0b77xoosjm1/config
trace -> https://www.dropbox.com/s/5uf58oqo0qwcn4x/trace-cyclictest-2508us.txt

I still get max latencies of about 4000us on this TI AM335x system running 3.12.6-rt9 with
timers-do-not-raise-softirq-unconditionally.patch reverse applied.

sched_rt_runtime_us and sched_rt_period_us are identical. The system is idle during the test.
Rootfilesystem comes via NFS.

root@generic-armv7a:~# cat /proc/sys/kernel/sched_rt_runtime_us 
1000000
root@generic-armv7a:~# cat /proc/sys/kernel/sched_rt_period_us  
1000000

root@generic-armv7a:~# uname -a 
Linux generic-armv7a 3.12.6-rt9-dirty #3 SMP PREEMPT RT Sat Jan 4 23:01:19 CET 2014 armv7l GNU/Linux

root@generic-armv7a:~# ~/cyclictest -p99 -m -n -i200 -h400 -q -l100000 -b 500
# /dev/cpu_dma_latency set to 0us
INFO: debugfs mountpoint: /sys/kernel/debug/tracing/
could not set ftrace_enabled to 0
could not set tracing_max_latency to 0
# Histogram
...
# Total: 000018604
# Min Latencies: 00024
# Avg Latencies: 00158
# Max Latencies: 02508
# Histogram Overflows: 00212
# Histogram Overflow at cycle number:
# Thread 0: ...
...
# Thread Ids: 01126
# Break thread: 1126
# Break value: 2508

Does any of you have an idea where this big max. latency comes from?

Matthias

On 01/01/2014 05:37 PM, Matthias Fuchs wrote:
> Hi,
> 
> I did a setup with 3.12.6-rt9 kernel on a Beaglebone board
> with an TI AM335x CPU running at fixed 720MHz. The kernel uses the 
> omap2plus_defconfig configuration that comes with this kernel with 
> additional CONFIG_PREEMPT_RT_FULL switched on.
> 
> I am observing some strange max. latencies when comparing with kernel 
> 3.2.45-rt66. The results of a similiar system can be found on the OSADL lab
> site (https://www.osadl.org/Latency-plot-of-system-in-rack-7-slot.qa-latencyplot-r7s5.0.html).
> 
> With "cyclictest -p99 -m -n -i200 -h400 -q -l10000000" I get
> ...
> # Min Latencies: 00013
> # Avg Latencies: 00062
> # Max Latencies: 04664
> ...
> 
> Also the latency does not differ much from that when doing a flood ping against 
> the system as simple stress.
> 
> 3.2.45-rt66 comes with a max. latency of 118us! So I expect something to be wrong with 3.12.6-rt9
> at least on armv7 or especially this device (max. lat. 4664us).
> 
> I also noticed an issue with the on-chip ethernet when CONFIG_PREEMPT_RT_FULL is
> switched on with this kernel:
> 
> I also noticed that the 3.12.6-rt9 with enabled 
> [    2.817024] net eth0: initializing cpsw version 1.12 (0)
> [    2.825269] net eth0: phy found : id is : 0x7c0f1
> [    2.830713] libphy: PHY 4a101000.mdio:01 not found
> [    2.835777] net eth0: phy 4a101000.mdio:01 not found on slave 1
> [   12.846394] Waiting up to 110 more seconds for network.
> [   22.846147] Waiting up to 100 more seconds for network.
> ...
> 
> Finally networking is fine. But I need to wait for 110 seconds :-)
> 
> Prior testing with 3.12.6-rt9 I did the same test with 3.12.5-rt7. Same results.
> But without CONFIG_PREEMPT_RT_FULL I do not get this bringup delay. I could not do this 
> test with rt9 because it does not build without CONFIG_PREEMPT_RT_FULL!
> 
> Any ideas?
> 
> Matthias
> --
> 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
> 

Re: 3.12.6-rt9 on AM335x (armv7)

[Tim Sander]

Hi
> after some chatting with Nicholas and being sure that I didn't do anything
> totally stupid I would like to provide my current kernel config and a trace
> generated by "cyclictest ... -b500".
> 
> kernel config -> https://www.dropbox.com/s/zsud0b77xoosjm1/config
> trace ->
> https://www.dropbox.com/s/5uf58oqo0qwcn4x/trace-cyclictest-2508us.txt
> 
> I still get max latencies of about 4000us on this TI AM335x system running
> 3.12.6-rt9 with timers-do-not-raise-softirq-unconditionally.patch reverse
> applied.
> 
> sched_rt_runtime_us and sched_rt_period_us are identical. The system is idle
> during the test. Rootfilesystem comes via NFS.
> 
> root@generic-armv7a:~# cat /proc/sys/kernel/sched_rt_runtime_us
> 1000000
> root@generic-armv7a:~# cat /proc/sys/kernel/sched_rt_period_us
> 1000000
> 
> root@generic-armv7a:~# uname -a
> Linux generic-armv7a 3.12.6-rt9-dirty #3 SMP PREEMPT RT Sat Jan 4 23:01:19
> CET 2014 armv7l GNU/Linux
> 
> root@generic-armv7a:~# ~/cyclictest -p99 -m -n -i200 -h400 -q -l100000 -b
> 500 # /dev/cpu_dma_latency set to 0us
> INFO: debugfs mountpoint: /sys/kernel/debug/tracing/
> could not set ftrace_enabled to 0
> could not set tracing_max_latency to 0
> # Histogram
> ...
> # Total: 000018604
> # Min Latencies: 00024
> # Avg Latencies: 00158
> # Max Latencies: 02508
Wohaa, thats bad for a latency patched kernel. Have you disabled 
powermanagement? I have an older rt patched kernel and it was not too good.
If i remember correctly it was between 100-200µs latency. But thats
far better than this. You could also load the system with hackbench, if its 
the idle pm than latency would get better.

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

Re: 3.12.6-rt9 on AM335x (armv7)

[Matthias Fuchs]

Hi Tim,

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.

Matthias

On 01/07/2014 09:38 AM, Tim Sander wrote:
> Hi
>> after some chatting with Nicholas and being sure that I didn't do anything
>> totally stupid I would like to provide my current kernel config and a trace
>> generated by "cyclictest ... -b500".
>>
>> kernel config -> https://www.dropbox.com/s/zsud0b77xoosjm1/config
>> trace ->
>> https://www.dropbox.com/s/5uf58oqo0qwcn4x/trace-cyclictest-2508us.txt
>>
>> I still get max latencies of about 4000us on this TI AM335x system running
>> 3.12.6-rt9 with timers-do-not-raise-softirq-unconditionally.patch reverse
>> applied.
>>
>> sched_rt_runtime_us and sched_rt_period_us are identical. The system is idle
>> during the test. Rootfilesystem comes via NFS.
>>
>> root@generic-armv7a:~# cat /proc/sys/kernel/sched_rt_runtime_us
>> 1000000
>> root@generic-armv7a:~# cat /proc/sys/kernel/sched_rt_period_us
>> 1000000
>>
>> root@generic-armv7a:~# uname -a
>> Linux generic-armv7a 3.12.6-rt9-dirty #3 SMP PREEMPT RT Sat Jan 4 23:01:19
>> CET 2014 armv7l GNU/Linux
>>
>> root@generic-armv7a:~# ~/cyclictest -p99 -m -n -i200 -h400 -q -l100000 -b
>> 500 # /dev/cpu_dma_latency set to 0us
>> INFO: debugfs mountpoint: /sys/kernel/debug/tracing/
>> could not set ftrace_enabled to 0
>> could not set tracing_max_latency to 0
>> # Histogram
>> ...
>> # Total: 000018604
>> # Min Latencies: 00024
>> # Avg Latencies: 00158
>> # Max Latencies: 02508
> Wohaa, thats bad for a latency patched kernel. Have you disabled 
> powermanagement? I have an older rt patched kernel and it was not too good.
> If i remember correctly it was between 100-200µs latency. But thats
> far better than this. You could also load the system with hackbench, if its 
> the idle pm than latency would get better.
> 
> 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

Re: 3.12.6-rt9 on AM335x (armv7)

[Tim Sander]

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

Re: 3.12.6-rt9 on AM335x (armv7)

[Pavel Vasilyev]

[-- Attachment #1: Type: text/plain, Size: 611 bytes --]

08.01.2014 02:58, Tim Sander пишет:

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

On my Intel Atom D425, latency around 25-30 µs (but peaks upto 5000 µs :/ )

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


-- 

                                                         Pavel.


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 836 bytes --]

Re: 3.12.6-rt9 on AM335x (armv7)

[Matthias Fuchs]

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

Re: 3.12.6-rt9 on AM335x (armv7)

[Matthias Fuchs]

Hmm, on Intel it might be an SMI-Issue.

Matthias

On 08.01.2014 00:46, Pavel Vasilyev wrote:
> 08.01.2014 02:58, Tim Sander пишет:
> 
>> 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.
> 
> On my Intel Atom D425, latency around 25-30 µs (but peaks upto 5000 µs :/ )
> 
>>
>> 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. 
>>
> 
> 

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

Re: 3.12.6-rt9 on AM335x (armv7)

[Sebastian Andrzej Siewior]

* Matthias Fuchs | 2014-01-08 09:06:53 [+0100]:

>Hi Tim,
Hi Matthias,

>I already linked to trace for a 2508us run in a previous post. Here is the
>most interesting section. A added two comments:

Do you see this also without runtime-pm? Now that I think about it, I
remember that I disabled it in my config a while ago because they were
taking sleeping locks in hard irq context. Not sure if this is still the
case.

Sebastian