为什么同一个程序中相同的C循环代码副本执行时间差异显著且保持一致?

22
我希望您能够将我的问题简化为一个简单且可重现的测试用例。源代码(可以在这里找到)包含了10个相同的简单循环。每个循环的形式如下:
#define COUNT (1000 * 1000 * 1000)
volatile uint64_t counter = 0;

void loopN(void) {
  for (int j = COUNT; j != 0; j--) {
    uint64_t val = counter;
    val = val + 1;
    counter = val;
  }
  return;
}

变量的“volatile”很重要,因为它强制在每次迭代中从内存读取和写入值。每个循环都使用“-falign-loops=64”对齐到64字节,并且产生相同的汇编代码,除了相对于全局变量的偏移量:
   400880:       48 8b 15 c1 07 20 00    mov    0x2007c1(%rip),%rdx  # 601048 <counter>
   400887:       48 83 c2 01             add    $0x1,%rdx
   40088b:       83 e8 01                sub    $0x1,%eax
   40088e:       48 89 15 b3 07 20 00    mov    %rdx,0x2007b3(%rip)  # 601048 <counter>
   400895:       75 e9                   jne    400880 <loop8+0x20>

我正在一台搭载Intel Haswell i7-4470处理器的电脑上运行Linux 3.11操作系统。使用GCC 4.8.1编译程序,命令行如下:

 gcc -std=gnu99 -O3 -falign-loops=64 -Wall -Wextra same-function.c -o same-function

我还在源代码中使用属性((noinline))来使汇编更清晰,但这并不是观察问题所必需的。我使用shell循环找到最快和最慢的函数:

for n in 0 1 2 3 4 5 6 7 8 9; 
do echo same-function ${n}:; 
/usr/bin/time -f "%e seconds" same-function ${n}; 
/usr/bin/time -f "%e seconds" same-function ${n}; 
/usr/bin/time -f "%e seconds" same-function ${n}; 
done

它产生的结果在运行之间保持一致,误差约为1%。最快和最慢函数的确切数字因二进制布局而异。
same-function 0:
2.08 seconds
2.04 seconds
2.06 seconds
same-function 1:
2.12 seconds
2.12 seconds
2.12 seconds
same-function 2:
2.10 seconds
2.14 seconds
2.11 seconds
same-function 3:
2.04 seconds
2.04 seconds
2.05 seconds
same-function 4:
2.05 seconds
2.00 seconds
2.03 seconds
same-function 5:
2.07 seconds
2.07 seconds
1.98 seconds
same-function 6:
1.83 seconds
1.83 seconds
1.83 seconds
same-function 7:
1.95 seconds
1.98 seconds
1.95 seconds
same-function 8:
1.86 seconds
1.88 seconds
1.86 seconds
same-function 9:
2.04 seconds
2.04 seconds
2.02 seconds

在这种情况下,我们可以看到loop2()是执行最慢的之一,而loop6()是执行最快的之一,两者之间的差异略大于10%。我们通过使用另一种方法重复测试这两种情况来重新确认这一点:
nate@haswell$ N=2; for i in {1..10}; do perf stat same-function $N 2>&1 | grep GHz; done
     7,180,104,866 cycles                    #    3.391 GHz
     7,169,930,711 cycles                    #    3.391 GHz
     7,150,190,394 cycles                    #    3.391 GHz
     7,188,959,096 cycles                    #    3.391 GHz
     7,177,272,608 cycles                    #    3.391 GHz
     7,093,246,955 cycles                    #    3.391 GHz
     7,210,636,865 cycles                    #    3.391 GHz
     7,239,838,211 cycles                    #    3.391 GHz
     7,172,716,779 cycles                    #    3.391 GHz
     7,223,252,964 cycles                    #    3.391 GHz

nate@haswell$ N=6; for i in {1..10}; do perf stat same-function $N 2>&1 | grep GHz; done
     6,234,770,361 cycles                    #    3.391 GHz
     6,199,096,296 cycles                    #    3.391 GHz
     6,213,348,126 cycles                    #    3.391 GHz
     6,217,971,263 cycles                    #    3.391 GHz
     6,224,779,686 cycles                    #    3.391 GHz
     6,194,117,897 cycles                    #    3.391 GHz
     6,225,259,274 cycles                    #    3.391 GHz
     6,244,391,509 cycles                    #    3.391 GHz
     6,189,972,381 cycles                    #    3.391 GHz
     6,205,556,306 cycles                    #    3.391 GHz

考虑到这一点,我们重新阅读了每本英特尔体系结构手册中的每个字,筛选了整个网络中提到“计算机”或“编程”的每一页,并在山顶孤独地冥想了6年。未能获得任何启示后,我们下山回归文明,剃掉胡须,洗个澡,向StackOverflow上的专家寻求帮助:这里可能发生了什么?
编辑:在Benjamin的帮助下(见他下面的答案),我已经想出了一个更加简洁的测试案例succinct test case。它是一个独立的20行汇编程序。将SUB改为SBB会导致性能差异达到15%,尽管结果保持不变,执行的指令数也相同。解释?我认为我离答案越来越近了。
; Minimal example, see also https://dev59.com/hF8d5IYBdhLWcg3w8F--
; To build (Linux):
;   nasm -felf64 func.asm
;   ld func.o
; Then run:
;   perf stat -r10 ./a.out
; On Haswell and Sandy Bridge, observed runtime varies 
; ~15% depending on whether sub or sbb is used in the loop
section .text
global _start
_start:
  push qword 0h       ; put counter variable on stack
  jmp loop            ; jump to function
align 64              ; function alignment.
loop:
  mov rcx, 1000000000
align 64              ; loop alignment.
l:
  mov rax, [rsp]
  add rax, 1h
  mov [rsp], rax
; sbb rcx, 1h         ; which is faster: sbb or sub?
  sub rcx, 1h         ; switch, time it, and find out
  jne l               ; (rot13 spoiler: foo vf snfgre ol 15%)
fin:                  ; If that was too easy, explain why.
  mov eax, 60
  xor edi, edi        ; End of program. Exit with code 0
  syscall

2
你如何考虑后台进程中断你的程序?(我对Linux不是很熟悉,但在Windows上,当尝试计时简单但长时间运行的代码时,这是一个巨大的问题。)当线程进入睡眠状态时,它会花费一段未知的时间间隔而不运行,而计时器仍然在 - 可能 - 走动。 - xxbbcc
1
这似乎不是处理器争用的问题。这可能解释了相同N运行之间时间差异的变化,但它并不能解释不同N运行时间的一致且具有统计学意义的差异。 - John Bollinger
3
例如,loop6loop1的地址对齐方式是什么?它们都是32字节对齐的吗?它们具有相同的整体对齐方式吗? - Paul R
4
你也禁用了Turbo Boost吗?你需要确保CPU不会动态调整频率。另外,你尝试过改变循环执行顺序了吗? - MooseBoys
2
如果您执行该进程10次(即,程序每次运行循环一次),那么答案是缓存状态。如果您在同一进程中重复循环(即,单个程序执行循环10次),那么答案是缓存状态分支预测 - barak manos
显示剩余24条评论
2个回答

9
查看完整的perf stat输出,您会发现变化的不是指令数量,而是停顿周期数。
通过查看反汇编代码,我发现两件事情:
1.计数器变量的偏移量在函数之间有所变化。然而,将计数器设为每个函数的局部变量并没有让这种行为消失。
2.这些函数没有放置在64字节边界上,因此它们可能涵盖不同数量的缓存行。使用-falign-functions=64编译几乎完全消除了差异。
在我的机器上进行了上述更改后进行测试,结果如下:
`for f in $( seq 7); do perf stat -e cycles -r3 ./same-function $f 2>&1; done|grep cycles 6,070,933,420 cycles ( +- 0.11% ) 6,052,771,142 cycles ( +- 0.06% ) 6,099,676,333 cycles ( +- 0.07% ) 6,092,962,697 cycles ( +- 0.16% ) 6,151,861,993 cycles ( +- 0.69% ) 6,074,323,033 cycles ( +- 0.36% ) 6,174,434,653 cycles ( +- 0.65% )`
不过我不知道你找到的停顿的性质更多是什么。
编辑:我已经将计数器设为每个函数的易失成员,测试了在我的I7-3537U上不同的编译方式,并发现“-falign-loops=64”实际上是最慢的。
$ gcc  -std=gnu99 -O3 -Wall -Wextra same-function.c -o same-function
$ gcc -falign-loops=64 -std=gnu99 -O3 -Wall -Wextra same-function.c -o same-function-l64
$ gcc -falign-functions=64 -std=gnu99 -O3 -Wall -Wextra same-function.c -o same-function-f64
$ for prog in same-function{,-l64,-f64}; do echo $prog; for f in $(seq 7); do perf stat -e cycles -r10 ./$prog $f 2>&1; done|grep cycl; done
same-function
     6,079,966,292      cycles                     ( +-  0.19% )
     7,419,053,569      cycles                     ( +-  0.07% )
     6,136,061,105      cycles                     ( +-  0.27% )
     7,282,434,896      cycles                     ( +-  0.74% )
     6,104,866,406      cycles                     ( +-  0.16% )
     7,342,985,942      cycles                     ( +-  0.52% )
     6,208,373,040      cycles                     ( +-  0.50% )
same-function-l64
     7,336,838,175      cycles                     ( +-  0.46% )
     7,358,913,923      cycles                     ( +-  0.52% )
     7,412,570,515      cycles                     ( +-  0.38% )
     7,435,048,756      cycles                     ( +-  0.10% )
     7,404,834,458      cycles                     ( +-  0.34% )
     7,291,095,582      cycles                     ( +-  0.99% )
     7,312,052,598      cycles                     ( +-  0.95% )
same-function-f64
     6,103,059,996      cycles                     ( +-  0.12% )
     6,116,601,533      cycles                     ( +-  0.29% )
     6,120,841,824      cycles                     ( +-  0.18% )
     6,114,278,098      cycles                     ( +-  0.09% )
     6,105,938,586      cycles                     ( +-  0.14% )
     6,101,672,717      cycles                     ( +-  0.19% )
     6,121,339,944      cycles                     ( +-  0.11% )

有关 align-loops 和 align-functions 的更多细节:

$ for prog in same-function{-l64,-f64}; do sudo perf stat -d -r10 ./$prog 0; done

 Performance counter stats for './same-function-l64 0' (10 runs):

       2396.608194      task-clock:HG (msec)      #    1.001 CPUs utilized            ( +-  0.64% )
                56      context-switches:HG       #    0.024 K/sec                    ( +-  5.51% )
                 1      cpu-migrations:HG         #    0.000 K/sec                    ( +- 74.78% )
                46      page-faults:HG            #    0.019 K/sec                    ( +-  0.63% )
     7,331,450,530      cycles:HG                 #    3.059 GHz                      ( +-  0.51% ) [85.68%]
     5,332,248,218      stalled-cycles-frontend:HG #   72.73% frontend cycles idle     ( +-  0.71% ) [71.42%]
   <not supported>      stalled-cycles-backend:HG
     5,000,800,933      instructions:HG           #    0.68  insns per cycle
                                                  #    1.07  stalled cycles per insn  ( +-  0.04% ) [85.73%]
     1,000,446,303      branches:HG               #  417.443 M/sec                    ( +-  0.04% ) [85.75%]
             8,461      branch-misses:HG          #    0.00% of all branches          ( +-  6.05% ) [85.76%]
   <not supported>      L1-dcache-loads:HG
            45,593      L1-dcache-load-misses:HG  #    0.00% of all L1-dcache hits    ( +-  3.61% ) [85.77%]
             6,148      LLC-loads:HG              #    0.003 M/sec                    ( +-  8.80% ) [71.36%]
   <not supported>      LLC-load-misses:HG

       2.394456699 seconds time elapsed                                          ( +-  0.64% )


 Performance counter stats for './same-function-f64 0' (10 runs):

       1998.936383      task-clock:HG (msec)      #    1.001 CPUs utilized            ( +-  0.61% )
                60      context-switches:HG       #    0.030 K/sec                    ( +- 17.77% )
                 1      cpu-migrations:HG         #    0.001 K/sec                    ( +- 47.86% )
                46      page-faults:HG            #    0.023 K/sec                    ( +-  0.68% )
     6,107,877,836      cycles:HG                 #    3.056 GHz                      ( +-  0.34% ) [85.63%]
     4,112,602,649      stalled-cycles-frontend:HG #   67.33% frontend cycles idle     ( +-  0.52% ) [71.41%]
   <not supported>      stalled-cycles-backend:HG
     5,000,910,172      instructions:HG           #    0.82  insns per cycle
                                                  #    0.82  stalled cycles per insn  ( +-  0.01% ) [85.72%]
     1,000,423,026      branches:HG               #  500.478 M/sec                    ( +-  0.02% ) [85.77%]
            10,660      branch-misses:HG          #    0.00% of all branches          ( +- 13.23% ) [85.80%]
   <not supported>      L1-dcache-loads:HG
            47,492      L1-dcache-load-misses:HG  #    0.00% of all L1-dcache hits    ( +- 14.82% ) [85.80%]
            11,719      LLC-loads:HG              #    0.006 M/sec                    ( +- 42.44% ) [71.28%]
   <not supported>      LLC-load-misses:HG

       1.997319759 seconds time elapsed                                          ( +-  0.62% )

这两个可执行文件的指令/周期计数非常低,可能是由于循环的极简主义性质和其施加的内存压力所致,但我不知道为什么其中一个比另一个更糟糕。

我还尝试了类似以下内容的东西

$ for prog in same-function{-l64,-f64}; do sudo perf stat -eL1-{d,i}cache-load-misses,L1-dcache-store-misses,cs,cycles,instructions -r10 ./$prog 0; done

并且

$ sudo perf record -F25000 -e'{cycles:pp,stalled-cycles-frontend}' ./same-function-l64 0
[ perf record: Woken up 28 times to write data ]
[ perf record: Captured and wrote 6.771 MB perf.data (~295841 samples) ]
$ sudo perf report --group -Sloop0 -n --show-total-period --stdio
$ sudo perf annotate --group -sloop0  --stdio

但是一直没有找到罪犯的线索。尽管如此,我觉得把这个记录在这里可能会有所帮助...

编辑2: 这是我对same-function.c的补丁:

$ git diff -u -U0
diff --git a/same-function.c b/same-function.c
index f78449e..78a5772 100644
--- a/same-function.c
+++ b/same-function.c
@@ -20 +20 @@ done
-volatile uint64_t counter = 0;
+//volatile uint64_t counter = 0;
@@ -22,0 +23 @@ COMPILER_NO_INLINE void loop0(void) {
+volatile uint64_t counter = 0;
@@ -31,0 +33 @@ COMPILER_NO_INLINE void loop1(void) {
+volatile uint64_t counter = 0;
@@ -40,0 +43 @@ COMPILER_NO_INLINE void loop2(void) {
+volatile uint64_t counter = 0;
@@ -49,0 +53 @@ COMPILER_NO_INLINE void loop3(void) {
+volatile uint64_t counter = 0;
@@ -58,0 +63 @@ COMPILER_NO_INLINE void loop4(void) {
+volatile uint64_t counter = 0;
@@ -67,0 +73 @@ COMPILER_NO_INLINE void loop5(void) {
+volatile uint64_t counter = 0;
@@ -76,0 +83 @@ COMPILER_NO_INLINE void loop6(void) {
+volatile uint64_t counter = 0;
@@ -85,0 +93 @@ COMPILER_NO_INLINE void loop7(void) {
+volatile uint64_t counter = 0;
@@ -94,0 +103 @@ COMPILER_NO_INLINE void loop8(void) {
+volatile uint64_t counter = 0;
@@ -103,0 +113 @@ COMPILER_NO_INLINE void loop9(void) {
+volatile uint64_t counter = 0;
@@ -135 +145 @@ int main(int argc, char** argv) {
-}
\ No newline at end of file
+}

编辑3: 这是一个更加简单的例子:

这里有同样的问题:
; Minimal example, see also https://dev59.com/hF8d5IYBdhLWcg3w8F-- 
; To build (Linux):
;   nasm -felf64 func.asm
;   ld func.o
; Then run:
;   perf stat -r10 ./a.out
; Runtime varies ~10% depending on whether 
section .text
global _start
_start:
  push qword 0h       ; put counter variable on stack
  jmp loop            ; jump to function
;align 64             ; function alignment. Try commenting this
loop:
  mov rcx, 1000000000
;align 64             ; loop alignment. Try commenting this
l:
  mov rax, [rsp]
  add rax, 1h
  mov [rsp], rax
  sub rcx, 1h
  jne l
fin:                  ; End of program. Exit with code 0
  mov eax, 60
  xor edi, edi
  syscall

这里也有同样的效果。有趣。

祝好, 本杰明


1
@Nathan,我从same-function.c文件顶部的注释中获取了编译指令,但没有注意到它不包含你建议的-falign-loops=64,然后使用"eu-readelf -s same-function | grep loop"和"objdump -d same-function"检查对齐情况。我只是想知道代码是否未按64字节边界对齐,如果可能会导致指令缓存未命中问题,因此我尝试了-falign-functions。由于我现在离开了我的机器,所以我将在晚上回答你的其他问题。谢谢! - bking
1
@Natan,另外我使用了不同的架构(Sandy Bridge),但我也能在那里重现你最初的发现。 - bking
好的,就放在我的回答里。真的没什么特别的。针对所有三个编译标志集,我已经编译了这段代码。 - bking
1
根据英特尔优化 3.6.5.2,存储后不久立即对同一地址进行读取“可能会导致相当大但非确定性的延迟”。它甚至特别提到了易失性变量。在这种情况下,“太快”意味着“在同一个周期内发送到RAT”。这会导致减速。症状上,我们可以测量比预期执行更多的存储和加载指令,但只有预期数量被退役。我仍然不理解哪种对齐方式导致哪种速度,但我认为它必须影响正在发出的微操作的方式。让人费解。 - Nathan Kurz
2
我还不知道如何使用带有内存操作数的inc指令。我会尝试探索一下。但是,这确实有实际用途!我已经遇到了这个问题几次了,这是我第一次真正尝试解决它。最新的应用程序在这里有很好的描述:http://fastcompression.blogspot.com/2014/09/counting-bytes-fast-little-trick-from.html。Yann正在编写一个直方图,以计算作为压缩算法输入的每个字节出现的次数。但随着数据变得更加可预测,性能变差。可预测的情况最终会表现得很像这个循环。 - Nathan Kurz
显示剩余8条评论

1
几年前,我会告诉你检查在任何这些循环中到达时CPU的内部状态是否有任何差异; 因为已知这对乱序预测过程的能力有深远影响(或类似的东西)。例如,相同的循环的性能可能会因CPU在进入循环之前所做的事情而发生15-20%左右的变化,而仅仅从两个不同点跳转就足以改变执行速度。
在你的情况下,测试相当容易。您只需更改IF块中指令的顺序即可;例如替换以下内容:
  switch (firstLetter) {
  case '0': loop0(); break;
  case '1': loop1(); break;
  case '2': loop2(); break;
  case '3': loop3(); break;
  case '4': loop4(); break;
  case '5': loop5(); break;
  case '6': loop6(); break;
  case '7': loop7(); break;
  case '8': loop8(); break;
  case '9': loop9(); break;
  default: goto die_usage;
  }

使用:

  switch (firstLetter) {
  case '9': loop9(); break;
  case '8': loop8(); break;
  case '7': loop7(); break;
  case '6': loop6(); break;
  case '5': loop5(); break;
  case '4': loop4(); break;
  case '3': loop3(); break;
  case '2': loop2(); break;
  case '1': loop1(); break;
  case '0': loop0(); break;
  default: goto die_usage;
  }

或以任意随机顺序。当然,您应该检查生成的汇编代码,以确保指令的顺序未被编译器重新排序。

此外,由于您的循环位于各自的函数内,因此还应确保这些函数本身在64字节边界上对齐。


我不确定我理解你的回答。如果你是在暗示调用发生的位置决定了函数的速度,我不知道这可能是什么机制。但是我按照你提出的顺序进行了更改,并发现函数在switch语句中的位置不会影响其执行速度。也就是说,速度似乎是函数的一个属性。为了再次确认,我还编辑了生成的汇编代码,交换了对“最快”和“最慢”函数的调用,结果发现它们仍然保持原来的速度。 - Nathan Kurz
那是我的想法。几年前,OOO机制非常不可预测。在你的情况下,另一个可能性是每个函数对齐方式的差异。您还可以检查是否使用goto语句替换函数。 - SylvainL
你也可以尝试使用goto语句替换函数。当我允许函数内联时,我得到了类似的时间差异,我认为这应该与切换到goto相同(或更明确)。它改变了哪个“函数”是快速的,但并没有解决问题。我在示例中没有这样做,因为我认为将所有内容放在main()中会使事情复杂化。 - Nathan Kurz

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