问题描述
从 a great answer 开始,我的理解是每次事件计数器超过阈值时 perf
都会采样。当要求以特定频率进行采样时,它会尝试设置事件计数器阈值,以便通过调整其对每次事件率的估计,以指定的间隔发生溢出。
我在问自己这是如何处理多个线程的,例如使用默认的“cycles”事件。
- 是否有一个全局“周期”计数器可以对发生溢出时正在运行的任何线程进行采样?或者每个 cpu 是否都有自己的“周期”计数器来对当前正在运行的线程进行采样,如果是,“每个 cpu”是指逻辑内核还是物理内核?还是每个线程都有一个计数器?
- 是否只计算用于运行程序的周期?
我希望能够解释这样的模式——显然事件发生率正在重新校准,但我不清楚为什么:
tid timestamp event counter
5881 187296.210979: 15736902 cycles:
5881 187296.215945: 15664720 cycles:
5881 187296.221356: 15586918 cycles:
5881 187296.227022: 1 cycles:
5881 187296.227032: 1 cycles:
5881 187296.227037: 62 cycles:
5881 187296.227043: 6902 cycles:
5881 187296.227048: 822728 cycles:
5881 187296.231842: 90947120 cycles:
我希望它计算每个样本的下一个计数器阈值,所以在 187296.215945
的样本之后,它设置下一个样本在 15586918
周期后发生,对吗?但是在之前200Hz的目标频率已经稳定的情况下,将187296.221356
后的阈值设置为1个周期是没有意义的。这是来自另一个线程的干扰吗?
解决方法
免责声明
我不是这方面的专家,但我觉得这个问题很有趣,所以我试着想出一个答案。对这个答案持保留态度。欢迎更正 -- 也许 Cunningham's law 会给我们更好的答案。
cycles
映射到什么
根据 perf wiki,在 Intel 上,perf 使用 UNHALTED_CORE_CYCLES
事件。
配置工具和计数器在共享处理器内核的逻辑处理器之间不共享。
对于 AMD,perf wiki 表示使用了 CPU_CLK_UNHALTED
硬件事件。我在当前的 Preliminary Processor Programming Reference (PPR) for AMD Family 19h Model 01h,Revision B1 Processors Volume 2 of 2 中找不到此事件,但我在第 2.1.17.1 节中找到了:
每个线程有六个核心性能事件计数器,每个 L3 复合体有六个性能事件计数器和四个数据 Fabric 性能事件计数器
我认为处理器支持跟踪每个逻辑核心的 cycles
事件,我认为它在 ARM 和其他架构上是相似的(否则,我认为性能计数器的用处会小很多)
性能的作用
现在执行has different sampling modes:
perf 工具可用于在每个线程、每个进程、每个 CPU 或系统范围的基础上计算事件。在每线程模式下,计数器仅监控指定线程的执行。当线程被调度出去时,监控停止。当线程从一个处理器迁移到另一个处理器时,计数器会保存在当前处理器上,并在新处理器上恢复。
默认情况下,perf 记录在每线程模式下运行,启用继承模式。
从这些来源来看,我希望 perf 有以下行为:
- 当线程开始在内核上执行时,性能计数器会重置
- 当线程运行时,每当计数器溢出时,就会进行采样
- 如果线程停止执行,则监控停止
您的问题
所以,我的结论是
是否有一个全局“周期”计数器可以对发生溢出时正在运行的任何线程进行采样?还是每个 CPU 都有自己的“周期”计数器来采样当前正在运行的线程,如果是,“每个 CPU”是指逻辑内核还是物理内核?
每个逻辑核心都有自己的计数器。
还是每个线程一个计数器?
它是 cpu 内核上的硬件计数器,但 perf 允许您像按线程一样使用它——如果调度了不同程序的线程,这对您不应该有任何影响。默认情况下,perf 不会为存储在 perf.data
中的样本注释线程信息。根据{{3}},您可以使用-s
或--stat
来存储此信息。然后,性能报告将允许您分析应用程序的各个线程。
是否只计算运行程序所花费的周期?
是的,除非另有说明。
你的输出
tid timestamp event counter
5881 187296.210979: 15736902 cycles:
5881 187296.215945: 15664720 cycles:
5881 187296.221356: 15586918 cycles:
5881 187296.227022: 1 cycles:
5881 187296.227032: 1 cycles:
5881 187296.227037: 62 cycles:
5881 187296.227043: 6902 cycles:
5881 187296.227048: 822728 cycles:
5881 187296.231842: 90947120 cycles:
你执行了什么来得到这个输出?也许我误解了,但我猜发生了以下情况:
下面的实验部分使这里的观点无效
- 您使用指定的目标频率进行录制。这意味着 perf 会尝试优化硬件计数器的当前溢出值,以便您每秒获得指定数量的循环溢出。
- 对于前三个时间戳,您的程序线程在 CPU 上执行,这触发了高
cycles
计数。 perf 大约每 0.005 秒采样一次。 - 然后,您的线程似乎不再以每秒那么多 cpu 周期执行。也许它大部分时间都在等待 IO 操作?* 因此,下一个样本是在 0.006 秒后进行的,并且周期数下降到 1。 perf 注意到实际采样频率已经下降,因此它降低了溢出阈值,以保持采样率稳定。
- 然后,也许 IO 操作已完成,您的线程又开始以每秒更多的 cpu 周期运行。这导致了大量循环事件,但由于溢出阈值较低,perf 现在在较少的事件后(在接下来的 3 个样本的 0.00001s 和 0.000005s 之后)进行采样。在此期间,Perf 增加了溢出阈值。
- 对于最后一个样本,它似乎已经回到样本之间大约 0.005 秒的距离
实验
我认为以下内容可能会提供更多见解。让我们创建一个小的、易于理解的工作负载:
int main() {
volatile unsigned int i = 0;
while(1) {
i++;
}
}
gcc the man page:内存加载、增量、内存存储、跳转。根据 htop 的说法,这使用了一个逻辑核心,正如您所期望的那样。我可以模拟它停止执行,就好像它正在等待 IO 或未调度一样,只需在 shell 中使用 ctrl+Z 将其挂起即可。
现在,我们运行
perf record -F 10 -p $(pidof my_workload)
让它运行一会儿。然后,使用 ctrl+Z 暂停执行。稍等片刻,然后使用 fg
恢复执行。几秒钟后,结束程序。
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0,021 MB perf.data (65 samples) ]
就我而言,perf record 写入了 65 个样本。我们可以使用 perf 脚本来检查写入的样本数据并获取(完整输出,因为我认为我可能不小心删除了一些重要的东西。这是在 Intel i5-6200U、Ubuntu 20.04、内核 5.4.0-72-generic 上):
my_workload 831622 344935.025844: 1 cycles: ffffffffa0673594 native_write_msr+0x4 ([kernel.kallsyms])
my_workload 831622 344935.025847: 1 cycles: ffffffffa0673594 native_write_msr+0x4 ([kernel.kallsyms])
my_workload 831622 344935.025849: 2865 cycles: ffffffffa0673594 native_write_msr+0x4 ([kernel.kallsyms])
my_workload 831622 344935.025851: 16863383 cycles: ffffffffa12016f2 nmi_restore+0x25 ([kernel.kallsyms])
my_workload 831622 344935.031948: 101431200645 cycles: 558f3623317e main+0x15 (/tmp/my_workload)
my_workload 831622 344935.693910: 269342015 cycles: 558f36233178 main+0xf (/tmp/my_workload)
my_workload 831622 344935.794233: 268586235 cycles: 558f36233178 main+0xf (/tmp/my_workload)
my_workload 831622 344935.893934: 269806654 cycles: 558f3623317b main+0x12 (/tmp/my_workload)
my_workload 831622 344935.994321: 269410272 cycles: 558f3623317b main+0x12 (/tmp/my_workload)
my_workload 831622 344936.094938: 271951524 cycles: 558f36233178 main+0xf (/tmp/my_workload)
my_workload 831622 344936.195815: 269543174 cycles: 558f3623317e main+0x15 (/tmp/my_workload)
my_workload 831622 344936.295978: 269967653 cycles: 558f3623317b main+0x12 (/tmp/my_workload)
my_workload 831622 344936.397041: 266160499 cycles: 558f3623317b main+0x12 (/tmp/my_workload)
my_workload 831622 344936.497782: 265215251 cycles: 558f3623317e main+0x15 (/tmp/my_workload)
my_workload 831622 344936.596074: 269863048 cycles: 558f36233178 main+0xf (/tmp/my_workload)
my_workload 831622 344936.696280: 269857624 cycles: 558f36233178 main+0xf (/tmp/my_workload)
my_workload 831622 344936.796730: 269274440 cycles: 558f36233178 main+0xf (/tmp/my_workload)
my_workload 831622 344936.897487: 269115742 cycles: 558f36233178 main+0xf (/tmp/my_workload)
my_workload 831622 344936.997988: 266867300 cycles: 558f36233178 main+0xf (/tmp/my_workload)
my_workload 831622 344937.097088: 269734778 cycles: 558f3623317e main+0x15 (/tmp/my_workload)
my_workload 831622 344937.196955: 270487956 cycles: 558f3623317b main+0x12 (/tmp/my_workload)
my_workload 831622 344937.297281: 270136625 cycles: 558f3623317e main+0x15 (/tmp/my_workload)
my_workload 831622 344937.397516: 269741183 cycles: 558f3623317b main+0x12 (/tmp/my_workload)
my_workload 831622 344943.438671: 173595673 cycles: 558f3623317e main+0x15 (/tmp/my_workload)
my_workload 831622 344943.512800: 251467821 cycles: 558f3623317b main+0x12 (/tmp/my_workload)
my_workload 831622 344943.604016: 274913168 cycles: 558f3623317e main+0x15 (/tmp/my_workload)
my_workload 831622 344943.703440: 276448269 cycles: 558f3623317b main+0x12 (/tmp/my_workload)
my_workload 831622 344943.803753: 275059394 cycles: 558f36233178 main+0xf (/tmp/my_workload)
my_workload 831622 344943.903362: 276318281 cycles: 558f3623317e main+0x15 (/tmp/my_workload)
my_workload 831622 344944.005543: 266874454 cycles: 558f3623317b main+0x12 (/tmp/my_workload)
my_workload 831622 344944.105663: 268220344 cycles: 558f3623317b main+0x12 (/tmp/my_workload)
my_workload 831622 344944.205213: 269369912 cycles: 558f3623317b main+0x12 (/tmp/my_workload)
my_workload 831622 344944.305541: 267387036 cycles: 558f3623317b main+0x12 (/tmp/my_workload)
my_workload 831622 344944.405660: 266906130 cycles: 558f3623317e main+0x15 (/tmp/my_workload)
my_workload 831622 344944.506126: 266194513 cycles: 558f36233178 main+0xf (/tmp/my_workload)
my_workload 831622 344944.604879: 268882693 cycles: 558f3623317e main+0x15 (/tmp/my_workload)
my_workload 831622 344944.705588: 266555089 cycles: 558f3623317e main+0x15 (/tmp/my_workload)
my_workload 831622 344944.804896: 268419478 cycles: 558f36233178 main+0xf (/tmp/my_workload)
my_workload 831622 344944.905269: 267700541 cycles: 558f36233178 main+0xf (/tmp/my_workload)
my_workload 831622 344945.004885: 267365839 cycles: 558f3623317b main+0x12 (/tmp/my_workload)
my_workload 831622 344945.103970: 269655126 cycles: 558f3623317e main+0x15 (/tmp/my_workload)
my_workload 831622 344945.203823: 269330033 cycles: 558f36233178 main+0xf (/tmp/my_workload)
my_workload 831622 344945.304258: 267423569 cycles: 558f3623317e main+0x15 (/tmp/my_workload)
my_workload 831622 344945.403472: 269773962 cycles: 558f3623317e main+0x15 (/tmp/my_workload)
my_workload 831622 344945.504194: 275795565 cycles: 558f3623317e main+0x15 (/tmp/my_workload)
my_workload 831622 344945.606329: 271013012 cycles: 558f3623317e main+0x15 (/tmp/my_workload)
my_workload 831622 344945.703866: 277537908 cycles: 558f3623317b main+0x12 (/tmp/my_workload)
my_workload 831622 344945.803821: 277559915 cycles: 558f3623317e main+0x15 (/tmp/my_workload)
my_workload 831622 344945.904299: 277242574 cycles: 558f36233178 main+0xf (/tmp/my_workload)
my_workload 831622 344946.005167: 272430392 cycles: 558f3623317b main+0x12 (/tmp/my_workload)
my_workload 831622 344946.104424: 275291909 cycles: 558f3623317b main+0x12 (/tmp/my_workload)
my_workload 831622 344946.204402: 275331204 cycles: 558f3623317b main+0x12 (/tmp/my_workload)
my_workload 831622 344946.304334: 273818645 cycles: 558f3623317b main+0x12 (/tmp/my_workload)
my_workload 831622 344946.403674: 275723986 cycles: 558f3623317e main+0x15 (/tmp/my_workload)
my_workload 831622 344946.456065: 1 cycles: ffffffffa0673594 native_write_msr+0x4 ([kernel.kallsyms])
my_workload 831622 344946.456069: 1 cycles: ffffffffa0673594 native_write_msr+0x4 ([kernel.kallsyms])
my_workload 831622 344946.456071: 2822 cycles: ffffffffa0673594 native_write_msr+0x4 ([kernel.kallsyms])
my_workload 831622 344946.456072: 17944993 cycles: ffffffffa0673596 native_write_msr+0x6 ([kernel.kallsyms])
my_workload 831622 344946.462714: 107477037825 cycles: 558f36233178 main+0xf (/tmp/my_workload)
my_workload 831622 344946.804126: 281880047 cycles: 558f3623317e main+0x15 (/tmp/my_workload)
my_workload 831622 344946.907508: 274093449 cycles: 558f36233178 main+0xf (/tmp/my_workload)
my_workload 831622 344947.007473: 270795847 cycles: 558f36233178 main+0xf (/tmp/my_workload)
my_workload 831622 344947.106277: 275006801 cycles: 558f36233178 main+0xf (/tmp/my_workload)
my_workload 831622 344947.205757: 274972888 cycles: 558f36233178 main+0xf (/tmp/my_workload)
my_workload 831622 344947.305405: 274436774 cycles: 558f3623317b main+0x12 (/tmp/my_workload)
我认为我们可以在此输出中看到两个主要内容
- 344937.397516 处的样本似乎是我暂停程序之前的最后一个样本,而 344943.438671 似乎是它恢复后的第一个样本。我们这里的周期数略低。除此之外,它看起来就像其他行一样。
- 但是,您的模式可以在启动后直接找到——我会说这是预料之中的——并且在时间戳 344946.456065 处。通过注释
native_write_msr
,我认为我们在这里观察到的是执行内部工作的性能。关于native_write_msr
的作用有 compiles the loop to four instructions。根据 Peter 对该问题的评论,这是内核编程硬件性能计数器。还是有点奇怪。也许,在将当前缓冲区写入 perf.data 之后,perf 的行为就像它刚刚启动一样?
* 正如 Jérôme 在评论中指出的,cycles
事件发生较少的原因可能有很多。我猜你的程序没有被执行,因为它正在睡眠或等待 IO 或内存访问。也有可能您的程序根本没有安排在此期间由操作系统运行。
如果您测量的不是特定的工作负载,而是您的一般系统,那么 CPU 也可能会降低时钟频率或进入睡眠状态,因为它没有工作可做。我假设您可能在 my_program 是 CPU 密集型工作负载时执行了类似 perf record ./my_program
的操作,因此认为 CPU 不太可能决定休眠。