静态tracepoint预埋在内核的关键位置, 通过这些预埋的tracepoint, 可以比较容易梳理出相关模块的框架及主要流程. 相比于直接钻到scheduler的实现细节中去, 我们先通过tracepoint及其相关工具去理解实现背后的逻辑, 细节总是不停变化, 而分析方法往往相对固定, 也更容易沉淀下来.
通过perf命令可以列出系统所有的tracepoint:
$ sudo perf list | grep sched:
sched:sched_kthread_stop [Tracepoint event]
sched:sched_kthread_stop_ret [Tracepoint event]
sched:sched_migrate_task [Tracepoint event]
sched:sched_move_numa [Tracepoint event]
sched:sched_pi_setprio [Tracepoint event]
sched:sched_process_exec [Tracepoint event]
sched:sched_process_exit [Tracepoint event]
sched:sched_process_fork [Tracepoint event]
sched:sched_process_free [Tracepoint event]
sched:sched_process_hang [Tracepoint event]
sched:sched_process_wait [Tracepoint event]
sched:sched_stat_blocked [Tracepoint event]
sched:sched_stat_iowait [Tracepoint event]
sched:sched_stat_runtime [Tracepoint event]
sched:sched_stat_sleep [Tracepoint event]
sched:sched_stat_wait [Tracepoint event]
sched:sched_stick_numa [Tracepoint event]
sched:sched_swap_numa [Tracepoint event]
sched:sched_switch [Tracepoint event]
sched:sched_wait_task [Tracepoint event]
sched:sched_wake_idle_without_ipi [Tracepoint event]
sched:sched_wakeup [Tracepoint event]
sched:sched_wakeup_new [Tracepoint event]
sched:sched_waking [Tracepoint event]sched_switch
sched_wakeup
sched_waking
sched_migrate_task
该类型的tracepoint额外带有delay的时间
sched_stat_blocked
sched_stat_iowait
sched_stat_runtime
sched_stat_sleep
sched_stat_wait
sched_kthread_stop, sched_kthread_stop_ret. 在kthread_stop时产生, 一般不是scheduler性能调试的重点
sched_move_numa, sched_swap_numa, sched_stick_numa. NUMA相关, 从性能分析角度上看, 它们必须在我们的checklist中, 一定程度可以把它们当作是异常(USE)
sched_pi_setprio. 用于实现rt_mutex的优先级继承, 比如用在futex上.
sched_process_exec, sched_process_exit, sched_process_fork, sched_process_free. 进程相关的主要事件
sched_process_hang. 进程hang
sched_process_wait. 等子进程的状态变化
sched_wait_task. 等待其他任务unschedule, 比如用于ptrace.
sched_wake_idle_without_ipi. 如果target cpu上的任务设置了TIF_POLLING_NRFLAG标记 (只有idle进程会设置), 这样idle进程自己去poll TIF_NEED_RESCHED, 这样就不用发ipi中断去通知了
sched_wakeup_new. 同sched_wakeup, 但针对的是新创建的任务
当调度器决定schedule另一个task运行的时候, 也就是任务切换的时候, 会触发该tracepoint. 核心逻辑如下:
__schedule
next = pick_next_task(rq, prev, &rf);
if (likely(prev != next))
trace_sched_switch(preempt, prev, next);
rq = context_switch(rq, prev, next, &rf);我们稍微关注以下context_switch里面的切栈操作:
switch_to(prev, next, prev);
prev = __switch_to_asm((prev), (next)));
pushq %rbp, %rbx, %r12, %13, %14, %15 /* Save callee-saved registers */
movq %rsp, TASK_threadsp(%rdi)
movq TASK_threadsp(%rsi), %rsp /* switch stack */
popq %15, %14, %13, %12, %rbx, %rbp /* restore callee-saved registers */
jmp __switch_to
struct task_struct *__switch_to(struct task_struct *prev, struct task_struct *next);注意这里的__switch_to_asm传入了prev, 又返回了prev, 看似没有必要, 但是因为context_switch函数涉及到2个task, 在切栈之前是A, 切栈之后就变成B了
对于切栈前的task A来说, prev指的就是A本身
对于切栈后的task B来说, prev指的还必须是A, switch到B之后还需要更新A的信息. 这里通过函数调用巧妙解决了2个task之间变量的传递.
ULK引入3个task来解释switch_to, 我认为反而复杂了.
内核会通过try_to_wake_up把任务唤醒, 这会涉及到这sched_wakeup和sched_waking两个tracepoint.
try_to_wake_up
if (p == current) ...
trace_sched_waking(p);
if (p->on_rq && ttwu_remote(p, wake_flags)) goto unlock;
rq = __task_rq_lock(p, &rf);
if (task_on_rq_queued(p))
ret = 1;
ttwu_do_wakeup(rq, p, wake_flags, &rf);
check_preempt_curr(rq, p, wake_flags);
p->state = TASK_RUNNING;
trace_sched_wakeup(p);
p->state = TASK_WAKING;
cpu = select_task_rq(p, p->wake_cpu, SD_BALANCE_WAKE, wake_flags);
if (task_cpu(p) != cpu)
wake_flags |= WF_MIGRATED;
set_task_cpu(p, cpu);
ttwu_queue(p, cpu, wake_flags);
return ttwu_queue_remote(p, cpu, wake_flags); if (sched_feat(TTWU_QUEUE) && !cpus_share_cache(smp_processor_id(), cpu))
if (llist_add(&p->wake_entry, &cpu_rq(cpu)->wake_list))
smp_send_reschedule(cpu); if (!set_nr_if_polling(rq->idle))
scheduler_ipi
sched_ttwu_pending();
ttwu_do_activate(rq, p, p->sched_remote_wakeup ? WF_MIGRATED : 0, &rf);
rq = cpu_rq(cpu);
rq_lock(rq, &rf);
ttwu_do_activate(rq, p, wake_flags, &rf);
activate_task(rq, p, en_flags);
enqueue_task(rq, p, flags);
for_each_sched_entity(se)
break; if (se->on_rq)
enqueue_entity(cfs_rq, se, flags);
update_curr(cfs_rq);
update_stats_enqueue(cfs_rq, se, flags);
__enqueue_entity(cfs_rq, se); if (!curr)
se->on_rq = 1;
p->on_rq = TASK_ON_RQ_QUEUED;
ttwu_do_wakeup(rq, p, wake_flags, rf);
check_preempt_curr(rq, p, wake_flags);
p->state = TASK_RUNNING;
trace_sched_wakeup(p);上面需要关注的点:
可以唤醒current task
唤醒on_rq的task比较直接, 在sched_waking和sched_wakeup之间的时间非常短
当需要迁移到其他cpu时会有2种方案
通过ipi给target cpu发送中断, 在中断处理函数中完成wakeup的后面部分
直接在当前cpu上操作target cpu, 所以需要先执行rq_lock操作, 可能会有锁冲突
从上面可以看出, sched_waking和sched_wakeup在wakeup task过程中肯定都会发生, sched_waking事件在ttwu开始的时候触发, 而sched_wakeup在ttwu结束的时候触发. 一般情况下, 这2个tracepoint触发的时间非常靠近, 但是不排除中间会有较大gap.
从资源的角度看, 只有系统中存在多个同类资源(这里是cpu), 为了最大化资源利用率, 就会涉及到migration. 从性能角度看, 这个的影响是比较大的, 也是性能调试的时候必须关注的, migration有没有及时, migration会不会太多 (locality).
为了使用stat类型的tracepoint, 我们需要先enable.
# sysctl kernel.sched_schedstats
kernel.sched_schedstats = 0
# sysctl -w kernel.sched_schedstats=1
kernel.sched_schedstats = 1update_stats_dequeue
if (tsk->state & TASK_INTERRUPTIBLE)
__schedstat_set(se->statistics.sleep_start, rq_clock(rq_of(cfs_rq)));
if (tsk->state & TASK_UNINTERRUPTIBLE)
__schedstat_set(se->statistics.block_start, rq_clock(rq_of(cfs_rq)));
update_stats_enqueue
update_stats_enqueue_sleeper(cfs_rq, se); if (flags & ENQUEUE_WAKEUP)
if (sleep_start)
trace_sched_stat_sleep(tsk, delta);
if (block_start)
trace_sched_stat_iowait(tsk, delta); if (tsk->in_iowait)
trace_sched_stat_blocked(tsk, delta);stat_sleep用于记录TASK_INTERRUPTIBLE的时间
stat_blocked用于记录TASK_UNINTERRUPTIBLE的时间
stat_iowait用于iowait的场景, 这种情况下stat_iowait和stat_blocked值是一样的
stat_wait和上面的stat不一样的地方在于, stat_wait更反映调度器本身的执行情况.
update_stats_wait_start()
wait_start = rq_clock(rq_of(cfs_rq));
__schedstat_set(se->statistics.wait_start, wait_start);
update_stats_wait_end
delta = rq_clock(rq_of(cfs_rq)) - schedstat_val(se->statistics.wait_start);
trace_sched_stat_wait(p, delta); if (entity_is_task(se))wait的起始时间wait_start. 任务状态切到runnable, 但是不能马上在cpu上执行
task被抢占了, 那么wait_start就是抢占点. put_prev_entity并且prev->on_rq成立
task唤醒的时候, 从enqueue_entity进入
wait的结束时间
任务马上要在cpu上执行了, set_next_entity
任务enqueue后压根没能在该cpu上执行就被dequeue了, update_stats_dequeue
记录任务的执行时间, 包括runtime, vruntime
__schedule()的主要逻辑
if (!preempt && prev->state)
if (signal_pending_state(prev->state, prev))
prev->state = TASK_RUNNING;
else
deactivate_task(rq, prev, DEQUEUE_SLEEP | DEQUEUE_NOCLOCK);
p->on_rq = (flags & DEQUEUE_SLEEP) ? 0 : TASK_ON_RQ_MIGRATING;
dequeue_task(rq, p, flags);
p->sched_class->dequeue_task(rq, p, flags);
dequeue_entity(cfs_rq, se, flags);
update_stats_dequeue(cfs_rq, se, flags);
__dequeue_entity(cfs_rq, se); if (se != cfs_rq->curr) // 在move_queued_task中, moved task可能不是curr
rb_erase_cached(&se->run_node, &cfs_rq->tasks_timeline);
se->on_rq = 0;
next = pick_next_task(rq, prev, &rf);
fair_sched_class.pick_next_task(rq, prev, rf); // pick_next_task_fair
put_prev_task(rq, prev); if (prev)
put_prev_entity(cfs_rq, se);
if (prev->on_rq)
update_curr(cfs_rq);
update_stats_wait_start(cfs_rq, prev);
__enqueue_entity(cfs_rq, prev);
cfs_rq->curr = NULL;
se = pick_next_entity(cfs_rq, NULL);
set_next_entity(cfs_rq, se);
if (se->on_rq) // 什么时候不on_rq?
update_stats_wait_end(cfs_rq, se);
trace_sched_stat_wait(p, delta);
__dequeue_entity(cfs_rq, se); // 'current' is not kept within the tree.
update_stats_curr_start(cfs_rq, se);
se->exec_start = rq_clock_task(rq_of(cfs_rq));
cfs_rq->curr = se;
if (likely(prev != next))
trace_sched_switch(preempt, prev, next);
rq = context_switch(rq, prev, next, &rf);即使不是调度器的开发者, 有的时候也需要能够对调度器进行调试, 比如应用开发者或者系统管理员, 升级内核后性能退化, 修改线程模型后性能不满足预期等, 最终可能只需要动某个调度器的参数而已, 但是前提是能够定位到这个参数.
只要抓取sched:sched_switch一个tracepoint, 就可以抓到系统所有的切换事件, 以下perf sched map的输出:
前面每列代表一个cpu, 后面2列是事件发生的时间戳和任务缩写的映射
点(.)表示cpu在idle
星号(*)表示有事件发生
. . . *J0 . . 40302.714499 secs J0 => containerd:1125
. . . J0 . *K0 40302.714507 secs K0 => containerd:1094
. . . J0 . *. 40302.714515 secs
. . . *. . . 40302.714517 secs
. . . . *L0 . 40302.714522 secs L0 => containerd:1121
. . . . *. . 40302.714527 secs
. . . . . *K0 40302.714583 secs
. . . . . *. 40302.714586 secs
. . *M0 . . . 40302.738012 secs M0 => cron:911
. . *. . . . 40302.738043 secs
. . . . . *N0 40302.802649 secs N0 => kworker/5:0-eve:706
. . . . . *. 40302.802657 secs
. . . . *O0 . 40302.818889 secs O0 => chrome:1370该命令可以获得task的wait time, 特别地, 还能拿到sch delay. timehist统计的sch delay是通过sched_switch和sched_wakeup计算出来的, 而不是上面的stat_wait.
/*
* Explanation of delta-time stats:
*
* t = time of current schedule out event
* tprev = time of previous sched out event
* also time of schedule-in event for current task
* last_time = time of last sched change event for current task
* (i.e, time process was last scheduled out)
* ready_to_run = time of wakeup for current task
*
* -----|------------|------------|------------|------
* last ready tprev t
* time to run
*
* |-------- dt_wait --------|
* |- dt_delay -|-- dt_run --|
*
* dt_run = run time of current task
* dt_wait = time between last schedule out event for task and tprev
* represents time spent off the cpu
* dt_delay = time between wakeup and schedule-in of task
*/
time cpu task name wait time sch delay run time
[tid/pid] (msec) (msec) (msec)
--------------- ------ ------------------------------ --------- --------- ---------
43721.001384 [0001] 0.000 0.000 0.000
43721.001401 [0001] avahi-daemon[950] 0.000 0.000 0.017
43721.001451 [0000] 0.000 0.000 0.000
43721.001468 [0000] Chrome_IOThread[2401/2383] 0.000 0.000 0.016
43721.001516 [0004] 0.000 0.000 0.000 这里的delay同timehist的sch delay.
# perf sched latency -s max
-----------------------------------------------------------------------------------------------------------------
Task | Runtime ms | Switches | Average delay ms | Maximum delay ms | Maximum delay at |
-----------------------------------------------------------------------------------------------------------------
rcu_preempt:11 | 0.323 ms | 13 | avg: 0.020 ms | max: 0.141 ms | max at: 43721.824102 s
kworker/1:3-eve:10084 | 0.636 ms | 7 | avg: 0.047 ms | max: 0.141 ms | max at: 43721.716104 s
ThreadPoolForeg:(3) | 1.148 ms | 20 | avg: 0.012 ms | max: 0.139 ms | max at: 43721.797089 s
containerd:(7) | 1.863 ms | 46 | avg: 0.012 ms | max: 0.070 ms | max at: 43721.068446 s
gnome-shell:1612 | 2.517 ms | 16 | avg: 0.011 ms | max: 0.054 ms | max at: 43721.982652 s通过关联以下2个tracepoint, 我们可以得到任务sleep的时长及其对应的callchain
sched_iowait/sleep/blocked. 获得sleep的时长
sched_switch. 获得调用栈
commit 26a031e136f4f8dc82c64df48cca0eb3b5d3eb4f
Author: Andrew Vagin
Date: Tue Aug 7 16:56:04 2012 +0400
perf inject: Merge sched_stat_* and sched_switch events
You may want to know where and how long a task is sleeping. A callchain
may be found in sched_switch and a time slice in stat_iowait, so I add
handler in perf inject for merging this events.
My code saves sched_switch event for each process and when it meets
stat_iowait, it reports the sched_switch event, because this event
contains a correct callchain. By another words it replaces all
stat_iowait events on proper sched_switch events.这里列出一些调试的想法, 暂时没有整理和一一展开
性能调试要考虑工具的开销, 比如perf的开销是否会影响到应用的性能. 我们可以使用eBPF重写上面的perf的功能, eBPF因为能够在内核中直接聚合, 开销相比perf会小
虽然tracepoint能提供更多更完整的调试信息, 但是其他的统计工具比如schedstat等对调试也会有帮助, 很多时候只能用这些一直在搜集的信息, 而不是所有场景都能复现然后上去通过tracepoint搜集信息的
以上涉及的工具都还是文本界面的, 图形界面的工具会更有优势. 文本的好处是可以再加工, 图像的好处是更直观, 更容易发现问题
和scheduler相关的性能问题主要是两个方面, 一是怎么定位应用程序的off-cpu, 二是scheduler自身的影响, 都有一些相对固定的方法
有了这些tracepoint以及动态添加的kprobe, 我们很容易拿到应用程序schedule相关的信息, 比如在context switch in/out时收集信息, 就可以生成带callchain的off-cpu flamegraph
如果某个cpu忙应该看到什么现象, 我们可以去获取cpu runqueue的长度
如果task的某个函数执行时间过长, 我们可以检查它是在cpu上执行慢, 还是在等资源. 如果是调度不及时, 我们可以看到当时它runnable的时长, 以及其他cpu的状态
如果我们已经有了cpu视角和task视角, 我们看到大量cpu idle而只有某个task在跑, 那么一种合理的推测是该task是否阻塞其他task了
调试其实就是把很多现象关联起来, 也就是说孤立地去看一种现象往往收获不大. 一般来说我们可以通过时间轴把这些事件关联起来, 从资源的角度(比如每个cpu的在任意时间的使用情况), 从消费者的角度(比如每个进程的运行状态/路径)
如果某个cpu忙其他cpu闲会有什么现象, 以每个cpu为视角, 通过时间轴把所有的cpu关联起来, 使用不同的颜色表示runqueue的长度, 这样生成的图可以很容易看出migration是否及时, 这样的资源利用图是非常有必要的, 有点类似htop, 但是更加精细
本文作者：J.FW
来源：https://zhuanlan.zhihu.com/p/143320517（阅读原文可直达)
