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

概述

以上描述进程的创建、执行、调度器的工作原理,有了这些准备之后,可以使用systemtap在系统中埋点进行一些跟踪,以便理解进程的行为。

分析进程对CPU的占用

简单回顾一下前面进程调度相关的内容:

  • 内核中使用就绪队列来维护当前所有处于可运行状态的进程,可运行状态不包括等待IO、休眠等状态的进程。
  • 进程调度器负责从就绪队列中选择处于可运行状态的进程来执行。
  • 而所有不处于可运行状态的进程,并不占用CPU资源,这些进程都等待被相关的事件比如网络IO唤醒,唤醒之后的进程更改状态为可运行状态,同时加入到就绪队列中,然后才能被调度器算法选择执行。

因此,一个进程的整个生命周期中,虽然看上去进程一直存在,但是并不是所有时候都占用CPU资源。根据CPU占用资源与否,或者说当前是否在运行,分为on cpuoff cpu状态:

onoffcpu

上图中就一个进程执行的时间线做了简单的阶段划分,其中省略掉了进程被创建出来和最后退出时的情况,仅列出占用CPU资源状态的切换。

  • 进程占用CPU获得执行权的时候,称为on cpu时间。
  • 进程因为各种原因(被其他进程抢占、自己调用了sleep系统调用主动进入睡眠状态、等待网络IO等)被剥夺了执行权的时候,首先会调用deactivate_task函数从就绪队列中删除,接下来调用context_switch函数进行进程的上下文切换,这个时候旧的进程失去CPU的执行权,此时正式进入off cpu时间中。
  • 在此之后,进程由于各种原因被唤醒,唤醒之后首先会被再次调用activate_task函数加入到就绪队列中,进入就绪队列的进程也并不是马上就能够获得执行权的,是由进程调度算法来决定哪一个在就绪队列中的进程来执行。这段时间又可以分为两个部分:
    • 进程被切换出去直到重新进入就绪队列,这部分时间内进程等待被唤醒。
    • 进入就绪队列到被调度器选中执行,这部分时间内进程等待被调度执行。
    • 以上两部分时间的总和,加起来就是进程休眠的时间,即处于off cpu状态的时间。

从这里看出来,一个进程虽然看上去一直存在,但并不是所有时间都在执行,跟进一个程序的运行时间时,需要区分其onoff cpu的时间,如果off的时间过长,那需要看看是什么原因导致了进程一直没有被唤醒执行。

另外需要注意的是,进程处于就绪状态,并不一定就是在运行,有可能还在就绪队列中等待被调度执行;但是反之则不然,一个占用CPU在执行的进程,其状态一定是就绪状态。即:

进程处于就绪状态的时间 = 进程在就绪队列的时间 + 进程在执行的时间

关于off cpu这一概念,Off-CPU Analysis一文中有更多的讲述。

有了上面对on cpuoff 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函数来完成进程上下文切换的工作,这时候才意味着新的进程真正获得了执行权。

context_switch_probe

因此,可以认为:

  • scheduler.cpu_off:在这个调用点上一个执行进程失去执行权。
  • scheduler.cpu_on:在这个调用点下一个执行进程得到执行权,正式开始执行。

利用scheduler.cpu_on probe事件,同时搭配上进程进出就绪队列的函数调用,就可以知道一个进程在从就绪队列中删除以及重新回到就绪队列,中间的延迟时间有多少。

比如systemtap安装包中提供的例子脚本latencytap.stp,其工作原理如下:

  • 内核函数activate_taskdeactivate_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 cpuoff cpu时间。观察一个服务进程,如果其在繁忙的时候,CPU时间一直上不去,说明某些原因导致其off cpu时间过多,这时候就需要查看原因了。

scheduler.cpu_offscheduler.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 cpuon 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

以上的流程总结如下:

hotpot

下图是火焰图的一个示例,火焰图分为以下几个部分:

  • 横轴:函数调用的时间占比。直观来看,横轴上越宽的函数调用,其采样到的数据就越多,这样才能直观的看到“热点”在哪些函数调用上。
  • 纵轴:函数的调用栈信息。

hotpot-example

进程状态的切换

前面几个部分,已经可以观测出来进程在on cpuoff cpu上面花费的时间、执行热点、调用栈等信息了,但是程序在非执行时间,其实还可以细分为以下几个状态:

  • 进程的执行权是被抢占的,本身并没有任何放弃执行权的操作。此时就意味着,进程还一直在就绪队列中,只不过被优先级更高的进程抢占了执行权。
  • 进程因为等待IO、主动休眠等原因,让出了执行权,此时还可以细分为进程是休眠还是在等待IO事件完成后再唤醒进程执行。

offcpu

本节中来看看如何使用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 cpuoff cpu两部分时间。前者表示进程在占用CPU执行的时间,后者是除此之外的进程时间。
  • 如果进程的CPU一直上不去,可以看看进程的off cpu时间都分布在哪些函数调用上;反之,可以从进程的on cpu时间中看到进程执行时的热点函数。
  • 有了不同状态下的函数调用栈采样数据之后,可以生成火焰图直观查看采样数据。
  • 使用systemtap脚本可以跟进这两部分时间、进程上下文切换、进程状态切换的情况。