【发布时间】:2017-02-13 08:02:09
【问题描述】:
一段时间以来,我一直在使用 Linux perf 进行应用程序分析。通常,经过分析的应用程序相当复杂,因此人们往往会简单地将所报告的计数器值视为表面价值,只要与您根据第一原则所期望的值没有任何严重差异。
然而,最近,我分析了一些琐碎的 64 位汇编程序 - 琐碎到可以几乎准确地计算出各种计数器的预期值,而且似乎 perf stat 计数过多。
以如下循环为例:
.loop:
nop
dec rax
nop
jne .loop
这将简单地循环n 次,其中n 是rax 的初始值。循环的每次迭代执行 4 条指令,因此您会期望执行 4 * n 指令,加上一些小的固定开销用于进程启动和终止,以及在进入循环之前设置 n 的一小段代码。
这是n = 1,000,000,000 的(典型)perf stat 输出:
~/dev/perf-test$ perf stat ./perf-test-nop 1
Performance counter stats for './perf-test-nop 1':
301.795151 task-clock (msec) # 0.998 CPUs utilized
0 context-switches # 0.000 K/sec
0 cpu-migrations # 0.000 K/sec
2 page-faults # 0.007 K/sec
1,003,144,430 cycles # 3.324 GHz
4,000,410,032 instructions # 3.99 insns per cycle
1,000,071,277 branches # 3313.742 M/sec
1,649 branch-misses # 0.00% of all branches
0.302318532 seconds time elapsed
嗯。我们看到的不是大约 4,000,000,000 条指令和 1,000,000,000 个分支,而是神秘的额外 410,032 条指令和 71,277 个分支。总是有“额外”指令,但数量略有不同 - 例如,后续运行分别有 421K、563K 和 464K extra 指令。您可以通过构建我的simple github project 在您的系统上自己运行它。
好的,所以你可能会猜到这几十万条额外的指令只是固定的应用程序设置和拆卸成本(用户空间设置是very small,但可能有隐藏的东西)。那就试试n=10 billion吧:
~/dev/perf-test$ perf stat ./perf-test-nop 10
Performance counter stats for './perf-test-nop 10':
2907.748482 task-clock (msec) # 1.000 CPUs utilized
3 context-switches # 0.001 K/sec
0 cpu-migrations # 0.000 K/sec
2 page-faults # 0.001 K/sec
10,012,820,060 cycles # 3.443 GHz
40,004,878,385 instructions # 4.00 insns per cycle
10,001,036,040 branches # 3439.443 M/sec
4,960 branch-misses # 0.00% of all branches
2.908176097 seconds time elapsed
现在有大约 490 万条额外指令,比以前增加了大约 10 倍,与循环次数增加 10 倍成正比。
您可以尝试各种计数器 - 所有与 CPU 相关的计数器都显示类似的比例增加。然后让我们关注指令计数以保持简单。分别使用:u 和:k 后缀测量user 和kernel 计数表明,kernel 中发生的计数几乎占所有额外的事件:
~/dev/perf-test$ perf stat -e instructions:u,instructions:k ./perf-test-nop 1
Performance counter stats for './perf-test-nop 1':
4,000,000,092 instructions:u
388,958 instructions:k
0.301323626 seconds time elapsed
宾果游戏。在 389,050 条额外指令中,有 99.98% (388,958) 发生在内核中。
好的,但是这会给我们带来什么影响?这是一个微不足道的 CPU 绑定循环。它不进行任何系统调用,也不访问内存(可能通过缺页机制间接调用内核)。为什么内核代表我的应用程序执行指令?
这似乎不是由上下文切换或 CPU 迁移引起的,因为它们处于或接近于零,并且在任何情况下,extra 指令计数与更多的运行无关发生了这些事件。
额外内核指令的数量实际上与循环计数非常平滑。这是(数十亿次)循环迭代与内核指令的图表:
您可以看到,这种关系几乎是完全线性的——事实上,直到 15e9 次迭代,只有一个异常值。在那之后,似乎有两条单独的线,表明对导致多余时间的任何事物进行了某种量化。无论如何,在主循环中执行的每 1e9 条指令都会产生大约 35 万条内核指令。
最后,我注意到执行的内核指令的数量似乎与 runtime1(或 CPU 时间)成正比,而不是与执行的指令成正比。为了测试这一点,我使用了similar program,但将其中一条nop 指令替换为idiv,它的延迟约为40 个周期(删除了一些无趣的行):
~/dev/perf-test$ perf stat ./perf-test-div 10
Performance counter stats for './perf-test-div 10':
41,768,314,396 cycles # 3.430 GHz
4,014,826,989 instructions # 0.10 insns per cycle
1,002,957,543 branches # 82.369 M/sec
12.177372636 seconds time elapsed
在这里,我们花费了大约 42e9 个周期来完成 1e9 次迭代,并且我们有大约 14,800,000 条额外指令。相比之下,使用nop 的相同 1e9 循环只有约 400,000 条额外指令。如果我们与 nop 循环进行比较,该循环需要大约相同数量的 cycles(40e9 次迭代),我们会看到几乎完全相同数量的额外指令:
~/dev/perf-test$ perf stat ./perf-test-nop 41
Performance counter stats for './perf-test-nop 41':
41,145,332,629 cycles # 3.425
164,013,912,324 instructions # 3.99 insns per cycle
41,002,424,948 branches # 3412.968 M/sec
12.013355313 seconds time elapsed
内核中发生的这项神秘工作是怎么回事?
1 我在这里或多或少地互换使用术语“时间”和“周期”。 CPU 在这些测试期间会完全耗尽,因此以一些与涡轮增压相关的热效应为模,周期与时间成正比。
【问题讨论】:
-
perf 通过虚拟化硬件计数器,因此在执行到达对硬件计数器执行某些操作的 perf 代码之前,可能额外的指令在定时器(和其他)中断上。如果 IRQ 处理程序甚至用 perf 做 anything;如果他们只是接受来自 IRQ 处理程序的噪音被视为降低
perf开销的价格,我不会感到惊讶。我猜perf将硬件计数器添加到 64 位软件总数中只会发生在实际的上下文切换上,而不是 IRQ“上半部分”处理程序。 -
确实,我想到了中断,但我发现关于中断如何与
perf实际交互的信息很少。您是否在“... virtualizes the hardware counters by, ...”之后错过了一些文字? -
xD,是的,通过在上下文切换上将硬件计数器记录到 64 位软件计数器中来进行虚拟化。
-
@PeterCordes 这是 Linux 计时器,并且计数器也配置为在 OS 模式下计数。刚刚编写了一个性能计数器工具,我立即将注意力集中在the answer,它详细介绍了我的 LKM 和演示的一些内部工作原理。
标签: performance assembly linux-kernel x86 perf