Hi,
I'm trying to get an idea why we would be spending a whole millisecond running
the cascade() routine.
This is on a CentOS 7 kernel (config modified as per below) so feel free to send
me off to the other support fora if you like.
Running cyclictest gave the following:
cyclicte-29932 14d..2 282141264us : pick_next_task_idle <-__schedule
<idle>-0 14d..1 282149191us : do_softirq <-irq_exit
<idle>-0 14d..1 282149192us : __do_softirq <-call_softirq
<idle>-0 14d..1 282149192us : msecs_to_jiffies <-__do_softirq
<idle>-0 14..s1 282149192us : run_timer_softirq <-__do_softirq
<idle>-0 14..s1 282149192us : _raw_spin_lock_irq <-run_timer_softirq
<idle>-0 14d.s2 282149193us : cascade <-run_timer_softirq
(1167 similar lines removed)
<idle>-0 14d.s2 282150286us : cascade <-run_timer_softirq
<idle>-0 14d.s2 282150286us : __internal_add_timer <-cascade
<idle>-0 14d.s2 282150287us : cascade <-run_timer_softirq
(20 similar lines removed)
<idle>-0 14d.s2 282150305us : cascade <-run_timer_softirq
<idle>-0 14d.s2 282150305us : __internal_add_timer <-cascade
<idle>-0 14d.s2 282150306us : _raw_spin_unlock_irq <-run_timer_softirq
cyclicte-29932 14...1 282150347us : tracing_mark_write: hit latency threshold
(1100 > 1000)
I vaguely understand what cascade() is doing, but it doesn't make any sense to
me that it would do it for over a millisecond. Is it coincidence that
cascade() is called roughly every microsecond for just over a millisecond?
Overall the latency is actually pretty reasonable except for these sporadic
glitches:
/home/wrsroot/cyclictest -S -m -p 80 -l 1000000
# /dev/cpu_dma_latency set to 0us
policy: fifo: loadavg: 4.08 4.07 4.08 5/371 6845
T: 0 ( 5060) P:80 I:1000 C:1000000 Min: 1 Act: 2 Avg: 1 Max: 58
T: 1 ( 5061) P:80 I:1500 C: 666670 Min: 1 Act: 1 Avg: 1 Max: 3
T: 2 ( 5062) P:80 I:2000 C: 500002 Min: 2 Act: 2 Avg: 2 Max: 4
T: 3 ( 5063) P:80 I:2500 C: 400001 Min: 1 Act: 2 Avg: 1 Max: 10
T: 4 ( 5064) P:80 I:3000 C: 333333 Min: 1 Act: 2 Avg: 1 Max: 8
T: 5 ( 5065) P:80 I:3500 C: 285711 Min: 1 Act: 2 Avg: 2 Max: 1011
T: 6 ( 5066) P:80 I:4000 C: 249996 Min: 1 Act: 2 Avg: 2 Max: 1015
T: 7 ( 5067) P:80 I:4500 C: 222219 Min: 1 Act: 2 Avg: 2 Max: 17
T: 8 ( 5068) P:80 I:5000 C: 199996 Min: 1 Act: 1 Avg: 1 Max: 3
T: 9 ( 5069) P:80 I:5500 C: 181814 Min: 2 Act: 2 Avg: 2 Max: 5
T:10 ( 5070) P:80 I:6000 C: 166662 Min: 1 Act: 2 Avg: 2 Max: 5
T:11 ( 5071) P:80 I:6500 C: 153841 Min: 1 Act: 2 Avg: 2 Max: 8
T:12 ( 5072) P:80 I:7000 C: 142853 Min: 1 Act: 2 Avg: 2 Max: 1008
T:13 ( 5073) P:80 I:7500 C: 133329 Min: 2 Act: 3 Avg: 2 Max: 5
T:14 ( 5074) P:80 I:8000 C: 124996 Min: 1 Act: 2 Avg: 2 Max: 7
T:15 ( 5075) P:80 I:8500 C: 117643 Min: 1 Act: 2 Avg: 2 Max: 6
Kernel config has been modified as follows:
CONFIG_RCU_BOOST=y
CONFIG_DEBUG_PREEMPT=n
CONFIG_PROVE_RCU_DELAY=n
CONFIG_RCU_CPU_STALL_VERBOSE=n
CONFIG_PREEMPT_TRACER=n
CONFIG_RCU_BOOST_PRIO=1
CONFIG_RCU_BOOST_DELAY=500
Chris
