使用 perf record 基于频率的多线程采样

Question

从开始，我的理解是每次事件计数器超过阈值时 perf 都会采样。当被要求以特定频率采样时，它会尝试设置事件计数器阈值，以便通过调整其对每次事件发生率的估计来在指定的时间间隔内发生溢出。

我在问自己这是如何处理多线程的，例如默认的“循环”事件。

是否有一个全局“周期”计数器可以在发生溢出时对运行的任何线程进行采样？还是每个 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 周期后发生，对吗？但是把187296.221356之后的阈值设置为1个周期就没有意义了，之前200Hz的目标频率已经稳定了。这是来自另一个线程的干扰吗？

Answer 1

免责声明

我不是这方面的专家，但我觉得这个问题很有趣，所以我试着想出一个答案。对这个答案持保留态度。欢迎更正 - 也许 Cunningham's law 会给我们更好的答案。

什么 `cycles` 映射到

根据 perf wiki，在 Intel 上，perf 使用 UNHALTED_CORE_CYCLES 事件。

来自Intel® 64 and IA-32 Architectures Software Developer’s Manual, Volume 4, 18.2.1 Architectural Performance Monitoring Version 1

Configuration facilities and counters are not shared between logical processors sharing a processor core.

对于 AMD，perf wiki 表示使用了 CPU_CLK_UNHALTED 硬件事件。我无法在当前的 AMD 系列 19h 型号 01h，版本 B1 处理器第 2 卷的初步处理器编程参考 (PPR) 中找到此事件，但我在第 2.1 节中找到了此事件。 17.1:

There are six core performance event counters per thread, six performance events counters per L3 complex and four Data Fabric performance events counters

我会得出结论，处理器支持跟踪每个逻辑核心的 cycles 事件，我认为它在 ARM 和其他架构上是相似的（否则，我认为性能计数器会少很多有用）

什么性能

现在执行 has different sampling modes:

The perf tool can be used to count events on a per-thread, per-process, per-cpu or system-wide basis. In per-thread mode, the counter only monitors the execution of a designated thread. When the thread is scheduled out, monitoring stops. When a thread migrated from one processor to another, counters are saved on the current processor and are restored on the new one.

and

By default, perf record operates in per-thread mode, with inherit mode enabled.

从这些来源，我希望 perf 有以下行为：

当线程开始在内核上执行时，性能计数器会重置
作为线程运行s，每当计数器溢出时，都会进行采样
如果线程停止执行，则监听停止

您的问题

所以，我的结论是

Is there a global "cycles" counter that samples whatever threads are running at the time when the overflow occurs? Or does each CPU have its own "cycles" counter that samples the thread that it is currently running, and if yes, does "each CPU" mean logical or physical cores?

每个逻辑核心都有自己的计数器。

Or is it a counter per thread?

它是 cpu 内核上的一个硬件计数器，但是 perf 允许您像每个线程一样使用它——如果调度了不同程序的线程，这应该不会有任何影响在你身上。默认情况下，perf 不会为 perf.data 中存储的样本注释线程信息。根据the man page，您可以使用-s或--stat来存储这些信息。然后，perf report 将允许您分析应用程序的各个线程。

Are only cycles counted that were spent running the program?

是的，除非另有说明。

你的输出

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 操作已完成并且您的线程再次开始运行ning 每秒更多 cpu 个周期。这导致了很多循环事件，但由于溢出阈值较低，perf 现在在更少的事件后获取样本（接下来的 3 个样本在 0.00001s 和 0.000005s 之后）。 Perf 在此期间增加了溢出阈值。
对于最后一个样本，它似乎已经返回到样本之间大约 0.005 秒的距离

实验

我认为以下内容可能会提供更多见解。让我们创建一个小的、易于理解的工作负载：

int main() {
    volatile unsigned int i = 0;
    while(1) {
        i++;
    }
}

gcc compiles the loop to four instructions：内存加载，增量，内存存储，跳转。根据 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-通用）：

     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 我认为我们在这里观察到的是 perf 做内部工作。 this question 关于 native_write_msr 的作用。根据 Peter 对该问题的评论，这是内核编程硬件性能计数器。还是有点奇怪。也许，在将当前缓冲区写出到 perf.data 之后，perf 的行为就像刚刚启动一样？

^* 正如 Jérôme 在评论中指出的那样，cycles 事件发生较少的原因可能有很多。我猜你的程序没有被执行是因为它正在休眠或等待 IO 或内存访问。也有可能是您的程序在此期间未被 OS 安排到运行。

如果您测量的不是特定的工作负载，而是您的一般系统，则 CPU 也可能会降低时钟频率或进入睡眠状态，因为它没有工作要做。我假设你可能做了类似 perf record ./my_program 的事情，而 my_program 是一个 CPU 密集的工作量，所以我认为 cpu 不太可能决定睡觉。

使用 perf record 基于频率的多线程采样

Frequency-based sampling of multiple threads with perf record

multithreading

profiling

perf

免责声明

什么 `cycles` 映射到

什么性能

您的问题

你的输出

实验

使用 perf record 基于频率的多线程采样

Frequency-based sampling of multiple threads with perf record

multithreading

profiling

perf

免责声明

什么 cycles 映射到

什么性能

您的问题

你的输出

实验

什么 `cycles` 映射到