简单的CPU绑定循环中的Perf过度计数:神秘的内核工作?

12
我已经使用Linux perf 一段时间来进行应用程序分析。通常,被分析的应用程序非常复杂,因此人们往往只是简单地接受报告的计数器值,只要与基于第一原理的预期相差不大就行了。
然而,最近我对一些微不足道的64位汇编程序进行了分析——足够微不足道,以至于可以几乎精确地计算出各种计数器的预期值,结果发现perf stat存在过多计数的情况。
例如,考虑以下循环:
.loop:
    nop
    dec rax
    nop
    jne .loop

这将简单地循环 n 次,其中 n rax 的初始值。循环的每次迭代执行 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个额外指令。您可以通过构建我的 简单的github项目 在您的系统上运行此项测试。
好的,那么你可能会猜测这几十万个额外的指令只是固定的应用程序设置和拆卸成本(用户空间设置是非常小的,但可能有隐藏的东西)。那么我们试试 n=100亿
~/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倍,与循环计数的增加成比例。您可以尝试各种计数器-所有与CPU相关的计数器都显示类似的比例增加。为了保持简单,让我们重点关注指令计数。使用“:u”和“:k”后缀分别测量用户和内核计数,显示在内核中产生的计数几乎占所有额外事件的比例:
~/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迁移引起的,因为这些事件的数量接近于零,而且无论如何,“额外”指令计数都不与发生更多这些事件的运行相关。

事实上,额外的内核指令数量与循环次数非常平稳。以下是(十亿级别的)循环迭代与内核指令的图表:

Loop count versus kernel instructions

你可以看到,这个关系几乎是完美的线性关系 - 实际上,在15亿次迭代之前只有一个异常值。在那之后,似乎有两条不同的线路,表明某种导致超额时间的量化。无论如何,在主循环中执行10亿条指令,你会产生大约350K个内核指令。
最后,我注意到执行的内核指令数量似乎与运行时间1(或CPU时间)成正比,而不是与执行的指令数量成正比。为了测试这一点,我使用了一个类似的程序,但用一个nop指令替换了一个具有大约40个周期延迟的idiv(删除了一些不相关的行)。
~/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

在这里,我们花费了大约42亿个周期来完成10亿次迭代,并且我们有大约1480万个额外的指令。相比之下,使用nop执行相同的10亿次循环只有大约40万个额外指令。如果我们将其与需要大约相同数量的cycles(40亿次迭代)的nop循环进行比较,我们会看到几乎完全相同数量的额外指令:

~/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在这些测试期间全速运行,因此除了一些涡轮增压相关的热效应外,周期与时间成正比。


2
perf通过虚拟化硬件计数器,因此额外的指令可能是在定时器(和其他)中断之前执行,然后才到达执行某些与HW计数器有关的perf代码。如果IRQ处理程序甚至对perf做任何事情;我不会惊讶,如果它们只接受来自IRQ处理程序的噪声作为更低的perf开销的代价。我猜测perf将HW计数器添加到64位软件总数中,只会在实际上下文切换时发生,而不是在IRQ“顶半部”处理程序中发生。 - Peter Cordes
确实,中断曾经在我的脑海中闪过,但我发现关于中断如何与 perf 实际交互的信息很少。你是否错过了“...通过虚拟化硬件计数器,...”之后的一些文本? - BeeOnRope
xD,是的,通过在上下文切换时将硬件计数器记录到64位软件计数器中进行虚拟化。 - Peter Cordes
3
这是Linux计时器,而且计数器也被配置成在操作系统模式下计数。我刚写了一个性能计数器工具,所以我立刻就找到了答案,它详细说明了我的LKM和演示程序的一些内部工作原理。@PeterCordes - Iwillnotexist Idonotexist
1个回答

8

简而言之

答案非常简单。你的计数器设置了在用户和操作系统模式下同时计数,而且Linux的时间分片调度程序会定期干扰你的测量,该调度程序每秒会打几次时钟中断。

幸运的是,在5天前,我在解决其他问题时,与@PeterCordes一起研究了一个干净的性能计数器访问软件(链接),名为libpfc

libpfc

libpfc是我自己编写的非常低级别的库和Linux可加载内核模块,仅使用完整的Intel软件开发人员手册作为参考。性能计数设施记录在SDM的第3卷,第18-19章中。它通过向某些x86处理器中存在的特定MSR(模型专用寄存器)写入特定值来配置。

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

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

    • 发出的指令:字面意思。
    • 未停止的核心周期:实际发生的时钟周期数。如果处理器的频率上下调整,此计数器将分别以每单位时间更快或更慢的速度进行计数。
    • 未停止的参考周期:时钟周期数,以动态频率缩放不受影响的恒定频率进行滴答声。在我的2.4GHz处理器上,它精确地以2.4GHz滴答声。因此,未停止的参考/2.4e9提供亚纳秒精度的定时,未停止的核心/未停止的参考提供了您从Turbo Boost中获得的平均加速比。
  • 通用计数器。这些通常可以配置为跟踪SDM中列出的任何事件(仅有少数限制),具体取决于您特定处理器的SDM。对于Haswell,它们目前在SDM的第3卷§19.4中列出,我的存储库包含一个演示,pfcdemo,可以访问其中的大型子集。它们在pfcdemo.c:169中列出。在我的Haswell处理器上,启用HyperThreading时,每个核心都有4个这样的计数器。

正确配置计数器

为了正确配置计数器,我承担了在我的LKM pfc.ko中自己编程每个MSR的负担,其源代码包含在我的存储库中

必须非常小心地编程MSR,否则处理器将惩罚您导致内核恐慌。因此,我熟悉了5种不同类型的MSR的每一位,除了通用计数器和固定功能计数器本身。关于这些寄存器的笔记在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,而从LSB中的位4*x开始的每组4位在IA32_FIXED_CTR_CTRL中计数固定函数计数器x
在MSR IA32_PERFEVTSELx中,如果清除了OS位,同时设置了User位,则仅在用户模式下累积计数器,并排除内核模式事件。在MSR IA32_FIXED_CTRL_CTRL中,每组4位包含一个两位enable字段,如果将其设置为20b10),则将启用在用户模式中但不在内核模式中计数事件。
我的LKM强制对固定功能和通用计数器进行仅用户模式计数,分别位于pfckmod.c:296pfckmod.c:330
用户空间
在用户空间中,用户配置计数器(过程示例,从pfcdemo.c:98开始),然后使用宏PFCSTART()PFCEND()夹住要计时的代码。这些是非常特定的代码序列,但它们具有成本,因此会产生偏差结果,从计时器中过多地计算事件数量。因此,您还必须调用pfcRemoveBias(),当PFCSTART()/PFCEND()围绕0指令时,它会计时并从累积计数中删除偏差。
您的代码,在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可以看出核心正在以2.4GHz的133%Turbo Boost,即3.2GHz。


1
太棒了,明天我会深入研究它。 - BeeOnRope
1
做得好,调查得很透彻,但你的结论是开销来自内核,这是OP已经通过使用带有:u标志的perf发现的。 - Moncef M.
2
是的,我确实发现:u标志可以消除大部分开销,但仍有一些剩余 - 但这可能仍然是由于中断的开销 - 可以参见此页面了解一些剩余的过度计数问题(即使使用:u)并且如果您真的想深入了解,还有一整篇论文(实际上有几篇论文)。 - BeeOnRope
@BeeOnRope,这些不是唯一的过度计数:处理器中的错误也可能导致这种情况。英特尔处理器的勘误列表经常列出PMC错误计数的情况。 - Iwillnotexist Idonotexist
...但我实际测量的代码部分只有几十条指令,因此libpfc允许我采取另一种方法,即只运行一次或少数几次(但现在也存在其他陷阱,如AVX启动开销等)。 - BeeOnRope
显示剩余3条评论

网页内容由stack overflow 提供, 点击上面的
可以查看英文原文,
原文链接