【问题标题】:Perf overcounting simple CPU-bound loop: mysterious kernel work?Perf 过度计算简单的 CPU 绑定循环:神秘的内核工作?
【发布时间】:2017-02-13 08:02:09
【问题描述】:

一段时间以来,我一直在使用 Linux perf 进行应用程序分析。通常,经过分析的应用程序相当复杂,因此人们往往会简单地将所报告的计数器值视为表面价值,只要与您根据第一原则所期望的值没有任何严重差异。

然而,最近,我分析了一些琐碎的 64 位汇编程序 - 琐碎到可以几乎准确地计算出各种计数器的预期值,而且似乎 perf stat 计数过多。

以如下循环为例:

.loop:
    nop
    dec rax
    nop
    jne .loop

这将简单地循环n 次,其中nrax 的初始值。循环的每次迭代执行 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 后缀测量userkernel 计数表明,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


【解决方案1】:

TL;DR

答案很简单。 您的计数器设置为在用户操作系统模式下计数,并且您的测量会定期受到Linux时间片的干扰调度程序,每秒滴答数次

幸运的是,在 5 天前与 @PeterCordes 调查一个不相关的问题时,我 published a cleaned-up version of my own performance counter access software ,libpfc

libpfc

libpfc 是一个非常低级的库和 Linux 可加载内核模块,我仅使用完整的 Intel Software Developers' Manual 作为参考编写了自己的代码。性能计数功能记录在 SDM 第 3 卷第 18-19 章中。它是通过将特定值写入某些 x86 处理器中存在的特定 MSR(模型特定寄存器)来配置的。

在我的 Intel Haswell 处理器上可以配置两种类型的计数器:

  • 固定功能计数器。它们仅限于计算特定类型的事件。它们可以启用或禁用,但它们跟踪的内容不能更改。在 2.4GHz Haswell i7-4700MQ 上有 3 个:

    • 已发布说明:锡纸上写着什么。
    • Unhalted Core Cycles:实际发生的时钟滴答数。如果处理器的频率按比例增加或减少,则此计数器将在单位时间内分别开始更快或更慢地计数。
    • Unhalted Reference Cycles:时钟滴答的数量,以不受动态频率缩放影响的恒定频率滴答。在我的 2.4GHz 处理器上,它的频率正好是 2.4GHz。因此,Unhalted Reference / 2.4e9 给出了亚纳秒精度的计时,Unhalted Core / Unhalted Reference 给出了您从 Turbo Boost 中获得的平均加速因子。
  • 通用计数器。这些通常可以配置为跟踪 SDM 中为您的特定处理器列出的任何事件(只有一些限制)。对于 Haswell,它们目前列在 SDM 的第 3 卷第 19.4 节中,我的存储库包含一个演示,pfcdemo,它可以访问其中的大部分。他们被列为at pfcdemo.c:169。在我的 Haswell 处理器上,启用超线程后,每个内核都有 4 个这样的计数器。

正确配置计数器

为了配置计数器,我自己承担了在我的 LKM、pfc.kowhose source code is included in my repository 中对每个 MSR 进行编程的负担。

必须非常小心地对 MSR 进行编程,否则处理器会以内核恐慌来惩罚你。出于这个原因,除了通用和固定功能计数器本身之外,我还熟悉了 5 种不同类型 MSR 的每一位。我对这些寄存器的注释是at pfckmod.c:750,并在此处转载:

/** 186+x IA32_PERFEVTSELx           -  Performance Event Selection, ArchPerfMon v3
 * 
 *                     /63/60 /56     /48     /40     /32     /24     /16     /08     /00
 *                    {................................################################}
 *                                                     |      ||||||||||      ||      |
 *     Counter Mask -----------------------------------^^^^^^^^|||||||||      ||      |
 *     Invert Counter Mask ------------------------------------^||||||||      ||      |
 *     Enable Counter ------------------------------------------^|||||||      ||      |
 *     AnyThread ------------------------------------------------^||||||      ||      |
 *     APIC Interrupt Enable -------------------------------------^|||||      ||      |
 *     Pin Control ------------------------------------------------^||||      ||      |
 *     Edge Detect -------------------------------------------------^|||      ||      |
 *     Operating System Mode ----------------------------------------^||      ||      |
 *     User Mode -----------------------------------------------------^|      ||      |
 *     Unit Mask (UMASK) ----------------------------------------------^^^^^^^^|      |
 *     Event Select -----------------------------------------------------------^^^^^^^^
 */
/** 309+x IA32_FIXED_CTRx            -  Fixed-Function Counter,      ArchPerfMon v3
 * 
 *                     /63/60 /56     /48     /40     /32     /24     /16     /08     /00
 *                    {????????????????????????????????????????????????????????????????}
 *                     |                                                              |
 *     Counter Value --^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
 *     
 *     NB: Number of FF counters determined by    CPUID.0x0A.EDX[ 4: 0]
 *     NB: ???? FF counter bitwidth determined by CPUID.0x0A.EDX[12: 5]
 */
/** 38D   IA32_FIXED_CTR_CTRL        -  Fixed Counter Controls,      ArchPerfMon v3
 * 
 *                     /63/60 /56     /48     /40     /32     /24     /16     /08     /00
 *                    {....................................................############}
 *                                                                         |  ||  |||||
 *     IA32_FIXED_CTR2 controls  ------------------------------------------^^^^|  |||||
 *     IA32_FIXED_CTR1 controls  ----------------------------------------------^^^^||||
 *                                                                                 ||||
 *     IA32_FIXED_CTR0 controls:                                                   ||||
 *     IA32_FIXED_CTR0 PMI --------------------------------------------------------^|||
 *     IA32_FIXED_CTR0 AnyThread ---------------------------------------------------^||
 *     IA32_FIXED_CTR0 enable (0:Disable 1:OS 2:User 3:All) -------------------------^^
 */
/** 38E   IA32_PERF_GLOBAL_STATUS    -  Global Overflow Status,      ArchPerfMon v3
 * 
 *                  /63/60 /56     /48     /40     /32     /24     /16     /08     /00
 *                 {###..........................###............................####}
 *                  |||                          |||                            ||||
 *     CondChgd ----^||                          |||                            ||||
 *     OvfDSBuffer --^|                          |||                            ||||
 *     OvfUncore -----^                          |||                            ||||
 *     IA32_FIXED_CTR2 Overflow -----------------^||                            ||||
 *     IA32_FIXED_CTR1 Overflow ------------------^|                            ||||
 *     IA32_FIXED_CTR0 Overflow -------------------^                            ||||
 *     IA32_PMC(N-1)   Overflow ------------------------------------------------^|||
 *     ....                     -------------------------------------------------^||
 *     IA32_PMC1       Overflow --------------------------------------------------^|
 *     IA32_PMC0       Overflow ---------------------------------------------------^
 */
/** 38F   IA32_PERF_GLOBAL_CTRL      -  Global Enable Controls,      ArchPerfMon v3
 * 
 *                     /63/60 /56     /48     /40     /32     /24     /16     /08     /00
 *                    {.............................###............................####}
 *                                                  |||                            ||||
 *     IA32_FIXED_CTR2 enable ----------------------^||                            ||||
 *     IA32_FIXED_CTR1 enable -----------------------^|                            ||||
 *     IA32_FIXED_CTR0 enable ------------------------^                            ||||
 *     IA32_PMC(N-1)   enable -----------------------------------------------------^|||
 *     ....                   ------------------------------------------------------^||
 *     IA32_PMC1       enable -------------------------------------------------------^|
 *     IA32_PMC0       enable --------------------------------------------------------^
 */
/** 390   IA32_PERF_GLOBAL_OVF_CTRL  -  Global Overflow Control,     ArchPerfMon v3
 * 
 *                     /63/60 /56     /48     /40     /32     /24     /16     /08     /00
 *                    {###..........................###............................####}
 *                     |||                          |||                            ||||
 *     ClrCondChgd ----^||                          |||                            ||||
 *     ClrOvfDSBuffer --^|                          |||                            ||||
 *     ClrOvfUncore -----^                          |||                            ||||
 *     IA32_FIXED_CTR2 ClrOverflow -----------------^||                            ||||
 *     IA32_FIXED_CTR1 ClrOverflow ------------------^|                            ||||
 *     IA32_FIXED_CTR0 ClrOverflow -------------------^                            ||||
 *     IA32_PMC(N-1)   ClrOverflow ------------------------------------------------^|||
 *     ....                        -------------------------------------------------^||
 *     IA32_PMC1       ClrOverflow --------------------------------------------------^|
 *     IA32_PMC0       ClrOverflow ---------------------------------------------------^
 */
/** 4C1+x IA32_A_PMCx                -  General-Purpose Counter,     ArchPerfMon v3
 * 
 *                     /63/60 /56     /48     /40     /32     /24     /16     /08     /00
 *                    {????????????????????????????????????????????????????????????????}
 *                     |                                                              |
 *     Counter Value --^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
 *     
 *     NB: Number of GP counters determined by    CPUID.0x0A.EAX[15: 8]
 *     NB: ???? GP counter bitwidth determined by CPUID.0x0A.EAX[23:16]
 */

特别注意IA32_PERFEVTSELx,位 16(用户模式)和 17(操作系统模式)和IA32_FIXED_CTR_CTRL,位 IA32_FIXED_CTRx enableIA32_PERFEVTSELx配置通用计数器x,而从IA32_FIXED_CTR_CTRL中的LSB开始计数的每组4位从4*x开始计数配置固定功能计数器x

在 MSR IA32_PERFEVTSELx 中,如果在设置用户位的同时清除 OS 位,则计数器只会在用户模式下累积事件,并且会排除内核模式事件。在 MSR IA32_FIXED_CTRL_CTRL 中,每组 4 位包含一个两位 enable 字段,如果设置为 2 (0b10) 将启用在用户模式下而不是在内核模式下计数事件。

我的 LKM 对固定功能和通用计数器分别在 pfckmod.c:296pfckmod.c:330 强制执行仅用户模式计数。

用户空间

在用户空间中,用户配置计数器(流程示例,从pfcdemo.c:98 开始),然后使用宏PFCSTART()PFCEND() 将要计时的代码夹在中间。这些是非常具体的代码序列,但它们是有代价的,因此会产生一个有偏差的结果,即高估了来自计时器的事件数量。因此,您还必须调用 pfcRemoveBias(),当它们包围 0 条指令时,它会对 PFCSTART()/PFCEND() 进行计时,并从累积计数中消除偏差。

你的代码,在 libpfc 下

我把你的代码放入pfcdemo.c:130,这样它现在就可以读取了

/************** Hot section **************/
PFCSTART(CNT);
asm volatile(
".intel_syntax noprefix\n\t"
"mov             rax, 1000000000\n\t"
".loop:\n\t"
"nop\n\t"
"dec             rax\n\t"
"nop\n\t"
"jne             .loop\n\t"
".att_syntax noprefix\n\t"
: /* No outputs we care about */
: /* No inputs we care about */
: "rax", "memory", "cc"
);
PFCEND  (CNT);
/************ End Hot section ************/

。我得到了以下信息:

Instructions Issued                  :           4000000086
Unhalted core cycles                 :           1001668898
Unhalted reference cycles            :            735432000
uops_issued.any                      :           4000261487
uops_issued.any<1                    :              2445188
uops_issued.any>=1                   :           1000095148
uops_issued.any>=2                   :           1000070454
Instructions Issued                  :           4000000084
Unhalted core cycles                 :           1002792358
Unhalted reference cycles            :            741096720
uops_issued.any>=3                   :           1000057533
uops_issued.any>=4                   :           1000044117
uops_issued.any>=5                   :                    0
uops_issued.any>=6                   :                    0
Instructions Issued                  :           4000000082
Unhalted core cycles                 :           1011149969
Unhalted reference cycles            :            750048048
uops_executed_port.port_0            :            374577796
uops_executed_port.port_1            :            227762669
uops_executed_port.port_2            :                 1077
uops_executed_port.port_3            :                 2271
Instructions Issued                  :           4000000088
Unhalted core cycles                 :           1006474726
Unhalted reference cycles            :            749845800
uops_executed_port.port_4            :                 3436
uops_executed_port.port_5            :            438401716
uops_executed_port.port_6            :           1000083071
uops_executed_port.port_7            :                 1255
Instructions Issued                  :           4000000082
Unhalted core cycles                 :           1009164617
Unhalted reference cycles            :            756860736
resource_stalls.any                  :                 1365
resource_stalls.rs                   :                    0
resource_stalls.sb                   :                    0
resource_stalls.rob                  :                    0
Instructions Issued                  :           4000000083
Unhalted core cycles                 :           1007578976
Unhalted reference cycles            :            755945832
uops_retired.all                     :           4000097703
uops_retired.all<1                   :              8131817
uops_retired.all>=1                  :           1000053694
uops_retired.all>=2                  :           1000023800
Instructions Issued                  :           4000000088
Unhalted core cycles                 :           1015267723
Unhalted reference cycles            :            756582984
uops_retired.all>=3                  :           1000021575
uops_retired.all>=4                  :           1000011412
uops_retired.all>=5                  :                 1452
uops_retired.all>=6                  :                    0
Instructions Issued                  :           4000000086
Unhalted core cycles                 :           1013085918
Unhalted reference cycles            :            758116368
inst_retired.any_p                   :           4000000086
inst_retired.any_p<1                 :             13696825
inst_retired.any_p>=1                :           1000002589
inst_retired.any_p>=2                :           1000000132
Instructions Issued                  :           4000000083
Unhalted core cycles                 :           1004281248
Unhalted reference cycles            :            745031496
inst_retired.any_p>=3                :            999997926
inst_retired.any_p>=4                :            999997925
inst_retired.any_p>=5                :                    0
inst_retired.any_p>=6                :                    0
Instructions Issued                  :           4000000086
Unhalted core cycles                 :           1018752394
Unhalted reference cycles            :            764101152
idq_uops_not_delivered.core          :             71912269
idq_uops_not_delivered.core<1        :           1001512943
idq_uops_not_delivered.core>=1       :             17989688
idq_uops_not_delivered.core>=2       :             17982564
Instructions Issued                  :           4000000081
Unhalted core cycles                 :           1007166725
Unhalted reference cycles            :            755495952
idq_uops_not_delivered.core>=3       :              6848823
idq_uops_not_delivered.core>=4       :              6844506
rs_events.empty                      :                    0
idq.empty                            :              6940084
Instructions Issued                  :           4000000088
Unhalted core cycles                 :           1012633828
Unhalted reference cycles            :            758772576
idq.mite_uops                        :             87578573
idq.dsb_uops                         :                56640
idq.ms_dsb_uops                      :                    0
idq.ms_mite_uops                     :               168161
Instructions Issued                  :           4000000088
Unhalted core cycles                 :           1013799250
Unhalted reference cycles            :            758772144
idq.mite_all_uops                    :            101773478
idq.mite_all_uops<1                  :            988984583
idq.mite_all_uops>=1                 :             25470706
idq.mite_all_uops>=2                 :             25443691
Instructions Issued                  :           4000000087
Unhalted core cycles                 :           1009164246
Unhalted reference cycles            :            758774400
idq.mite_all_uops>=3                 :             16246335
idq.mite_all_uops>=4                 :             16239687
move_elimination.int_not_eliminated  :                    0
move_elimination.simd_not_eliminated :                    0
Instructions Issued                  :           4000000089
Unhalted core cycles                 :           1018530294
Unhalted reference cycles            :            763961712
lsd.uops                             :           3863703268
lsd.uops<1                           :             53262230
lsd.uops>=1                          :            965925817
lsd.uops>=2                          :            965925817
Instructions Issued                  :           4000000082
Unhalted core cycles                 :           1012124380
Unhalted reference cycles            :            759399384
lsd.uops>=3                          :            978583021
lsd.uops>=4                          :            978583021
ild_stall.lcp                        :                    0
ild_stall.iq_full                    :                  863
Instructions Issued                  :           4000000087
Unhalted core cycles                 :           1008976349
Unhalted reference cycles            :            758008488
br_inst_exec.all_branches            :           1000009401
br_inst_exec.0x81                    :           1000009400
br_inst_exec.0x82                    :                    0
icache.misses                        :                  168
Instructions Issued                  :           4000000084
Unhalted core cycles                 :           1010302763
Unhalted reference cycles            :            758333856
br_misp_exec.all_branches            :                    2
br_misp_exec.0x81                    :                    1
br_misp_exec.0x82                    :                    0
fp_assist.any                        :                    0
Instructions Issued                  :           4000000082
Unhalted core cycles                 :           1008514841
Unhalted reference cycles            :            757761792
cpu_clk_unhalted.core_clk            :           1008510494
cpu_clk_unhalted.ref_xclk            :             31573233
baclears.any                         :                    0
idq.ms_uops                          :               164093

不再有开销!您可以从固定功能计数器(例如最后一组打印输出)看到 IPC 是 4000000082 / 1008514841,大约是 4 个 IPC,从 757761792 / 2.4e9 看到代码花费了 0.31573408 秒,从 1008514841 / 757761792 = 1.330912763941521核心是 Turbo Boosting 到 2.4GHz 或 3.2GHz 的 133%。

【讨论】:

  • 这太棒了,我明天会深入研究。
  • 对此进行了很好的调查,但您的结论是开销来自内核,这是 OP 通过使用带有 :u 标志的 perf 已经发现的。
  • @fireboot 我刚刚私下研究了那个特定的主题,所以我非常详细地知道 MSR 中的哪个位设置不正确,以及需要完成什么。我证实了 OP 的怀疑。
  • 是的,我确实发现:u 标志消除了大部分的开销,但仍然有一点——但可以想象它仍然是由于中断的开销——请参阅this page 了解一些剩余的过度计数问题(即使使用:u),如果您真的想深入了解,还有一个完整的paper(在facft 中有几篇论文)。
  • @BeeOnRope 这些不是唯一的超量:处理器中的错误也可以做到这一点。英特尔处理器的勘误表经常列出 PMC 会错误地多计的情况。
猜你喜欢
  • 1970-01-01
  • 1970-01-01
  • 2014-10-23
  • 2013-09-16
  • 2014-06-07
  • 1970-01-01
  • 1970-01-01
  • 1970-01-01
  • 2015-08-18
相关资源
最近更新 更多