《面向应用开发者的系统指南》CPU篇之使用systemtap分析进程的行为
本文是《面向应用开发者的系统指南》文档其中的一篇，完整的目录见《面向应用开发者的系统指南》导论。
概述
以上描述进程的创建、执行、调度器的工作原理，有了这些准备之后，可以使用systemtap在系统中埋点进行一些跟踪，以便理解进程的行为。
分析进程对CPU的占用
简单回顾一下前面进程调度相关的内容：
- 内核中使用就绪队列来维护当前所有处于可运行状态的进程，可运行状态不包括等待IO、休眠等状态的进程。
- 进程调度器负责从就绪队列中选择处于可运行状态的进程来执行。
- 而所有不处于可运行状态的进程，并不占用CPU资源，这些进程都等待被相关的事件比如网络IO唤醒，唤醒之后的进程更改状态为可运行状态，同时加入到就绪队列中，然后才能被调度器算法选择执行。
因此，一个进程的整个生命周期中，虽然看上去进程一直存在，但是并不是所有时候都占用CPU资源。根据CPU占用资源与否，或者说当前是否在运行，分为on cpu和off cpu状态：
上图中就一个进程执行的时间线做了简单的阶段划分，其中省略掉了进程被创建出来和最后退出时的情况，仅列出占用CPU资源状态的切换。
- 进程占用CPU获得执行权的时候，称为
on cpu时间。 - 进程因为各种原因（被其他进程抢占、自己调用了sleep系统调用主动进入睡眠状态、等待网络IO等）被剥夺了执行权的时候，首先会调用
deactivate_task函数从就绪队列中删除，接下来调用context_switch函数进行进程的上下文切换，这个时候旧的进程失去CPU的执行权，此时正式进入off cpu时间中。 - 在此之后，进程由于各种原因被唤醒，唤醒之后首先会被再次调用
activate_task函数加入到就绪队列中，进入就绪队列的进程也并不是马上就能够获得执行权的，是由进程调度算法来决定哪一个在就绪队列中的进程来执行。这段时间又可以分为两个部分：- 进程被切换出去直到重新进入就绪队列，这部分时间内进程等待被唤醒。
- 进入就绪队列到被调度器选中执行，这部分时间内进程等待被调度执行。
- 以上两部分时间的总和，加起来就是进程休眠的时间，即处于
off cpu状态的时间。
从这里看出来，一个进程虽然看上去一直存在，但并不是所有时间都在执行，跟进一个程序的运行时间时，需要区分其on和off cpu的时间，如果off的时间过长，那需要看看是什么原因导致了进程一直没有被唤醒执行。
另外需要注意的是，进程处于就绪状态，并不一定就是在运行，有可能还在就绪队列中等待被调度执行；但是反之则不然，一个占用CPU在执行的进程，其状态一定是就绪状态。即：
进程处于就绪状态的时间 = 进程在就绪队列的时间 + 进程在执行的时间
关于off cpu这一概念，Off-CPU Analysis一文中有更多的讲述。
有了上面对on cpu和off cpu的介绍，下面来看看使用systemtap如何跟踪这些状态以及所处的时间。
off CPU
systemtap中自带的tapset中，有一个scheduler.stp文件，里面定义了与调度器相关的一些probe。
其中跟踪off cpu的probe是scheduler.cpu_off ：
probe scheduler.cpu_off =
kernel.trace("sched_switch") !,
kernel.function("context_switch")
{
name = "cpu_off"
task_prev = $prev
task_next = $next
idle = __is_idle()
}
结合代码和最开始的示意图，可以知道该probe事件是针对内核trace事件sched_switch以及内核函数context_switch的封装，这两个事件都在进程上下文切换时触发。
在该probe事件中，能获取到的参数是：
- task_prev：保存切换之前的进程
task_struct结构体。 - task_next：保存切换之后的进程
task_struct结构体。 - idle：表示当前CPU是否空闲。
因为这个probe事件记录了进程切换前后的信息，因此可以用来完成类似记录系统切换最多的进程跟踪的功能：
global csw_count
global idle_count
probe scheduler.cpu_off {
csw_count[task_prev, task_next]++
idle_count+=idle
}
function fmt_task(task_prev, task_next)
{
return sprintf("%s(%d)->%s(%d)",
task_execname(task_prev),
task_pid(task_prev),
task_execname(task_next),
task_pid(task_next))
}
function print_cswtop () {
printf ("%45s %10s\n", "Context switch", "COUNT")
foreach ([task_prev, task_next] in csw_count- limit 20) {
printf("%45s %10d\n", fmt_task(task_prev, task_next), csw_count[task_prev, task_next])
}
printf("%45s %10d\n", "idle", idle_count)
delete csw_count
delete idle_count
}
probe timer.s($1) {
print_cswtop ()
printf("--------------------------------------------------------------\n")
}
（脚本出自文章Linux下谁在切换我们的进程）
该脚本在scheduler.cpu_off中累加进程切换的次数，然后在定时器中按照进程切换次数进行排序输出：
$ sudo stap process/cswmon.stp 1 -T 2
Context switch COUNT
swapper/0(0)->update-manager(3926) 515
update-manager(3926)->swapper/0(0) 514
Xorg(1418)->swapper/2(0) 430
swapper/2(0)->Xorg(1418) 429
swapper/1(0)->compiz(1855) 59
compiz(1855)->swapper/1(0) 59
swapper/3(0)->bamfdaemon(1733) 57
bamfdaemon(1733)->swapper/3(0) 57
Xorg(1418)->kworker/2:0(28665) 51
kworker/2:0(28665)->Xorg(1418) 50
swapper/3(0)->rcu_sched(8) 12
rcu_sched(8)->swapper/3(0) 12
swapper/2(0)->dockerd(2449) 12
dockerd(2449)->swapper/2(0) 12
swapper/2(0)->kworker/2:0(28665) 11
kworker/2:0(28665)->swapper/2(0) 11
swapper/0(0)->docker-containe(2563) 8
docker-containe(2563)->swapper/0(0) 8
swapper/1(0)->kworker/u8:1(28452) 8
kworker/u8:1(28452)->swapper/1(0) 8
idle 1202
--------------------------------------------------------------
on CPU
与scheduler.cpu_off相反的是，scheduler.cpu_on就是追踪进程获得CPU执行权时的probe事件了：
probe scheduler.cpu_on = kernel.function("finish_task_switch") ?
{
name = "cpu_on"
task_prev = $prev
idle = __is_idle()
}
内核函数在finish_task_switch在完成进程切换时被调用，其中的参数task_prev记录的是被切换出去的进程task_struct结构体指针。
需要注意的是，scheduler.cpu_off是在context_switch函数中被触发，而scheduler.cpu_on是在finish_task_switch函数中被触发，context_switch函数中调用了finish_task_switch函数来完成进程上下文切换的工作，这时候才意味着新的进程真正获得了执行权。
因此，可以认为：
scheduler.cpu_off：在这个调用点上一个执行进程失去执行权。scheduler.cpu_on：在这个调用点下一个执行进程得到执行权，正式开始执行。
利用scheduler.cpu_on probe事件，同时搭配上进程进出就绪队列的函数调用，就可以知道一个进程在从就绪队列中删除以及重新回到就绪队列，中间的延迟时间有多少。
比如systemtap安装包中提供的例子脚本latencytap.stp，其工作原理如下：
- 内核函数
activate_task和deactivate_task分别是进程进出就绪队列的函数调用点，两者之间的时间差值就是进程等待就绪的时间差。 scheduler.cpu_on中将上一步的就绪时间差记录到统计数组中。
上述核心代码简略如下：
probe kernel.trace("deactivate_task") !,
kernel.function("deactivate_task") {
s = task_state($p)
# 只有满足TASK_INTERRUPTIBLE和TASK_UNINTERRUPTIBLE状态的才记录
if (log_event($p) && (s & 3)) {
# 在离队队列中记录下来当前的时间
dequeue[$p] = gettimeofday_us();
}
}
# activate_task在一个任务不活跃的时候触发
probe kernel.trace("activate_task") !,
kernel.function("activate_task") {
a = gettimeofday_us()
# 拿到开始休眠的时间点
d = dequeue[$p]
# 删除记录
delete dequeue[$p]
# 如果存在这个休眠时间，就去计算时长
if (d) {
sleep = a - d
if (sleep > 0) {
# 记录下来休眠的时长
this_sleep[$p] = sleep
}
}
}
probe scheduler.cpu_on {
p = task_current()
t = this_sleep[p]
if (t){
delete this_sleep[p]
# 将休眠时间以进程调用栈为键值记录到统计数组中
sleep_time[backtrace()] <<< t
}
}
其实这个以调用栈为键值记录时间到统计数组的工作，完全可以同样放在activate_task函数中，官方的解释是，在activate_task函数中做这个操作会增大这个监控在进程上下文切换时的影响，所以就放在scheduler.cpu_on这个probe中来完成了：
#FIXME: It would be nicer to get backtrace information in activate_task probe.
# This would eliminate the overhead of probing every context switch
# and this_sleep associate array. However, this needs a properly working
# task_backtrace() to eliminate this probe.
off cpu的时间计算以及调用栈
从上面的分析可以看到，将进程的时间按照按照其是否占用CPU来执行的时间来划分，可以分为on cpu和off cpu时间。观察一个服务进程，如果其在繁忙的时候，CPU时间一直上不去，说明某些原因导致其off cpu时间过多，这时候就需要查看原因了。
scheduler.cpu_off和scheduler.cpu_on这两个probe事件，在进程被调度进出CPU资源的时候触发，在这里可以记录等待CPU时间以及调用堆栈。
openresty-systemtap-toolkit项目中的sample-bt-off-cpu脚本，可以用来观测并打印进程off cpu时间的调用栈，该脚本由perl语言实现，如果带上-d参数可以输出成systemtap的stap脚本内容，如下：
sudo ./sample-bt-off-cpu -p `pidof top` -t 2 -u -d
这里几个参数的含义：
- -p：待观测的进程pid，这里为了示范就选择top命令。
- -t：采集多少秒的数据之后就退出。
- -d：并不实际工作，而是输出systemtap的stp脚本文件内容。
- -u：打印的调用栈是用户层调用栈，反之如果使用
-k就是输出的内核调用栈。
以上命令在我机器上输出的stp脚本内容如下：
global bts
global start_time
global quit = 0;
global found
probe begin {
warn(sprintf("Tracing %d (/usr/bin/top)...\n", target()))
}
probe scheduler.cpu_off {
if (pid() == target()) {
if (!quit) {
start_time[tid()] = gettimeofday_us()
} else {
foreach (bt in bts- limit 1024) {
print_ustack(bt)
printf("\t%d\n", @sum(bts[bt]))
}
exit()
}
}
}
probe scheduler.cpu_on {
if (pid() == target() && !quit) {
t = tid()
begin = start_time[t]
if (begin > 0) {
elapsed = gettimeofday_us() - begin
if (elapsed >= 4) {
bts[ubacktrace()] <<< elapsed
found = 1
}
delete start_time[t]
}
}
}
probe timer.s(2) {
if (!found) {
warn("No backtraces found. Quitting now...\n")
exit()
} else {
warn("Time's up. Quitting now...(it may take a while)\n")
quit = 1
}
}
可以看到，这段脚本有在两个probe事件上加了处理函数：
- scheduler.cpu_off：进程失去cpu时，记录此时的时间。
- scheduler.cpu_on：进程获取到cpu资源准备执行时，拿到此时的时间，如果与off cpu的时间相差了超过4us，就记录下此时的用户层调用栈以及时间差。
- 当设置的脚本退出时间到来时，按照前面统计时间从到到少打印进程的调用栈信息。
on cpu的时间计算以及调用栈
进程除了在off cpu时间上等待被唤醒之外，就是在on cpu时间上一直执行了。与off cpu测量所不同的是，on cpu的时间上可以看出程序执行的热点，这部分调用栈的观察使用的是采样的方式。即：定时打印进程调用栈的信息。
openresty-systemtap-toolkit项目中的sample-bt脚本，其使用时的命令行参数与前面的sample-bt-off-cpu并无不同，这个脚本打印的是进程在on cpu状态下的调用栈，这样就可以观察出程序的执行热点来：
sudo ./sample-bt -p `pidof top` -t 2 -u -d
输出如下：
probe begin {
warn(sprintf("Tracing %d (/usr/bin/top) in user-space only...\n", target()))
}
global bts;
global quit = 0;
probe timer.profile {
if (pid() == target()) {
if (!quit) {
bts[ubacktrace()] <<< 1;
} else {
foreach (bt in bts- limit 1024) {
print_ustack(bt);
printf("\t%d\n", @count(bts[bt]));
}
exit()
}
}
}
probe timer.s(2) {
nstacks = 0
foreach (bt in bts limit 1) {
nstacks++
}
if (nstacks == 0) {
warn("No backtraces found. Quitting now...\n")
exit()
} else {
warn("Time's up. Quitting now...(it may take a while)\n")
quit = 1
}
}
这段脚本的工作原理是：在timer.profile这个probe事件中，判断当前执行的pid如果是所要观察的pid，就记录其调用栈信息到统计数组里，在最后脚本到期的时候按照统计数组的降序排列打印调用栈即可。
火焰图
以上，解释了如何打印进程在off cpu和on cpu两种状态下的调用栈信息，由于这些信息都是使用采样的方式进行收集的，因此还统计并且输出进程在这些状态下到底消耗在哪些地方。
此时，就需要召唤“火焰图”了。火焰图是一种根据输入的采样信息，统计生成热点的图片，在这里可以很方便的看到从采集的数据中，进程都消耗在哪些函数调用里。
生成火焰图的工具由brendangregg提供的项目FlameGraph生成，该项目提供多种Perl语言编写的脚本，数据源可以来自Perf、systemtap等多种Linux下面的profile工具，systemtap的输出可以由项目中的stackcollapse-stap.pl脚本来生成火焰图。
以使用前面的openresty-systemtap-toolkit项目中的sample-bt脚本为例，搭配火焰图使用的步骤大体如下：
# 跟踪pid为22222的进程，采样时间20秒，只采用用户层信息，输出到tmp.bt文件中
./sample-bt -p 22222 -t 20 -u > tmp.bt
# 调用stackcollapse-stap.pl文件，将第一步采样的数据生成cbt格式文件
./stackcollapse-stap.pl flame.bt > flame.cbt
# 生成火焰图的svg文件
./flamegraph.pl flame.cbt > flame.svg
以上的流程总结如下：
下图是火焰图的一个示例，火焰图分为以下几个部分：
- 横轴：函数调用的时间占比。直观来看，横轴上越宽的函数调用，其采样到的数据就越多，这样才能直观的看到“热点”在哪些函数调用上。
- 纵轴：函数的调用栈信息。
进程状态的切换
前面几个部分，已经可以观测出来进程在on cpu和off cpu上面花费的时间、执行热点、调用栈等信息了，但是程序在非执行时间，其实还可以细分为以下几个状态：
- 进程的执行权是被抢占的，本身并没有任何放弃执行权的操作。此时就意味着，进程还一直在就绪队列中，只不过被优先级更高的进程抢占了执行权。
- 进程因为等待IO、主动休眠等原因，让出了执行权，此时还可以细分为进程是休眠还是在等待IO事件完成后再唤醒进程执行。
本节中来看看如何使用systemtap脚本来具体统计程序在这几个细分状态中的执行时间。
先从描述进程的task_struct结构体信息说起，这部分在前面专门讲解task_struct结构体的部分有专门介绍，这里仅作简单的回顾。
task_struct结构体中，成员state用来表示进程当前的状态，有以下几个互斥的值：
#define TASK_RUNNING 0x0000
#define TASK_INTERRUPTIBLE 0x0001
#define TASK_UNINTERRUPTIBLE 0x0002
其中，TASK_RUNNING状态就是就绪状态。可以认为，只要state值为0（即TASK_RUNNING）的情况下，进程就是就绪状态的，此时只可能处于两种状态：
- 占用CPU在执行。
- 在就绪队列中等待被唤醒执行，这种进程还是就绪状态却被调度出CPU的情况，一般都是被优先级更高的进程抢占了执行权。
因此，当进程被调度让出cpu执行权时，如果state为0说明此时还在就绪队列中，否则就不是就绪状态。
此外，task_struct结构体中还有另一个成员in_iowait，用于表示当前进程是否在等待IO。因此，根据这个成员是否为1，就可以知道非就绪状态的进程是在等待IO还是在休眠。
总结上面的内容如下，当进程被剥夺执行权的时候：
- 如果当前进程状态还是
TASK_RUNNING，说明这时候回到就绪队列中排队等待调度执行。 - 如果进程状态大于0，此时会区分两种情况：
- 如果
in_iowait为1：说明在等待IO。 - 否则说明在休眠。
- 如果
- 第三种情况就是进程状态小于0的状态，此时进程已经死亡。
systemtap中自带的例子脚本schedtimes提供了统计以上三种时间的例子：
$ sudo stap schedtimes.stp -T 10
execname: pid run(us) sleep(us) iowait(us) queued(us) total(us)
systemd: 1 29 10034958 0 5 10034992
rcu_sched: 8 632 10030313 0 1432 10032377
watchdog/0: 11 49 8284090 0 102 8284241
watchdog/1: 14 47 8284082 0 102 8284231
ksoftirqd/1: 16 50 10028298 0 9 10028357
watchdog/2: 20 68 8280096 0 76 8280240
ksoftirqd/2: 22 97 7916416 0 141 7916654
脚本中能统计出程序在执行状态（run）、休眠状态（sleep）、等待IO状态（iowait）、在就绪队列中等待被调度状态（queued）的时间。
这个脚本的工作原理如下：
kernel.trace("sched_switch")事件中：这个事件在进程被切换出去cpu时被触发，此时可以拿到进程task_struct结构体的state成员，根据上面描述进程状态判断，就可以知道是主动让出执行权、排在就绪队列等待、还是死亡状态了。kernel.trace("sched_wakeup")事件中：这个事件在进程被再次执行时触发，此时判断进程在切换出去时的状态如果是主动让出执行权的话，那么如果这时task_struct->in_iowait为1，说明在等待IO，否则就是在休眠状态。
这部分相关代码及注释如下：
// 进程状态发生变化时触发，用于更新进程各种状态的统计时间
function update_times(pid, now)
{
delta = now - previous_timestamp[pid]
// 首先更新这一次统计的时间戳
previous_timestamp[pid] = now
if ((state = pid_state[pid]) > 0) {
// 进程状态大于0，说明进程没有就绪
if (state == SLEEPING)
// 更新休眠时间
sleep_time[pid] += delta
else if (state == QUEUED)
// 更新排队时间
queued_time[pid] += delta
else if (state == RUNNING)
// 更新运行时间
run_time[pid] += delta
}
return delta
}
probe kernel.trace("sched_switch")
{
// Task $prev is scheduled off this cpu
if (task_targeted($prev)) {
pid = $prev->pid
state = $prev->state
update_times(pid, timestamp())
// 根据进程状态来判断
if (state > 0) {
// 大于0说明不在运行状态，在休眠
@set_iowait($rq, $prev)
pid_state[pid] = SLEEPING
} else if (state == 0) {
// =0说明在运行状态，只不过被抢占了执行权
pid_state[pid] = QUEUED
} else {
// 小于0说明进程死了
pid_state[pid] = DEAD
}
}
// Task $next is scheduled onto this cpu
if (task_targeted($next)) {
pid = $next->pid
update_times(pid, timestamp())
@clear_iowait($rq, $next)
pid_state[pid] = RUNNING
}
}
// 进程被唤醒时触发
probe kernel.trace("sched_wakeup")
{
// Task $p is awakened
if (@choose_defined($success, 1) && task_targeted($p)) {
pid = $p->pid
delta = update_times(pid, timestamp())
// 在休眠同时在iowait，增加iowait时间
if (pid_state[pid] == SLEEPING && @in_iowait($p)) {
iowait_time[pid] += delta
}
// 状态是就绪队列状态
pid_state[pid] = QUEUED
}
}
小结
总结一下这一节涉及到的知识点：
- 进程的执行划分为
on cpu和off cpu两部分时间。前者表示进程在占用CPU执行的时间，后者是除此之外的进程时间。 - 如果进程的CPU一直上不去，可以看看进程的
off cpu时间都分布在哪些函数调用上；反之，可以从进程的on cpu时间中看到进程执行时的热点函数。 - 有了不同状态下的函数调用栈采样数据之后，可以生成火焰图直观查看采样数据。
- 使用systemtap脚本可以跟进这两部分时间、进程上下文切换、进程状态切换的情况。