3.12.6-rt9 on AM335x (armv7)

DISCUSSION Matthias Fuchs 4 participants 9 messages Jan 1, 2014 – Feb 7, 2014

Share & tools

Matthias Fuchs

author

2014-01-01 16:43 UTC #0 lore raw

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

Matthias Fuchs

author

2014-01-06 19:48 UTC #1 lore raw

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

Quoted 50 lines · 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
--
To unsubscribe from this list: send the line "unsubscribe linux-rt-users" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Tim Sander

2014-01-07 08:45 UTC #2 lore raw

Quoted 24 lines

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

Quoted 11 lines

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 [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Matthias Fuchs

author

2014-01-07 21:20 UTC #3 lore raw

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

Quoted 42 lines · Tim Sander

Hi
Quoted 24 lines
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
Quoted 11 lines
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.

Quoted 8 lines

Best regards
Tim
--
To unsubscribe from this list: send the line "unsubscribe linux-rt-users" in the body of a message to [email protected]
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 [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Tim Sander

2014-01-07 22:57 UTC #4 lore raw

Hi Matthias

Quoted 11 lines

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

Quoted 4 lines

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 [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Pavel Vasilyev

2014-01-07 23:47 UTC #5 lore raw

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

Quoted 3 lines

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 :/ )

Quoted 7 lines

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.

Signature · 1 line

                                                         Pavel.

Matthias Fuchs

author

2014-01-08 08:08 UTC #6 lore raw

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

Matthias

Quoted 17 lines · Pavel Vasilyev

08.01.2014 02:58, Tim Sander пишет:
Quoted 3 lines
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 :/ )
Quoted 7 lines
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 [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Matthias Fuchs

author

2014-01-08 08:06 UTC #7 lore raw

In reply to Tim Sander

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

Quoted 26 lines · Tim Sander

Hi Matthias
Quoted 11 lines
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
...
Quoted 4 lines
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.

Quoted 7 lines

Best regards
Tim
--
To unsubscribe from this list: send the line "unsubscribe linux-rt-users" in the body of a message to [email protected]
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 [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Sebastian Andrzej Siewior

2014-02-07 16:07 UTC #8 lore raw

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

Hi Tim,

Hi Matthias,

Quoted 2 lines

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