具有性能记录的多线程基于频率的采样答案

【问题标题】：Frequency-based sampling of multiple threads with perf record具有性能记录的多线程基于频率的采样
【发布时间】：2021-08-15 19:39:09
【问题描述】：

从a great answer 开始，我的理解是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的目标频率已经稳定了。这是来自另一个线程的干扰吗？

【问题讨论】：

标签： multithreading profiling perf

【解决方案1】：

免责声明

我不是这个话题的专家，但我发现这个问题很有趣，所以我试图想出一个答案。对这个答案持保留态度。欢迎指正——也许Cunningham's law 会给我们更好的答案。

`cycles` 映射到什么

根据perf wiki，在英特尔上，perf 使用UNHALTED_CORE_CYCLES 事件。

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

配置工具和计数器不在共享处理器内核的逻辑处理器之间共享。

对于 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 或系统范围内对事件进行计数。在 per-thread 模式下，计数器只监视指定线程的执行。当线程被调度出去时，监控停止。当线程从一个处理器迁移到另一个处理器时，计数器会保存在当前处理器上并在新处理器上恢复。

and

默认情况下，perf 记录以每线程模式运行，并启用继承模式。

从这些来源中，我预计 perf 会出现以下行为：

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

您的问题

所以，我的结论是

是否有一个全局“循环”计数器可以对溢出发生时正在运行的任何线程进行采样？还是每个 CPU 都有自己的“周期”计数器来采样它当前正在运行的线程，如果是，“每个 CPU”是指逻辑内核还是物理内核？

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

还是每个线程都有一个计数器？

它是 cpu 内核上的硬件计数器，但 perf 允许您像使用每个线程一样使用它——如果调度了不同程序的线程，这对您没有任何影响。默认情况下，perf 不会将线程信息注释到存储在perf.data 中的样本中。根据the man page，您可以使用-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.00001 秒和 0.000005 秒之后）。在此期间，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) ]

在我的例子中，性能记录写了 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 的作用，有this question。根据彼得对该问题的评论，这是内核编程硬件性能计数器。还是有点奇怪。也许，在将当前缓冲区写入 perf.data 之后，perf 的行为就像它刚刚启动一样？

^* 正如 Jérôme 在 cmets 中指出的那样，cycles 事件发生较少的原因可能有很多。我猜您的程序没有执行，因为它正在休眠或等待 IO 或内存访问。也有可能您的程序根本没有被操作系统安排在这段时间内运行。

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

【讨论】：

请注意，现代处理器的内核在负载方面可能有不同的频率。此外，由于 C-States，一些可以进入睡眠模式，而另一些可以工作。最后，周期数强烈依赖于时间戳和频率。由于时间戳显然不是均匀分布的，因此周期可能不会太均匀。
好点。我添加了一个关于分析整个系统的注释，它是合理的内核进入睡眠状态。但是，我认为对于平均 perf record ./my_program 运行来说，这是不太可能的。我们正在积极运行我们的工作负载，并且只测量实际执行它的核心，所以如果这些核心进入睡眠状态，那将是非常奇怪的行为。
@JérômeRichard：注意 cycles 事件名称中的 UNHALTED。即使您正在分析有权使用mwait 或hlt 并将内核置于睡眠状态的内核线程，“循环”事件也不会触发，因为时钟会停止。（或者在某些极端情况下，例如热节流，或超低功耗 Skylake，它会以某个占空比停止/停止时钟，而不是仅仅将时钟降至低效频率。）
但是通常内核只会让内核进入休眠状态，此时内核上的schedule() 决定没有任务可以在其上运行。（并且使用 Linux PAPI（perf API）在上下文切换上虚拟化 perf 计数器，就像它虚拟化架构状态（寄存器）一样，这意味着您无法获得未“执行”的线程的计数，即使用 CPU 时间根据内核的计算。我假设我们谈论的是正常的性能记录，而不是-a 系统范围；那么“unhalted”参数变得很重要。）
@He3lixxx 不错的答案。关于令人困惑的输出，我意识到我的问题不是很清楚，因此我根据自己的期望对其进行了编辑。

免责声明

cycles 映射到什么

性能的作用

您的问题

你的输出

实验

`cycles` 映射到什么