本文是《面向应用开发者的系统指南》文档其中的一篇，完整的目录见《面向应用开发者的系统指南》导论。

概述

以上描述进程的创建、执行、调度器的工作原理，有了这些准备之后，可以使用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")

}

该脚本在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_RUNNING0x0000

#define TASK_INTERRUPTIBLE0x0001

#define TASK_UNINTERRUPTIBLE0x0002

其中，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脚本可以跟进这两部分时间、进程上下文切换、进程状态切换的情况。