Dear experts,
I had a 4.14.4 kernel with its rtpatch running on a dual-core arm64
device, the desktop is ubuntu.
In general, the max latency of cyclictest is around 50us in empty load
which is acceptable. However, if i open a firefox duing cyclictest is
running, the max latency becomes higher up to 200us.
I tried to use ftrace to debug this issue,"cyclictest -p 90 -m -c 0 -i
10 -n -h 100 -q -l 10000000 -b 80", "-b 80" means enable ftrace event
and terminate cyclictest when latency is higher than 80us.
Here is a piece of log:
6034916919us+: cpu_idle: state=1 cpu_id=1
6034916981us+: hrtimer_cancel: hrtimer=ffffff8012663dc8
6034916994us+: sched_waking: comm=cyclictest pid=2321 prio=9 target_cpu=001
6034917032us+: cpu_idle: state=4294967295 cpu_id=1
6034917044us+: hrtimer_start: hrtimer=ffffffc07ffd5960
function=tick_sched_timer expires=6034920000000
softexpires=6034920000000 mode=ABS|PINNED
6034917066us+: sys_clock_nanosleep -> 0x0
In this case, I can only see it's stalled in some points but i could'n
find what happens, in other words, the root cause of the latency.
Is there any better way to debug this issue? I guess some of you might
meet the same issue, how did you approach to the root cause? I would
appreciate it so much if you could give me some advice, many thanks.
Best regards,
/Song
============================================================
Here is the log for reference:
<idle>-0 1d..h1.. 6034916878us : irq_handler_entry: irq=3
name=arch_timer -- this is a normal routine
<idle>-0 1d..h2.. 6034916879us : hrtimer_cancel:
hrtimer=ffffff8012663dc8
<idle>-0 1d..h1.. 6034916879us : hrtimer_expire_entry:
hrtimer=ffffff8012663dc8 function=hrtimer_wakeup now=6034916525493
<idle>-0 1d..h2.. 6034916880us : sched_waking: comm=cyclictest
pid=2321 prio=9 target_cpu=001
<idle>-0 1dn.h3.. 6034916882us : sched_wakeup: comm=cyclictest
pid=2321 prio=9 target_cpu=001
<idle>-0 1dn.h1.. 6034916883us : hrtimer_expire_exit:
hrtimer=ffffff8012663dc8
<idle>-0 1dn.h1.. 6034916884us : irq_handler_exit: irq=3
ret=handled
<idle>-0 1.n..1.. 6034916886us : cpu_idle: state=4294967295
cpu_id=1
<idle>-0 1dn..2.. 6034916888us : hrtimer_cancel:
hrtimer=ffffffc07ffd5960
<idle>-0 1dn..2.. 6034916890us : hrtimer_start:
hrtimer=ffffffc07ffd5960 function=tick_sched_timer expires=6034920000000
softexpires=6034920000000 mode=ABS|PINNED
<idle>-0 1dn..1.. 6034916891us : rcu_utilization: Start context
switch
<idle>-0 1dn..1.. 6034916892us : rcu_utilization: End context
switch
<idle>-0 1d...2.. 6034916894us : sched_switch:
prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==>
next_comm=cyclictest next_pid=2321 next_prio=9
cyclicte-2321 1....... 6034916897us : kfree:
call_site=ffffff80081501f0 ptr= (null)
cyclicte-2321 1....... 6034916898us : sys_exit: NR 115 = 0
cyclicte-2321 1....1.. 6034916898us : sys_clock_nanosleep -> 0x0
cyclicte-2321 1....... 6034916902us : sys_enter: NR 115 (1, 1,
7fbd20b448, 0, 0, 7fbd20be00)
cyclicte-2321 1....1.. 6034916903us :
sys_clock_nanosleep(which_clock: 1, flags: 1, rqtp: 7fbd20b448, rmtp: 0)
cyclicte-2321 1....... 6034916904us : hrtimer_init:
hrtimer=ffffff8012663dc8 clockid=CLOCK_MONOTONIC mode=ABS
cyclicte-2321 1d...1.. 6034916906us : hrtimer_start:
hrtimer=ffffff8012663dc8 function=hrtimer_wakeup expires=6034916622448
softexpires=6034916622448 mode=ABS
cyclicte-2321 1d...1.. 6034916907us : rcu_utilization: Start context
switch
cyclicte-2321 1d...1.. 6034916908us : rcu_utilization: End context switch
cyclicte-2321 1d...2.. 6034916911us : sched_switch:
prev_comm=cyclictest prev_pid=2321 prev_prio=9 prev_state=S ==>
next_comm=swapper/1 next_pid=0 next_prio=120
<idle>-0 1d...1.. 6034916915us : tick_stop: success=1
dependency=NONE
<idle>-0 1d...2.. 6034916916us : hrtimer_cancel:
hrtimer=ffffffc07ffd5960
<idle>-0 1d...2.. 6034916917us : hrtimer_start:
hrtimer=ffffffc07ffd5960 function=tick_sched_timer expires=6035010000000
softexpires=6035010000000 mode=ABS|PINNED
<idle>-0 1d...1.. 6034916919us+: cpu_idle: state=1 cpu_id=1
--(1)
<idle>-0 1d..h1.. 6034916977us : irq_handler_entry: irq=3
name=arch_timer
<idle>-0 1d..h2.. 6034916981us+: hrtimer_cancel:
hrtimer=ffffff8012663dc8 --(2)
<idle>-0 1d..h1.. 6034916993us : hrtimer_expire_entry:
hrtimer=ffffff8012663dc8 function=hrtimer_wakeup now=6034916628193
<idle>-0 1d..h2.. 6034916994us+: sched_waking: comm=cyclictest
pid=2321 prio=9 target_cpu=001 --(3)
<idle>-0 1dn.h3.. 6034917016us : sched_wakeup: comm=cyclictest
pid=2321 prio=9 target_cpu=001
<idle>-0 1dn.h1.. 6034917016us : hrtimer_expire_exit:
hrtimer=ffffff8012663dc8
<idle>-0 1dn.h1.. 6034917026us : irq_handler_exit: irq=3
ret=handled
<idle>-0 1.n..1.. 6034917032us+: cpu_idle: state=4294967295
cpu_id=1 --(4)
<idle>-0 1dn..2.. 6034917043us : hrtimer_cancel:
hrtimer=ffffffc07ffd5960
<idle>-0 1dn..2.. 6034917044us+: hrtimer_start:
hrtimer=ffffffc07ffd5960 function=tick_sched_timer expires=6034920000000
softexpires=6034920000000 mode=ABS|PINNED --(5)
<idle>-0 1dn..1.. 6034917056us : rcu_utilization: Start context
switch
<idle>-0 1dn..1.. 6034917057us : rcu_utilization: End context
switch
<idle>-0 1d...2.. 6034917062us : sched_switch:
prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==>
next_comm=cyclictest next_pid=2321 next_prio=9
cyclicte-2321 1....... 6034917065us : kfree:
call_site=ffffff80081501f0 ptr= (null)
cyclicte-2321 1....... 6034917066us : sys_exit: NR 115 = 0
cyclicte-2321 1....1.. 6034917066us+: sys_clock_nanosleep -> 0x0
--(5)
cyclicte-2321 1....... 6034917142us : sys_enter: NR 64 (5,
7fbd20c500, 1f, 7fbd20bf08, 2, 7fbd20be00)
cyclicte-2321 1....1.. 6034917143us : sys_write(fd: 5, buf:
7fbd20c500, count: 1f)
cyclicte-2321 1....... 6034917151us : tracing_mark_write: hit latency
threshold (91 > 80)
cyclicte-2321 1....... 6034917155us : kfree:
call_site=ffffff80081501f0 ptr= (null)
cyclicte-2321 1....... 6034917156us : sys_exit: NR 64 = 31
cyclicte-2321 1....1.. 6034917157us : sys_write -> 0x1f
cyclicte-2321 1....... 6034917159us : sys_enter: NR 64 (4, 408650, 1,
7fbd20bf08, 2, 7fbd20be00)
cyclicte-2321 1....1.. 6034917160us : sys_write(fd: 4, buf: 408650,
count: 1)
