Linux perf sched Summary

1. `Overview`

perf sched 使用了转储后再分析 (dump-and-post-process) 的方式来分析内核调度器的各种事件。
而这往往带来一些问题，因为这些调度事件通常非常地频繁，可以达到每秒钟百万级，进而导致 CPU，内存和磁盘的在调度器事件记录上的严重开销。
我最近一直在用 eBPF/bcc (包括 runqlat) 来写内核调度器分析工具，使用 eBPF 特性在内核里直接对调度事件的分析处理，可以极大的减少这种事件记录的开销。
但是有一些性能分析场景里，我们可能想用 perf shed 命令去记录每一个调度事件，尽管比起 ebpf 的方式，这会带来更大的开销。
想象一下这个场景，你有只有五分钟时间去分析一个有问题的云的虚拟机实例，在这个实例自动销毁之前，你想要为日后的各种分析去记录每个调度事件。

我们以记录一秒钟内的所有调度事件作为开始：

# perf sched record -- sleep 1
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 1.886 MB perf.data (13502 samples) ]

这个命令的结果是一秒钟记录了 1.9 Mb 的数据，其中包含了 13,502 个调度事件样本。
数据的大小和速度和系统的工作负载以及 CPU 数目的多少直接相关 (本例中正在一个 8 CPU 的服务器上 build 一个软件)。
事件记录如何被写入文件系统的过程已经被优化过了：为减少记录开销，perf 命令仅仅被唤醒一次，去读事件缓冲区里的数据，然后写到磁盘上。
因此这种方式下，仍旧会有非常显著的开销，包括调度器事件的产生和文件系统的数据写入。

这些调度器事件包括，

# perf script --header
# ========
# captured on: Sun Feb 26 19:40:00 2017
# hostname : bgregg-xenial
# os release : 4.10-virtual
# perf version : 4.10
# arch : x86_64
# nrcpus online : 8
# nrcpus avail : 8
# cpudesc : Intel(R) Xeon(R) CPU E5-2680 v2 @ 2.80GHz
# cpuid : GenuineIntel,6,62,4
# total memory : 15401700 kB
# cmdline : /usr/bin/perf sched record -- sleep 1
# event : name = sched:sched_switch, , id = { 2752, 2753, 2754, 2755, 2756, 2757, 2758, 2759...
# event : name = sched:sched_stat_wait, , id = { 2760, 2761, 2762, 2763, 2764, 2765, 2766, 2...
# event : name = sched:sched_stat_sleep, , id = { 2768, 2769, 2770, 2771, 2772, 2773, 2774, ...
# event : name = sched:sched_stat_iowait, , id = { 2776, 2777, 2778, 2779, 2780, 2781, 2782,...
# event : name = sched:sched_stat_runtime, , id = { 2784, 2785, 2786, 2787, 2788, 2789, 2790...
# event : name = sched:sched_process_fork, , id = { 2792, 2793, 2794, 2795, 2796, 2797, 2798...
# event : name = sched:sched_wakeup, , id = { 2800, 2801, 2802, 2803, 2804, 2805, 2806, 2807...
# event : name = sched:sched_wakeup_new, , id = { 2808, 2809, 2810, 2811, 2812, 2813, 2814, ...
# event : name = sched:sched_migrate_task, , id = { 2816, 2817, 2818, 2819, 2820, 2821, 2822...
# HEADER_CPU_TOPOLOGY info available, use -I to display
# HEADER_NUMA_TOPOLOGY info available, use -I to display
# pmu mappings: breakpoint = 5, power = 7, software = 1, tracepoint = 2, msr = 6
# HEADER_CACHE info available, use -I to display
# missing features: HEADER_BRANCH_STACK HEADER_GROUP_DESC HEADER_AUXTRACE HEADER_STAT
# ========
#perf 16984 [005] 991962.879966:   sched:sched_wakeup: comm=perf pid=16999 prio=120 target_cpu=005[...]

perf sched 可以用几种不同的方式记录调度事件，其 help 子命令总结如下:

# perf sched -hUsage: perf sched [] {record|latency|map|replay|script|timehist}-D, --dump-raw-trace  dump raw trace in ASCII-f, --force           don't complain, do it-i, --input     input file name-v, --verbose         be more verbose (show symbol address, etc)

2. `perf sched latency`

其中，perf sched latency 可以给出每个任务 (task) 的调度延迟，包括平均和最大延迟:

# perf sched latency-----------------------------------------------------------------------------------------------------------------Task                  |   Runtime ms  | Switches | Average delay ms | Maximum delay ms | Maximum delay at       |-----------------------------------------------------------------------------------------------------------------cat:(6)               |     12.002 ms |        6 | avg:   17.541 ms | max:   29.702 ms | max at: 991962.948070 sar:17043              |      3.191 ms |        1 | avg:   13.638 ms | max:   13.638 ms | max at: 991963.048070 srm:(10)               |     20.955 ms |       10 | avg:   11.212 ms | max:   19.598 ms | max at: 991963.404069 sobjdump:(6)           |     35.870 ms |        8 | avg:   10.969 ms | max:   16.509 ms | max at: 991963.424443 s:17008:17008          |    462.213 ms |       50 | avg:   10.464 ms | max:   35.999 ms | max at: 991963.120069 sgrep:(7)              |     21.655 ms |       11 | avg:    9.465 ms | max:   24.502 ms | max at: 991963.464082 sfixdep:(6)            |     81.066 ms |        8 | avg:    9.023 ms | max:   19.521 ms | max at: 991963.120068 smv:(10)               |     30.249 ms |       14 | avg:    8.380 ms | max:   21.688 ms | max at: 991963.200073 sld:(3)                |     14.353 ms |        6 | avg:    7.376 ms | max:   15.498 ms | max at: 991963.452070 srecordmcount:(7)      |     14.629 ms |        9 | avg:    7.155 ms | max:   18.964 ms | max at: 991963.292100 ssvstat:17067          |      1.862 ms |        1 | avg:    6.142 ms | max:    6.142 ms | max at: 991963.280069 scc1:(21)              |   6013.457 ms |     1138 | avg:    5.305 ms | max:   44.001 ms | max at: 991963.436070 sgcc:(18)              |     43.596 ms |       40 | avg:    3.905 ms | max:   26.994 ms | max at: 991963.380069 sps:17073              |     27.158 ms |        4 | avg:    3.751 ms | max:    8.000 ms | max at: 991963.332070 s
...]

为说明这些调度事件是如何记录和计算的，这里会以上面一行，最大调度延迟 29.702 毫秒的例子来说明。
同样的结果，可以使用 perf sched script 展现其原始调度事件:

sh 17028 [001] 991962.918368:  sched:sched_wakeup_new: comm=sh pid=17030 prio=120 target_cpu=002
[...]
cc1 16819 [002] 991962.948070: sched:sched_switch: prev_comm=cc1 prev_pid=16819 prev_prio=120prev_state=R ==> next_comm=sh next_pid=17030 next_prio=120
[...]

从 sh 任务被唤醒时间点 (991962.918368 单位是秒) 到 sh 通过上下文切换即将被执行的时间点 (991962.948070) 的时间间隔是 29.702 毫秒。
原始调度事件列出的 sh (shell) 进程，很快就会执行cat命令，因此在 perf sched latency输出里显示的是 cat命令的调度延迟。

3. `perf sched map`

perf sched map 显示所有的CPU的上下文切换的事件，其中的列输出了每个 CPU 正在做什么，以及具体时间。
它和我们在内核调度器分析 GUI 软件看到的可视化数据 (包括 perf timechart 的输出做 90 度旋转后）都是一样的。下面是一个输出的例子：

# perf sched map*A0           991962.879971 secs A0 => perf:16999A0     *B0   991962.880070 secs B0 => cc1:16863*C0          A0      B0   991962.880070 secs C0 => :17023:17023*D0      C0          A0      B0   991962.880078 secs D0 => ksoftirqd/0:6D0      C0 *E0      A0      B0   991962.880081 secs E0 => ksoftirqd/3:28D0      C0 *F0      A0      B0   991962.880093 secs F0 => :17022:17022*G0      C0  F0      A0      B0   991962.880108 secs G0 => :17016:17016G0      C0  F0     *H0      B0   991962.880256 secs H0 => migration/5:39G0      C0  F0     *I0      B0   991962.880276 secs I0 => perf:16984G0      C0  F0     *J0      B0   991962.880687 secs J0 => cc1:16996G0      C0 *K0      J0      B0   991962.881839 secs K0 => cc1:16945G0      C0  K0      J0 *L0  B0   991962.881841 secs L0 => :17020:17020G0      C0  K0      J0 *M0  B0   991962.882289 secs M0 => make:16637G0      C0  K0      J0 *N0  B0   991962.883102 secs N0 => make:16545G0     *O0  K0      J0  N0  B0   991962.883880 secs O0 => cc1:16819G0 *A0  O0  K0      J0  N0  B0   991962.884069 secs G0  A0  O0  K0 *P0  J0  N0  B0   991962.884076 secs P0 => rcu_sched:7G0  A0  O0  K0 *Q0  J0  N0  B0   991962.884084 secs Q0 => cc1:16831G0  A0  O0  K0  Q0  J0 *R0  B0   991962.884843 secs R0 => cc1:16825G0 *S0  O0  K0  Q0  J0  R0  B0   991962.885636 secs S0 => cc1:16900G0  S0  O0 *T0  Q0  J0  R0  B0   991962.886893 secs T0 => :17014:17014G0  S0  O0 *K0  Q0  J0  R0  B0   991962.886917 secs
[...]

这是一个 8 CPU 系统，你可以看到从左到右8 个列的输出来代表每个 CPU。
一些 CPU 的列以空白开始，因为在我们开始运行命令分析系统时，刚开始记录调度事件。
很快地，各个 CPU 所在列就开始填满输出了。

输出中的两个字符的代码 (“A0” “C0”)，时用于区分识别各个任务的，其关联的任务的名字显示在右侧 (“=>”)。
“*” 字符表示这个 CPU 上当时有上下文切换事件，从而导致新的调度事件发生。
例如，上面输出的最后一行表示在 991962.886917 秒的时间点， CPU 4 上发生了上下文切换，导致了任务 K0 的执行 (“cc1” 进程，PID 是 16945)。

上面这个例子来自一个繁忙的系统，下面是一个空闲系统的例子：

# perf sched map*A0           993552.887633 secs A0 => perf:26596*.                   A0           993552.887781 secs .  => swapper:0.                  *B0           993552.887843 secs B0 => migration/5:39.                  *.            993552.887858 secs .                   .  *A0       993552.887861 secs .                  *C0  A0       993552.887903 secs C0 => bash:26622.                  *.   A0       993552.888020 secs .          *D0      .   A0       993552.888074 secs D0 => rcu_sched:7.          *.       .   A0       993552.888082 secs .           .      *C0  A0       993552.888143 secs .      *.   .       C0  A0       993552.888173 secs .       .   .      *B0  A0       993552.888439 secs .       .   .      *.   A0       993552.888454 secs .      *C0  .       .   A0       993552.888457 secs .       C0  .       .  *.        993552.889257 secs .      *.   .       .   .        993552.889764 secs .       .  *E0      .   .        993552.889767 secs E0 => bash:7902
...]

输出中，空闲 CPU 被显示为“.”。

注意检查输出中的时间戳所在的列，这对数据的可视化很有意义 (GUI 的调度器分析工具使用时间戳作为一个维度，这样非常易于理解，但是 CLI 的工具只列出了时间戳的值)。
这个输出里也只显示了上下文切换事件的情况，而没有包含调度延迟。新子命令timehist有一个可视化 (-V)选项，允许包含唤醒 (wakeup)事件。

4. `perf sched timehist`

perf sched timehist 是Linux 4.10 里加入的，可以按照调度事件表示调度延迟，其中包括了任务等待被唤醒的时间 (wait time) 和任务从被唤醒之后到运行态的调度延迟。
其中的调度延迟是我们更感兴趣去优化的。详见下例：

# perf sched timehist
Samples do not have callchains.time    cpu  task name                       wait time  sch delay   run time[tid/pid]                          (msec)     (msec)     (msec)
--------------- ------  ------------------------------  ---------  ---------  ---------991962.879971 [0005]  perf[16984]                         0.000      0.000      0.000 991962.880070 [0007]  :17008[17008]                       0.000      0.000      0.000 991962.880070 [0002]  cc1[16880]                          0.000      0.000      0.000 991962.880078 [0000]  cc1[16881]                          0.000      0.000      0.000 991962.880081 [0003]  cc1[16945]                          0.000      0.000      0.000 991962.880093 [0003]  ksoftirqd/3[28]                     0.000      0.007      0.012 991962.880108 [0000]  ksoftirqd/0[6]                      0.000      0.007      0.030 991962.880256 [0005]  perf[16999]                         0.000      0.005      0.285 991962.880276 [0005]  migration/5[39]                     0.000      0.007      0.019 991962.880687 [0005]  perf[16984]                         0.304      0.000      0.411 991962.881839 [0003]  cat[17022]                          0.000      0.000      1.746 991962.881841 [0006]  cc1[16825]                          0.000      0.000      0.000
[...]991963.885740 [0001]  :17008[17008]                      25.613      0.000      0.057 991963.886009 [0001]  sleep[16999]                     1000.104      0.006      0.269 991963.886018 [0005]  cc1[17083]                         19.998      0.000      9.948

上面的输出包含了前面 perf record 运行时，为设定跟踪时间为 1 秒钟而执行的 sleep 命令。
你可以注意到，sleep 命令的等待时间是 10000.104 毫秒，这是该命令等待被定时器唤醒的时间。
这个 sleep 命令的调度延迟只有 0.006 毫秒，并且它在 CPU 上真正运行的时间只有 0.269 毫秒。

timehist 子命令有很多命令选项，包括 -V 选项用以增加 CPU 可视化列输出，-M 选项用以增加调度迁移事件，和 -w 选项用以显示唤醒事件。例如：

# perf sched timehist -MVw
Samples do not have callchains.time    cpu  012345678  task name           wait time  sch delay   run time[tid/pid]              (msec)     (msec)     (msec)
--------------- ------  ---------  ------------------  ---------  ---------  ---------991962.879966 [0005]             perf[16984]                                          awakened: perf[16999]991962.879971 [0005]       s     perf[16984]             0.000      0.000      0.000991962.880070 [0007]         s   :17008[17008]           0.000      0.000      0.000991962.880070 [0002]    s        cc1[16880]              0.000      0.000      0.000991962.880071 [0000]             cc1[16881]                                           awakened: ksoftirqd/0[6]991962.880073 [0003]             cc1[16945]                                           awakened: ksoftirqd/3[28]991962.880078 [0000]  s          cc1[16881]              0.000      0.000      0.000991962.880081 [0003]     s       cc1[16945]              0.000      0.000      0.000991962.880093 [0003]     s       ksoftirqd/3[28]         0.000      0.007      0.012991962.880108 [0000]  s          ksoftirqd/0[6]          0.000      0.007      0.030991962.880249 [0005]             perf[16999]                                          awakened: migration/5[39]991962.880256 [0005]       s     perf[16999]             0.000      0.005      0.285991962.880264 [0005]        m      migration/5[39]                                      migrated: perf[16999] cpu 5 => 1991962.880276 [0005]       s     migration/5[39]         0.000      0.007      0.019991962.880682 [0005]        m      perf[16984]                                          migrated: cc1[16996] cpu 0 => 5991962.880687 [0005]       s     perf[16984]             0.304      0.000      0.411991962.881834 [0003]             cat[17022]                                           awakened: :17020
...]991963.885734 [0001]             :17008[17008]                                        awakened: sleep[16999]991963.885740 [0001]   s         :17008[17008]          25.613      0.000      0.057991963.886005 [0001]             sleep[16999]                                         awakened: perf[16984]991963.886009 [0001]   s         sleep[16999]         1000.104      0.006      0.269991963.886018 [0005]       s     cc1[17083]             19.998      0.000      9.948 # perf sched timehist -MVw

CPU 可视化列 (“012345678”)用于表示对应CPU 的调度事件。如果包含一个 “s” 字符，就表示上下文切换事件的发生，但如果是 “m”字符，就代表调度迁移事件发生。

以上输出的最后几个事件里包含了之前 perf record 里设定时间的 sleep 命令。
其中唤醒发生在时间点 991963.885734，并且在时间点 991963.885740 (6 微妙之后)，CPU 1 开始发生上下文切换，sleep 命令被调度执行。
其中任务名所在的列仍然显示 “:17008[17008]”，以代表上下文切换开始前在 CPU 上的进程，但是上下文切换完成后被调度的目标进程并没有显示，它实际上可以在原始调度事件 (raw events) 里可以被找到：

:17008 17008 [001] 991963.885740:       sched:sched_switch: prev_comm=cc1 prev_pid=17008 prev_prio=120prev_state=R ==> next_comm=sleep next_pid=16999 next_prio=120

时间戳为 991963.886005的事件表示了 sleep 进程在 CPU 上运行时，perf 命令收到了一个唤醒 (这应该是 sleep 命令在结束退出时唤醒了它的父进程)。
随后在时间点 991963.886009，上下文切换事件发生，这时 sleep 命令停止执行，并且打印出上下文切换事件的跟踪记录：在 sleep 运行期间，它有 1000.104 毫秒的等待时间，0.006 毫秒的调度延迟，和 0.269 毫秒的 CPU 实际运行时间。

下面对 timehist 的输出做了上下文切换的目标进程相关的标注 (“next:” 为前缀)：

991963.885734 [0001]             :17008[17008]                                        awakened: sleep[16999]
991963.885740 [0001]   s         :17008[17008]          25.613      0.000      0.057  next: sleep[16999]
991963.886005 [0001]             sleep[16999]                                         awakened: perf[16984]
991963.886009 [0001]   s         sleep[16999]         1000.104      0.006      0.269  next: cc1[17008]
991963.886018 [0005]       s     cc1[17083]             19.998      0.000      9.948  next: perf[16984]

当 sleep 结束后，正在等待的 “cc1” 进程被执行。
随后的上下文切换， perf 命令被执行，并且它是最后一个调度事件 (因为 perf 命令最后退出了)。
笔者给社区提交了一个 patch，通过-n 命令选项，用以支持显示上下文切换的目标进程。

5. `perf sched script`

perf sched script 子命令用来显示所有原始调度事件 (raw event)，与 perf script 的作用类似：

# perf sched scriptperf 16984 [005] 991962.879960: sched:sched_stat_runtime: comm=perf pid=16984 runtime=3901506 [ns] vruntime=165...perf 16984 [005] 991962.879966:       sched:sched_wakeup: comm=perf pid=16999 prio=120 target_cpu=005perf 16984 [005] 991962.879971:       sched:sched_switch: prev_comm=perf prev_pid=16984 prev_prio=120 prev_stat...perf 16999 [005] 991962.880058: sched:sched_stat_runtime: comm=perf pid=16999 runtime=98309 [ns] vruntime=16405...cc1 16881 [000] 991962.880058: sched:sched_stat_runtime: comm=cc1 pid=16881 runtime=3999231 [ns] vruntime=7897...:17024 17024 [004] 991962.880058: sched:sched_stat_runtime: comm=cc1 pid=17024 runtime=3866637 [ns] vruntime=7810...cc1 16900 [001] 991962.880058: sched:sched_stat_runtime: comm=cc1 pid=16900 runtime=3006028 [ns] vruntime=7772...cc1 16825 [006] 991962.880058: sched:sched_stat_runtime: comm=cc1 pid=16825 runtime=3999423 [ns] vruntime=7876...

上面输出对应的每一个事件 (如 sched:sched_stat_runtime)，都与内核调度器相关代码里的tracepoint相对应，这些 tracepoint 都可以使用perf record 来直接激活并且记录其对应事件。如前文所示，这些原始调度事件 (raw event) 可以用来帮助理解和解释其它perf sched 子命令的相关输出。