wakeup tracer是用来追踪进程从被唤醒到真正得到执行之间的最大延迟。
| tracer | 说明 |
|---|---|
| wakeup | 追踪最高优先级普通任务从获得调度到被唤醒的最大延迟时间。 |
| wakeup_rt | 追踪RT类型的任务从获得调度到被唤醒的最大延迟时间。 |
| wakeup_dl | 追踪Deadline类型的任务从获得调度到被唤醒的最大延迟时间。 |
1、wakeup tracer
# cat wakeup.sh
#
cd /sys/kernel/debug/tracing/
echo 0 > trace
echo 0 > options/function-trace
echo wakeup > current_tracer
echo 1 > tracing_on
echo 0 > tracing_max_latency
chrt -f 5 sleep 1
echo 0 > tracing_on
cat trace
echo nop > current_tracer
输出：sleep进程 latency: 1002 us，rt_prio:5
# ./wakeup.sh
# tracer: wakeup
#
# wakeup latency trace v1.1.5 on 5.0.0+
# --------------------------------------------------------------------
# latency: 1002 us, #4/4, CPU#3 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
# -----------------
# | task: sleep-20005 (uid:0 nice:0 policy:1 rt_prio:5)
# -----------------
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
<idle>-0 3dNh. 24us+: 0:120:R + [003] 20005: 94:R sleep
<idle>-0 3dNh. 102us!: ttwu_do_activate <-ttwu_queue
<idle>-0 3d... 921us+: __schedule <-schedule_idle
<idle>-0 3d... 975us : 0:120:R ==> [003] 20005: 94:R sleep
2、wakeup tracer + function tracer
options中的function-trace，可以在latency tracers中，同时使能function tracing，很详尽的打印出整个过程中的函数调用。
# cat wakeup_function.sh
#
cd /sys/kernel/debug/tracing/
echo 0 > trace
echo 1 > options/function-trace
echo wakeup > current_tracer
echo 1 > tracing_on
echo 0 > tracing_max_latency
chrt -f 5 sleep 1
echo 0 > tracing_on
cat trace
echo 0 > options/function-trace
echo nop > current_tracer
# ./wakeup_function.sh
# tracer: wakeup
#
# wakeup latency trace v1.1.5 on 5.0.0+
# --------------------------------------------------------------------
# latency: 18434 us, #529/529, CPU#0 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
# -----------------
# | task: sleep-18042 (uid:0 nice:0 policy:1 rt_prio:5)
# -----------------
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
modprobe-18048 0dNh. 1015us#: 18048:120:R + [000] 18042: 94:R sleep
modprobe-18048 0dNh. 4341us!: ttwu_do_activate <-ttwu_queue
modprobe-18048 0dNh. 5108us!: task_woken_rt <-ttwu_do_wakeup
modprobe-18048 0dNh. 5367us+: update_avg <-ttwu_do_wakeup
modprobe-18048 0dNh. 5385us+: ttwu_stat <-try_to_wake_up
modprobe-18048 0dNh. 5406us+: __next_base <-__hrtimer_run_queues
modprobe-18048 0dNh. 5421us+: __next_base <-__hrtimer_run_queues
modprobe-18048 0dNh. 5434us+: __hrtimer_get_next_event <-hrtimer_interrupt
modprobe-18048 0dNh. 5445us+: __hrtimer_next_event_base <-__hrtimer_get_next_event
......
......
......
modprobe-18048 0dN.. 16888us+: _pick_next_task_rt <-pick_next_task_rt
modprobe-18048 0dN.. 16930us!: pick_next_rt_entity <-_pick_next_task_rt
modprobe-18048 0dN.. 17173us!: dequeue_pushable_task <-pick_next_task_rt
modprobe-18048 0dN.. 17336us+: update_rt_rq_load_avg <-pick_next_task_rt
modprobe-18048 0dN.. 17350us+: decay_load <-update_rt_rq_load_avg
modprobe-18048 0dN.. 17362us+: decay_load <-update_rt_rq_load_avg
modprobe-18048 0dN.. 17373us+: decay_load <-update_rt_rq_load_avg
modprobe-18048 0dN.. 17384us+: __accumulate_pelt_segments <-update_rt_rq_load_avg
modprobe-18048 0dN.. 17395us+: decay_load <-__accumulate_pelt_segments
modprobe-18048 0dN.. 17406us!: decay_load <-__accumulate_pelt_segments
modprobe-18048 0d... 17980us!: __schedule <-schedule
modprobe-18048 0d... 18101us : 18048:120:R ==> [000] 18042: 94:R sleep
3、wakeup tracer + event
如果“wakeup tracer” + “function tracer”方式会带来很多开销，但是你又想知道中间发生了什么，可以使用折中的方法：“wakeup tracer” + “trace event”：
cat wakeup_event.sh
#
cd /sys/kernel/debug/tracing/
echo 0 > trace
echo 0 > options/function-trace
echo wakeup > current_tracer
# 需要更全的log可以直接把events/enable使能
echo 0 > events/enable
echo 1 > events/sched/enable
echo 1 > events/timer/enable
echo 1 > tracing_on
echo 0 > tracing_max_latency
chrt -f 5 sleep 1
echo 0 > tracing_on
cat trace
echo nop > current_tracer
echo 0 > events/sched/enable
echo 0 > events/timer/enable
# ./wakeup_event.sh
# tracer: wakeup
#
# wakeup latency trace v1.1.5 on 5.0.0+
# --------------------------------------------------------------------
# latency: 2868 us, #12/12, CPU#1 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
# -----------------
# | task: sleep-19231 (uid:0 nice:0 policy:1 rt_prio:5)
# -----------------
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
modprobe-19239 1dNh. 147us!: 19239:120:R + [001] 19231: 94:R sleep
modprobe-19239 1dNh. 732us!: ttwu_do_activate <-ttwu_queue
modprobe-19239 1dNh. 1133us!: sched_wakeup: comm=sleep pid=19231 prio=94 target_cpu=001
modprobe-19239 1dNh. 1328us+: hrtimer_expire_exit: hrtimer=000000006f328cc8
modprobe-19239 1dNh. 1344us+: hrtimer_cancel: hrtimer=00000000b24cec9a
modprobe-19239 1dNh. 1362us+: hrtimer_expire_entry: hrtimer=00000000b24cec9a function=tick_sch
ed_timer now=11751032051187
modprobe-19239 1dNh. 1426us+: sched_stat_runtime: comm=modprobe pid=19239 runtime=5677472 [ns]
vruntime=2853666144906 [ns]
modprobe-19239 1dNh. 1440us+: sched_stat_minvruntime: comm=modprobe pid=19239 minvruntime=2853
666144906 [ns]
modprobe-19239 1dNh. 1491us+: hrtimer_expire_exit: hrtimer=00000000b24cec9a
modprobe-19239 1dNh. 1505us!: hrtimer_start: hrtimer=00000000b24cec9a function=tick_sched_time
r expires=11751036000000 softexpires=11751036000000 mode=ABS
modprobe-19239 1d... 2471us+: __schedule <-schedule
modprobe-19239 1d... 2548us : 19239:120:R ==> [001] 19231: 94:R sleep
