* 3.12.6-rt9 on AM335x (armv7) @ 2014-01-01 16:37 Matthias Fuchs 2014-01-06 19:48 ` Matthias Fuchs 0 siblings, 1 reply; 9+ messages in thread From: Matthias Fuchs @ 2014-01-01 16:37 UTC (permalink / raw) To: linux-rt-users 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 ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: 3.12.6-rt9 on AM335x (armv7) 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 0 siblings, 1 reply; 9+ messages in thread From: Matthias Fuchs @ 2014-01-06 19:48 UTC (permalink / raw) To: linux-rt-users 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 > ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: 3.12.6-rt9 on AM335x (armv7) 2014-01-06 19:48 ` Matthias Fuchs @ 2014-01-07 8:38 ` Tim Sander 2014-01-07 21:20 ` Matthias Fuchs 0 siblings, 1 reply; 9+ messages in thread From: Tim Sander @ 2014-01-07 8:38 UTC (permalink / raw) To: Matthias Fuchs; +Cc: linux-rt-users 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 ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: 3.12.6-rt9 on AM335x (armv7) 2014-01-07 8:38 ` Tim Sander @ 2014-01-07 21:20 ` Matthias Fuchs 2014-01-07 22:58 ` Tim Sander 0 siblings, 1 reply; 9+ messages in thread From: Matthias Fuchs @ 2014-01-07 21:20 UTC (permalink / raw) To: Tim Sander; +Cc: linux-rt-users 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 ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: 3.12.6-rt9 on AM335x (armv7) 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:06 ` Matthias Fuchs 0 siblings, 2 replies; 9+ messages in thread From: Tim Sander @ 2014-01-07 22:58 UTC (permalink / raw) To: Matthias Fuchs; +Cc: linux-rt-users 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 ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: 3.12.6-rt9 on AM335x (armv7) 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 1 sibling, 1 reply; 9+ messages in thread From: Pavel Vasilyev @ 2014-01-07 23:46 UTC (permalink / raw) To: Tim Sander, Matthias Fuchs; +Cc: linux-rt-users [-- 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 --] ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: 3.12.6-rt9 on AM335x (armv7) 2014-01-07 23:46 ` Pavel Vasilyev @ 2014-01-08 8:08 ` Matthias Fuchs 0 siblings, 0 replies; 9+ messages in thread From: Matthias Fuchs @ 2014-01-08 8:08 UTC (permalink / raw) To: pavel, Tim Sander; +Cc: linux-rt-users 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 ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: 3.12.6-rt9 on AM335x (armv7) 2014-01-07 22:58 ` Tim Sander 2014-01-07 23:46 ` Pavel Vasilyev @ 2014-01-08 8:06 ` Matthias Fuchs 2014-02-07 16:07 ` Sebastian Andrzej Siewior 1 sibling, 1 reply; 9+ messages in thread From: Matthias Fuchs @ 2014-01-08 8:06 UTC (permalink / raw) To: Tim Sander; +Cc: linux-rt-users 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 ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: 3.12.6-rt9 on AM335x (armv7) 2014-01-08 8:06 ` Matthias Fuchs @ 2014-02-07 16:07 ` Sebastian Andrzej Siewior 0 siblings, 0 replies; 9+ messages in thread From: Sebastian Andrzej Siewior @ 2014-02-07 16:07 UTC (permalink / raw) To: Matthias Fuchs; +Cc: Tim Sander, linux-rt-users * 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 ^ permalink raw reply [flat|nested] 9+ messages in thread
end of thread, other threads:[~2014-02-07 16:07 UTC | newest] Thread overview: 9+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 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 2014-02-07 16:07 ` Sebastian Andrzej Siewior
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).