Linux perf 在 Linux 4.10 中获得了新的 CPU 调度程序分析视图：perf sched timehist。由于我之前没有讨论过 perf sched，所以我将在这里总结它的功能。如果您赶时间，只需浏览以下屏幕截图可能会有所帮助，以便您了解可用的内容。（我也将此内容添加到我的性能示例页面。）
perf sched使用转储和后处理方法来分析调度程序事件，这可能是一个问题，因为这些事件可能非常频繁——每秒数百万——花费 CPU、内存和磁盘开销来记录。我最近一直在使用eBPF/bcc（包括runqlat）编写调度程序分析工具，这让我通过使用内核摘要大大减少了开销。但是在某些情况下，您可能希望使用perf sched来捕获每个事件，尽管开销更高。想象一下在自动终止之前有五分钟的时间来分析一个糟糕的云实例，并且您想要捕获所有内容以供以后分析。
我将从记录一秒钟的事件开始：
perf sched 记录 – sleep 1
[性能记录：唤醒1次写入数据]
[性能记录：捕获并写入 1.886 MB perf.data（13502 个样本）]
那是 1.9 MB一秒，包括 13,502 个样本。大小和速率将与您的工作负载和 CPU 数量相关（此示例是运行软件构建的 8 CPU 服务器）。写入文件系统的方式已经过优化：它只唤醒一次以读取事件缓冲区并将它们写入磁盘，从而减少了开销。也就是说，检测所有调度程序事件并将事件数据写入文件系统仍然存在大量开销。这些事件：
perf 脚本 --header
========
拍摄于：2017 年 2 月 26 日星期日 19:40:00
主机名：bgregg-xenial
操作系统版本：4.10-虚拟
性能版本：4.10
拱门：x86_64
#nrcpus 在线 : 8
nrcpus 有效：8
cpudesc : Intel(R) Xeon(R) CPU E5-2680 v2 @ 2.80GHz
cpuid : 正版Intel,6,62,4
总内存：15401700 kB
cmdline : /usr/bin/perf sched 记录 – sleep 1
事件 : 名称 = sched:sched_switch , , id = { 2752, 2753, 2754, 2755, 2756, 2757, 2758, 2759…
事件：名称 = sched:sched_stat_wait , , id = { 2760, 2761, 2762, 2763, 2764, 2765, 2766, 2…
事件：名称 = sched:sched_stat_sleep , , id = { 2768, 2769, 2770, 2771, 2772, 2773, 2774, …
事件：名称 = sched:sched_stat_iowait , , id = { 2776, 2777, 2778, 2779, 2780, 2781, 2782,…
事件：名称 = sched:sched_stat_runtime , , id = { 2784, 2785, 2786, 2787, 2788, 2789, 2790…
事件：名称 = sched:sched_process_fork , , id = { 2792, 2793, 2794, 2795, 2796, 2797, 2798…
事件：名称 = sched:sched_wakeup , , id = { 2800, 2801, 2802, 2803, 2804, 2805, 2806, 2807…
事件：名称 = sched:sched_wakeup_new , , id = { 2808, 2809, 2810, 2811, 2812, 2813, 2814, …
事件：名称 = sched:sched_migrate_task , , id = { 2816, 2817, 2818, 2819, 2820, 2821, 2822…
HEADER_CPU_TOPOLOGY 信息可用，使用 -I 显示
HEADER_NUMA_TOPOLOGY 信息可用，使用 -I 显示
pmu 映射：断点 = 5，功率 = 7，软件 = 1，跟踪点 = 2，msr = 6
HEADER_CACHE 信息可用，使用 -I 显示
缺少功能：HEADER_BRANCH_STACK HEADER_GROUP_DESC HEADER_AUXTRACE HEADER_STAT
========
性能 16984 [005] 991962.879966: sched:sched_wakeup: comm=perf pid=16999 prio=120 target_cpu=005
[…]
可以通过多种方式报告捕获的跟踪文件，帮助消息总结如下：
#性能调度 -h
用法：perf sched {记录| 延迟|地图|重播|脚本|timehist }
-D, --dump-raw-trace 以 ASCII 格式转储原始跟踪
-f, --force 不要抱怨，去做
-i，--输入 输入文件名
-v, --verbose 更详细（显示符号地址等）
perf sched 延迟将按任务汇总调度程序延迟，包括平均和最大延迟：
# perf 调度延迟
-----------------------------------------------------------------------------------------------------------------
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 毫秒的事件。 以下是 perf sched 脚本的原始事件：
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 ms。 此进程在原始事件中被列为“sh”（shell），但不久之后执行“cat”，因此在 perf sched 延迟输出中显示为“cat”。
perf sched map 显示所有 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)。
perf sched timehist在 Linux 4.10 中添加，并按事件显示调度程序延迟，包括任务等待唤醒的时间（等待时间）和唤醒到运行后的调度程序延迟（sch delay）。我们对调优更感兴趣的是调度程序延迟。示例输出：
# perf sched timehist
样本没有调用链。
time cpu 任务名称 等待时间 sch delay 运行时间
[时间/pid] (msec) (msec) (msec)
--------------- ------ ------------------------------ --------- --------- ---------
991962.879971 [0005] 性能 [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] 性能 [16999] 0.000 0.005 0.285
991962.880276 [0005] 迁移/5[39] 0.000 0.007 0.019
991962.880687 [0005] 性能 [16984] 0.304 0.000 0.411
991962.881839 [0003] 猫 [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] 睡眠[16999] 1000.104 0.006 0.269
991963.886018 [0005] cc1[17083] 19.998 0.000 9.948
此输出包括sleep命令运行以将 perf 本身的持续时间设置为一秒。请注意，sleep的等待时间是 1000.104 毫秒，因为我运行了“sleep 1”：这是它在等待定时器唤醒事件时处于睡眠状态的时间。它的调度器延迟只有 0.006 毫秒，而它在 CPU 上的时间是 0.269 毫秒。
timehist 有许多选项，包括 -V 添加 CPU 可视化列，-M 添加迁移事件，以及 -w 唤醒事件。例如：
# perf sched timehist -MVw
样本没有调用链。
time cpu 012345678 任务名称 等待时间 sch delay 运行时间
[时间/pid] (msec) (msec) (msec)
--------------- ------ --------- ------------------ --------- --------- ---------
991962.879966 [0005] 性能 [16984] 唤醒：性能 [16999]
991962.879971 [0005] 性能 [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] 唤醒：ksoftirqd/0[6]
991962.880073 [0003] cc1[16945] 唤醒：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] 唤醒：迁移/5 [39]
991962.880256 [0005] 性能 [16999] 0.000 0.005 0.285
991962.880264 [0005] m 迁移/5[39] 迁移：性能 [16999] cpu 5 => 1
991962.880276 [0005] s 迁移/5[39] 0.000 0.007 0.019
991962.880682 [0005] m perf[16984] 已迁移：cc1[16996] cpu 0 => 5
991962.880687 [0005] 性能 [16984] 0.304 0.000 0.411
991962.881834 [0003] 猫[17022] 唤醒：：17020
...]
991963.885734 [0001] :17008[17008] 唤醒：睡眠 [16999]
991963.885740 [0001] s :17008[17008] 25.613 0.000 0.057
991963.886005 [0001] 睡眠[16999] 唤醒：性能 [16984]
991963.886009 [0001] 睡眠 [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 开始上下文切换到睡眠进程。该事件的列仍显示“：17008[17008]”，表示 CPU 上的内容，但未显示上下文切换（睡眠）的目标。它在原始事件中：
: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 命令在 sleep 运行时收到了唤醒（几乎可以肯定 sleep 唤醒其父进程，因为它已终止），然后我们在 sleep 停止运行的 991963.886009 上进行上下文切换，并打印出摘要：等待时间为 1000.104 毫秒（“睡眠 1”），调度程序延迟为 0.006 毫秒，CPU 运行时间为 0.269 毫秒。
在这里，我用红色的上下文切换目标的详细信息装饰了 timehist 输出：
991963.885734 [0001] :17008[17008] 唤醒：睡眠 [16999]
991963.885740 [0001] s :17008[17008] 25.613 0.000 0.057 下一个：睡眠[16999]
991963.886005 [0001] 睡眠[16999] 唤醒：性能 [16984]
991963.886009 [0001] s 睡眠[16999] 1000.104 0.006 0.269 下一个：cc1 [17008]
991963.886018 [0005] s cc1 [17083] 19.998 0.000 9.948 下一个：性能[16984]
当睡眠结束时，一个等待的“cc1”进程然后执行。perf 在以下上下文切换上运行，并且是配置文件中的最后一个事件（perf 终止）。我已经提交了一个补丁来在使用 -n 选项时添加此信息。
perf sched 脚本转储所有事件（类似于perf 脚本）：
perf 调度脚本
perf 16984 [005] 991962.879960: sched:sched_stat_runtime: comm=perf pid=16984 runtime=3901506 [ns] vruntime=165 ...
性能 16984 [005] 991962.879966: sched:sched_wakeup: comm=perf pid=16999 prio=120 target_cpu=005
性能 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 记录直接检测的跟踪点。正如我之前所展示的，这个原始输出对于深入挖掘比汇总命令有用。
现在就是这样。狩猎愉快。
转载翻译自: https://www.brendangregg.com