用于 Linux CPU 调度程序分析的性能调度
Linux perf 在 Linux 4.10 中获得了一个新的 CPU 调度程序分析视图：perf sched timehist。由于我之前没有讨论过性能调度，我将在这里总结它的功能。如果您赶时间，浏览以下屏幕截图可能会有所帮助，以便您了解可用的内容。（我已将此内容添加到我的性能示例页面。
Perf Sched 使用转储和后处理方法来分析调度程序事件，这可能是一个问题，因为这些事件可能非常频繁（每秒数百万个），需要花费 CPU、内存和磁盘开销来记录。我最近一直在使用 eBPF/bcc（包括 runqlat）编写调度程序分析工具，这让我通过使用内核内摘要大大减少了开销。但在某些情况下，您可能希望改用性能调度来捕获每个事件，尽管开销更高。想象一下，在自动终止之前，有五分钟的时间分析一个坏的云实例，并且您希望捕获所有内容以供以后分析。
我将首先记录一秒钟的事件：
# 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 服务器）。它如何写入文件系统已经优化：它只唤醒一次读取事件缓冲区并将它们写入磁盘，从而减少了开销。也就是说，检测所有调度程序事件并将事件数据写入文件系统仍然存在大量开销。这些事件：
# 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 -h
Usage: 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)
性能计划延迟将按任务汇总计划程序延迟，包括平均和最大延迟：
# 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 s
ar:17043 | 3.191 ms | 1 | avg: 13.638 ms | max: 13.638 ms | max at: 991963.048070 s
rm:(10) | 20.955 ms | 10 | avg: 11.212 ms | max: 19.598 ms | max at: 991963.404069 s
objdump:(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 s
grep:(7) | 21.655 ms | 11 | avg: 9.465 ms | max: 24.502 ms | max at: 991963.464082 s
fixdep:(6) | 81.066 ms | 8 | avg: 9.023 ms | max: 19.521 ms | max at: 991963.120068 s
mv:(10) | 30.249 ms | 14 | avg: 8.380 ms | max: 21.688 ms | max at: 991963.200073 s
ld:(3) | 14.353 ms | 6 | avg: 7.376 ms | max: 15.498 ms | max at: 991963.452070 s
recordmcount:(7) | 14.629 ms | 9 | avg: 7.155 ms | max: 18.964 ms | max at: 991963.292100 s
svstat:17067 | 1.862 ms | 1 | avg: 6.142 ms | max: 6.142 ms | max at: 991963.280069 s
cc1:(21) | 6013.457 ms | 1138 | avg: 5.305 ms | max: 44.001 ms | max at: 991963.436070 s
gcc:(18) | 43.596 ms | 40 | avg: 3.905 ms | max: 26.994 ms | max at: 991963.380069 s
ps:17073 | 27.158 ms | 4 | avg: 3.751 ms | max: 8.000 ms | max at: 991963.332070 s
...]
为了阐明如何检测和计算它，我将展示导致顶级事件的“最大延迟”为 29.702 毫秒的事件。以下是来自性能调度脚本的原始事件：
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=120
prev_state=R ==> next_comm=sh next_pid=17030 next_prio=120
[...]
从唤醒（991962.918368，以秒为单位）到上下文切换 （991962.948070） 的时间为 29.702 毫秒。此过程在原始事件中列为“sh”（shell），但不久后列为“cat”，因此在性能调度延迟输出中显示为“cat”。
性能调度图显示所有 CPU 和上下文切换事件，其中列表示每个 CPU 正在执行的操作和时间。这是您在调度程序分析 GUI（包括性能时间表，布局旋转 90 度）中看到的可视化数据类型。示例输出：
# perf sched map
*A0 991962.879971 secs A0 => perf:16999
A0 *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:6
D0 C0 *E0 A0 B0 991962.880081 secs E0 => ksoftirqd/3:28
D0 C0 *F0 A0 B0 991962.880093 secs F0 => :17022:17022
*G0 C0 F0 A0 B0 991962.880108 secs G0 => :17016:17016
G0 C0 F0 *H0 B0 991962.880256 secs H0 => migration/5:39
G0 C0 F0 *I0 B0 991962.880276 secs I0 => perf:16984
G0 C0 F0 *J0 B0 991962.880687 secs J0 => cc1:16996
G0 C0 *K0 J0 B0 991962.881839 secs K0 => cc1:16945
G0 C0 K0 J0 *L0 B0 991962.881841 secs L0 => :17020:17020
G0 C0 K0 J0 *M0 B0 991962.882289 secs M0 => make:16637
G0 C0 K0 J0 *N0 B0 991962.883102 secs N0 => make:16545
G0 *O0 K0 J0 N0 B0 991962.883880 secs O0 => cc1:16819
G0 *A0 O0 K0 J0 N0 B0 991962.884069 secs
G0 A0 O0 K0 *P0 J0 N0 B0 991962.884076 secs P0 => rcu_sched:7
G0 A0 O0 K0 *Q0 J0 N0 B0 991962.884084 secs Q0 => cc1:16831
G0 A0 O0 K0 Q0 J0 *R0 B0 991962.884843 secs R0 => cc1:16825
G0 *S0 O0 K0 Q0 J0 R0 B0 991962.885636 secs S0 => cc1:16900
G0 S0 O0 *T0 Q0 J0 R0 B0 991962.886893 secs T0 => :17014:17014
G0 S0 O0 *K0 Q0 J0 R0 B0 991962.886917 secs
[...]
这是一个 8 个 CPU 的系统，您可以从左侧开始看到每个 CPU 的 8 列。某些 CPU 列以空白开头，因为我们尚未在配置文件开始时跟踪该 CPU 上的事件。他们很快就被覆盖了。
您看到的两个字符代码（“A0”、“C0”）是任务的标识符，它们映射在右侧（“=>”）。这比使用进程（任务）ID 更紧凑。“*”显示哪个 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 将其用作维度，这更容易理解，但此处仅列出了数字）。它也只显示上下文切换事件，而不显示调度程序延迟。较新的 timehist 命令具有可包含唤醒事件的可视化效果 （-V）。
在 Linux 4.10 中添加了 perf sched timehist，并按事件显示调度程序延迟，包括任务等待唤醒的时间（等待时间）和唤醒后调度程序延迟（sch 延迟）。我们更感兴趣的是调度程序延迟。示例输出：
# 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
此输出包括 sleep 命令运行，用于将 perf 本身的持续时间设置为 1 秒。请注意，睡眠的等待时间为 1000.104 毫秒，因为我运行了“睡眠 1”：这是它等待计时器唤醒事件进入睡眠状态的时间。它的调度程序延迟仅为 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.000
991962.880070 [0007] s :17008[17008] 0.000 0.000 0.000
991962.880070 [0002] s cc1[16880] 0.000 0.000 0.000
991962.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.000
991962.880081 [0003] s cc1[16945] 0.000 0.000 0.000
991962.880093 [0003] s ksoftirqd/3[28] 0.000 0.007 0.012
991962.880108 [0000] s ksoftirqd/0[6] 0.000 0.007 0.030
991962.880249 [0005] perf[16999] awakened: migration/5[39]
991962.880256 [0005] s perf[16999] 0.000 0.005 0.285
991962.880264 [0005] m migration/5[39] migrated: perf[16999] cpu 5 => 1
991962.880276 [0005] s migration/5[39] 0.000 0.007 0.019
991962.880682 [0005] m perf[16984] migrated: cc1[16996] cpu 0 => 5
991962.880687 [0005] s perf[16984] 0.304 0.000 0.411
991962.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.057
991963.886005 [0001] sleep[16999] awakened: perf[16984]
991963.886009 [0001] s sleep[16999] 1000.104 0.006 0.269
991963.886018 [0005] s cc1[17083] 19.998 0.000 9.948
CPU 可视化列 （“012345678”） 包含“s”表示上下文切换事件，“m”表示迁移事件，显示事件的 CPU。
该输出中的最后一个事件包括与用于计时性能的“sleep 1”命令相关的事件。唤醒发生在 991963.885734，在 991963.885740（6 微秒后）CPU 1 开始上下文切换到睡眠进程。该事件的列仍显示 CPU 上内容的“：17008[17008]”，但不显示上下文切换（睡眠）的目标。它在原始事件中：
:17008 17008 [001] 991963.885740: sched:sched_switch: prev_comm=cc1 prev_pid=17008 prev_prio=120
prev_state=R ==> next_comm=sleep next_pid=16999 next_prio=120
991963.886005 事件显示 perf 命令在睡眠运行时收到唤醒（几乎可以肯定睡眠唤醒了其父进程，因为它终止了），然后我们在 991963.886009 上有上下文开关，其中睡眠停止运行，并打印出摘要：1000.104 毫秒等待（“睡眠 1”），调度程序延迟为 0.006 毫秒， 和 0.269 毫秒的 CPU 运行时。
在这里，我用红色的上下文切换目标的详细信息装饰了 timehist 输出：
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]
睡眠结束后，将执行等待的“cc1”进程。性能在以下上下文切换上运行，并且是配置文件中的最后一个事件（性能终止）。我已经提交了一个补丁，以便在使用 -n 选项时添加此信息。
性能调度脚本转储所有事件（类似于性能脚本）：
# perf sched script
perf 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=005
perf 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”等）都是可以使用 perf 记录直接检测的跟踪点。如前所述，此原始输出可用于比摘要命令更深入的挖掘。
请先 后发表评论～