使用性能记录对多线程进行基于频率的采样

Question

从这里的一个很好的答案来看，我的理解是perf每次事件计数器超过阈值时都会进行采样。当要求以特定频率采样时，它会尝试通过调整每次事件速率的估计来设置事件计数器阈值，以便在指定间隔发生溢出。

\n

我问自己这如何与多个线程一起工作，例如使用默认的“cycles”事件。

\n

\n
• 是否有一个全局“周期”计数器可以对溢出发生时正在运行的任何线程进行采样？或者每个 CPU 是否都有自己的“周期”计数器，用于对当前正在运行的线程进行采样，如果是，“每个 CPU”是指逻辑核心还是物理核心？或者它是每个线程的计数器？
\n
• 是否只计算运行程序所花费的周期？
\n

\n

我希望能够解释像这些 \xe2\x80\x93 这样的模式，显然事件的发生率正在重新校准，但我不清楚为什么：

\n

tid  timestamp        event counter\n5881 187296.210979:   15736902 cycles:\n5881 187296.215945:   15664720 cycles:\n5881 187296.221356:   15586918 cycles:\n5881 187296.227022:          1 cycles:\n5881 187296.227032:          1 cycles:\n5881 187296.227037:         62 cycles:\n5881 187296.227043:       6902 cycles:\n5881 187296.227048:     822728 cycles:\n5881 187296.231842:   90947120 cycles:\n

\n

我希望它计算每个样本的下一个计数器阈值，因此在 处的样本之后187296.215945，它会将下一个样本设置为在15586918循环后发生，对吗？187296.221356但当200Hz的目标频率之前已经稳定时，将阈值设置为1个周期之后是没有意义的。这是来自另一个线程的干扰吗？

\n

Answer 1

免责声明

\n

我不是这个话题的专家，但我发现这个问题很有趣，所以我试图给出一个答案。对这个答案持保留态度。欢迎更正——也许还有坎宁安定律会给我们更好的答案。

\n

什么cycles映射到

\n

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

\n

来自Intel\xc2\xae 64 和 IA-32 架构软件开发人员\xe2\x80\x99s 手册，第 4 卷，18.2.1 架构性能监控版本 1

\n

\n

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

\n

\n

对于 AMD，perf wiki声明CPU_CLK_UNHALTED使用硬件事件。我在当前AMD 系列 19h 型号 01h、修订版 B1 处理器第 2 卷（共 2 卷）的初步处理器编程参考 (PPR)中找不到此事件，但我在第 2.1.17.1 节中找到了此事件：

\n

\n

每个线程有 6 个核心性能事件计数器，每个 L3 复合体有 6 个性能事件计数器，以及 4 个 Data\nFabric 性能事件计数器

\n

\n

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

\n

perf 的作用是什么

\n

现在 perf有不同的采样模式：

\n

\n

perf 工具可用于对每个线程、每个进程、每个 CPU 或系统范围内的事件进行计数。在每线程模式下，计数器仅监视指定线程的执行。当线程被调度出去时，监视就会停止。当线程从一个处理器迁移到另一处理器时，计数器将保存在当前处理器上，并在新处理器上恢复。

\n

\n

和

\n

\n

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

\n

\n

从这些来源，我期望 perf 出现以下行为：

\n

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

\n

你的问题

\n

所以，我的结论是

\n

\n

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

\n

\n

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

\n

\n

或者它是每个线程的计数器？

\n

\n

它是 cpu 核心上的硬件计数器，但 perf 允许您像每个线程一样使用它 - 如果不同程序的线程被调度，这不会对您产生任何影响。默认情况下，perf 不会将线程信息注释到存储在perf.data. 根据手册页，您可以使用-s或--stat存储此信息。然后，性能报告将允许您分析应用程序的各个线程。

\n

\n

是否只计算运行程序所花费的周期？

\n

\n

是的，除非另有说明。

\n

你的输出

\n

tid  timestamp        event counter\n5881 187296.210979:   15736902 cycles:\n5881 187296.215945:   15664720 cycles:\n5881 187296.221356:   15586918 cycles:\n5881 187296.227022:          1 cycles:\n5881 187296.227032:          1 cycles:\n5881 187296.227037:         62 cycles:\n5881 187296.227043:       6902 cycles:\n5881 187296.227048:     822728 cycles:\n5881 187296.231842:   90947120 cycles:\n

\n

你执行了什么来获得这个输出？也许我误解了，但我猜发生了以下情况：

\n

下面的实验部分证明了这里的观点是无效的

\n

\n
• 您以指定的目标频率进行录制。这意味着 perf 尝试优化硬件计数器的当前溢出值，以便每秒获得指定数量的溢出周期数。
\n
• 对于前三个时间戳，程序的线程在 CPU 上执行，这会触发高电平cycles计数。perf 大约每 0.005 秒采样一次。
\n
• 然后，看起来您的线程不再执行每秒那么多的 cpu 周期。也许大部分时间都在等待 IO 操作？^*因此，下一个样本在 0.006 秒后进行，循环计数降至 1。perf 注意到实际采样频率下降了，因此降低了溢出阈值，以保持采样率稳定。
\n
• 然后，也许 IO 操作已完成，您的线程再次开始每秒运行更多的 cpu 周期。这导致了很多周期事件，但由于溢出阈值较低，perf 现在在更少的事件后进行采样（接下来的 3 个采样在 0.00001 秒和 0.000005 秒之后）。在此期间，Perf 增加了溢出阈值。
\n
• 对于最后一个样本，样本之间的距离似乎回到了 0.005 秒左右
\n

\n

实验

\n

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

\n

tid  timestamp        event counter\n5881 187296.210979:   15736902 cycles:\n5881 187296.215945:   15664720 cycles:\n5881 187296.221356:   15586918 cycles:\n5881 187296.227022:          1 cycles:\n5881 187296.227032:          1 cycles:\n5881 187296.227037:         62 cycles:\n5881 187296.227043:       6902 cycles:\n5881 187296.227048:     822728 cycles:\n5881 187296.231842:   90947120 cycles:\n

\n

gcc将循环编译为四个指令：内存加载、增量、内存存储、跳转。根据 htop 的说法，这利用了一个逻辑核心，正如您所期望的那样。我可以模拟它停止执行，就好像它正在等待 IO 或未调度一样，只需在 shell 中使用 ctrl+Z 来暂停它。

\n

现在，我们运行

\n

perf record -F 10 -p $(pidof my_workload)\n

\n

让它运行一会儿。然后，使用ctrl+Z暂停执行。稍等片刻，然后使用fg恢复执行。几秒钟后，结束程序。

\n

[ perf record: Woken up 1 times to write data ]\n[ perf record: Captured and wrote 0,021 MB perf.data (65 samples) ]\n

\n

就我而言，perf record 写入了 65 个样本。我们可以使用 perf 脚本检查写入的示例数据并获取（完整输出，因为我认为我可能会意外删除一些重要的内容。这是在 Intel i5-6200U、Ubuntu 20.04、内核 5.4.0-72-generic 上）：

\n

     my_workload 831622 344935.025844:          1 cycles:  ffffffffa0673594 native_write_msr+0x4 ([kernel.kallsyms])\n     my_workload 831622 344935.025847:          1 cycles:  ffffffffa0673594 native_write_msr+0x4 ([kernel.kallsyms])\n     my_workload 831622 344935.025849:       2865 cycles:  ffffffffa0673594 native_write_msr+0x4 ([kernel.kallsyms])\n     my_workload 831622 344935.025851:   16863383 cycles:  ffffffffa12016f2 nmi_restore+0x25 ([kernel.kallsyms])\n     my_workload 831622 344935.031948: 101431200645 cycles:      558f3623317e main+0x15 (/tmp/my_workload)\n     my_workload 831622 344935.693910:  269342015 cycles:      558f36233178 main+0xf (/tmp/my_workload)\n     my_workload 831622 344935.794233:  268586235 cycles:      558f36233178 main+0xf (/tmp/my_workload)\n     my_workload 831622 344935.893934:  269806654 cycles:      558f3623317b main+0x12 (/tmp/my_workload)\n     my_workload 831622 344935.994321:  269410272 cycles:      558f3623317b main+0x12 (/tmp/my_workload)\n     my_workload 831622 344936.094938:  271951524 cycles:      558f36233178 main+0xf (/tmp/my_workload)\n     my_workload 831622 344936.195815:  269543174 cycles:      558f3623317e main+0x15 (/tmp/my_workload)\n     my_workload 831622 344936.295978:  269967653 cycles:      558f3623317b main+0x12 (/tmp/my_workload)\n     my_workload 831622 344936.397041:  266160499 cycles:      558f3623317b main+0x12 (/tmp/my_workload)\n     my_workload 831622 344936.497782:  265215251 cycles:      558f3623317e main+0x15 (/tmp/my_workload)\n     my_workload 831622 344936.596074:  269863048 cycles:      558f36233178 main+0xf (/tmp/my_workload)\n     my_workload 831622 344936.696280:  269857624 cycles:      558f36233178 main+0xf (/tmp/my_workload)\n     my_workload 831622 344936.796730:  269274440 cycles:      558f36233178 main+0xf (/tmp/my_workload)\n     my_workload 831622 344936.897487:  269115742 cycles:      558f36233178 main+0xf (/tmp/my_workload)\n     my_workload 831622 344936.997988:  266867300 cycles:      558f36233178 main+0xf (/tmp/my_workload)\n     my_workload 831622 344937.097088:  269734778 cycles:      558f3623317e main+0x15 (/tmp/my_workload)\n     my_workload 831622 344937.196955:  270487956 cycles:      558f3623317b main+0x12 (/tmp/my_workload)\n     my_workload 831622 344937.297281:  270136625 cycles:      558f3623317e main+0x15 (/tmp/my_workload)\n     my_workload 831622 344937.397516:  269741183 cycles:      558f3623317b main+0x12 (/tmp/my_workload)\n     my_workload 831622 344943.438671:  173595673 cycles:      558f3623317e main+0x15 (/tmp/my_workload)\n     my_workload 831622 344943.512800:  251467821 cycles:      558f3623317b main+0x12 (/tmp/my_workload)\n     my_workload 831622 344943.604016:  274913168 cycles:      558f3623317e main+0x15 (/tmp/my_workload)\n     my_workload 831622 344943.703440:  276448269 cycles:      558f3623317b main+0x12 (/tmp/my_workload)\n     my_workload 831622 344943.803753:  275059394 cycles:      558f36233178 main+0xf (/tmp/my_workload)\n     my_workload 831622 344943.903362:  276318281 cycles:      558f3623317e main+0x15 (/tmp/my_workload)\n     my_workload 831622 344944.005543:  266874454 cycles:      558f3623317b main+0x12 (/tmp/my_workload)\n     my_workload 831622 344944.105663:  268220344 cycles:      558f3623317b main+0x12 (/tmp/my_workload)\n     my_workload 831622 344944.205213:  269369912 cycles:      558f3623317b main+0x12 (/tmp/my_workload)\n     my_workload 831622 344944.305541:  267387036 cycles:      558f3623317b main+0x12 (/tmp/my_workload)\n     my_workload 831622 344944.405660:  266906130 cycles:      558f3623317e main+0x15 (/tmp/my_workload)\n     my_workload 831622 344944.506126:  266194513 cycles:      558f36233178 main+0xf (/tmp/my_workload)\n     my_workload 831622 344944.604879:  268882693 cycles:      558f3623317e main+0x15 (/tmp/my_workload)\n     my_workload 831622 344944.705588:  266555089 cycles:      558f3623317e main+0x15 (/tmp/my_workload)\n     my_workload 831622 344944.804896:  268419478 cycles:      558f36233178 main+0xf (/tmp/my_workload)\n     my_workload 831622 344944.905269:  267700541 cycles:      558f36233178 main+0xf (/tmp/my_workload)\n     my_workload 831622 344945.004885:  267365839 cycles:      558f3623317b main+0x12 (/tmp/my_workload)\n     my_workload 831622 344945.103970:  269655126 cycles:      558f3623317e main+0x15 (/tmp/my_workload)\n     my_workload 831622 344945.203823:  269330033 cycles:      558f36233178 main+0xf (/tmp/my_workload)\n     my_workload 831622 344945.304258:  267423569 cycles:      558f3623317e main+0x15 (/tmp/my_workload)\n     my_workload 831622 344945.403472:  269773962 cycles:      558f3623317e main+0x15 (/tmp/my_workload)\n     my_workload 831622 344945.504194:  275795565 cycles:      558f3623317e main+0x15 (/tmp/my_workload)\n     my_workload 831622 344945.606329:  271013012 cycles:      558f3623317e main+0x15 (/tmp/my_workload)\n     my_workload 831622 344945.703866:  277537908 cycles:      558f3623317b main+0x12 (/tmp/my_workload)\n     my_workload 831622 344945.803821:  277559915 cycles:      558f3623317e main+0x15 (/tmp/my_workload)\n     my_workload 831622 344945.904299:  277242574 cycles:      558f36233178 main+0xf (/tmp/my_workload)\n     my_workload 831622 344946.005167:  272430392 cycles:      558f3623317b main+0x12 (/tmp/my_workload)\n     my_workload 831622 344946.104424:  275291909 cycles:      558f3623317b main+0x12 (/tmp/my_workload)\n     my_workload 831622 344946.204402:  275331204 cycles:      558f3623317b main+0x12 (/tmp/my_workload)\n     my_workload 831622 344946.304334:  273818645 cycles:      558f3623317b main+0x12 (/tmp/my_workload)\n     my_workload 831622 344946.403674:  275723986 cycles:      558f3623317e main+0x15 (/tmp/my_workload)\n     my_workload 831622 344946.456065:          1 cycles:  ffffffffa0673594 native_write_msr+0x4 ([kernel.kallsyms])\n     my_workload 831622 344946.456069:          1 cycles:  ffffffffa0673594 native_write_msr+0x4 ([kernel.kallsyms])\n     my_workload 831622 344946.456071:       2822 cycles:  ffffffffa0673594 native_write_msr+0x4 ([kernel.kallsyms])\n     my_workload 831622 344946.456072:   17944993 cycles:  ffffffffa0673596 native_write_msr+0x6 ([kernel.kallsyms])\n     my_workload 831622 344946.462714: 107477037825 cycles:      558f36233178 main+0xf (/tmp/my_workload)\n     my_workload 831622 344946.804126:  281880047 cycles:      558f3623317e main+0x15 (/tmp/my_workload)\n     my_workload 831622 344946.907508:  274093449 cycles:      558f36233178 main+0xf (/tmp/my_workload)\n     my_workload 831622 344947.007473:  270795847 cycles:      558f36233178 main+0xf (/tmp/my_workload)\n     my_workload 831622 344947.106277:  275006801 cycles:      558f36233178 main+0xf (/tmp/my_workload)\n     my_workload 831622 344947.205757:  274972888 cycles:      558f36233178 main+0xf (/tmp/my_workload)\n     my_workload 831622 344947.305405:  274436774 cycles:      558f3623317b main+0x12 (/tmp/my_workload)\n

\n

我认为我们可以在这个输出中看到两个主要内容

\n

\n
• 344937.397516 处的样本似乎是我暂停程序之前的最后一个样本，而 344943.438671 似乎是程序恢复后的第一个样本。我们这里的周期数要少一些。除此之外，它看起来就像其他线路一样。
\n
• 然而，您的模式可以在启动后直接找到——我想说的是——并且在时间戳 344946.456065 处。通过注释，native_write_msr我认为我们在这里观察到的是执行内部工作。有一个关于做什么的问题native_write_msr。根据Peter对该问题的评论，这是内核编程硬件性能计数器。还是有点奇怪。也许，在将当前缓冲区写入 perf.data 后，perf 的行为就像刚刚启动一样？
\n

\n\n

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

\n

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

\n