为什么这个内循环在通过外循环的第一次迭代中加快了4倍?

我试图重现这里描述的一些处理器缓存效果。 我知道Java是一个托管环境,这些例子不会完全翻译,但我遇到了一个奇怪的案例,我试图提炼出一个简单的例子来说明效果:

public static void main(String[] args) { final int runs = 10; final int steps = 1024 * 1024 * 1024; for (int run = 0; run < runs; run++) { final int[] a = new int[1]; long start = System.nanoTime(); for (int i = 0; i < steps; i++) { a[0]++; } long stop = System.nanoTime(); long time = TimeUnit.MILLISECONDS.convert(stop - start, TimeUnit.NANOSECONDS); System.out.printf("Time for loop# %2d: %5d ms\n", run, time); } } 

输出:

  Time for loop# 0: 24 ms Time for loop# 1: 106 ms Time for loop# 2: 104 ms Time for loop# 3: 103 ms Time for loop# 4: 102 ms Time for loop# 5: 103 ms Time for loop# 6: 104 ms Time for loop# 7: 102 ms Time for loop# 8: 105 ms Time for loop# 9: 102 ms 

内循环的第一次迭代大约是后续迭代的4倍。 这与我通常所期望的相反,因为随着JIT的推出通常性能上升。

当然,在任何严肃的微基准测试中都会做几个预热循环,但我很好奇是什么原因造成这种行为,特别是因为如果我们知道循环可以在24ms内执行,那就不太令人满意了稳态时间超过100ms。

供我参考的JDK(在linux上):

  openjdk version "1.8.0_40" OpenJDK Runtime Environment (build 1.8.0_40-b20) OpenJDK 64-Bit Server VM (build 25.40-b23, mixed mode) 

更新:

这里有一些更新信息,基于一些评论和一些实验:

1)将System.out I / O移出循环(通过将时序存储在大小’run’的数组中)在时间上没有显着差异。

2)上面显示的输出是我在Eclipse中运行的时间。 当我从命令行编译并运行时(使用相同的JDK / JVM),我得到的内容更为温和,但结果仍然很明显(2倍而不是4倍)。 这看起来很有意思,因为如果有的话,在eclipse中运行会减慢速度。

3)向上移动,离开循环,以便重复使用它,每次迭代都没有效果。

4)如果int[] a变为long[] a ,则第一次迭代运行得更快(约20%),而其他迭代仍然是相同(较慢)的速度。

更新2:

我认为apangin的答案解释了它。 我用Sun的1.9 JVM尝试了这个,它来自:

 openjdk version "1.8.0_40" OpenJDK Runtime Environment (build 1.8.0_40-b20) OpenJDK 64-Bit Server VM (build 25.40-b23, mixed mode) Time for loop# 0: 48 ms Time for loop# 1: 116 ms Time for loop# 2: 112 ms Time for loop# 3: 113 ms Time for loop# 4: 112 ms Time for loop# 5: 112 ms Time for loop# 6: 111 ms Time for loop# 7: 111 ms Time for loop# 8: 113 ms Time for loop# 9: 113 ms 

至:

 java version "1.9.0-ea" Java(TM) SE Runtime Environment (build 1.9.0-ea-b73) Java HotSpot(TM) 64-Bit Server VM (build 1.9.0-ea-b73, mixed mode) Time for loop# 0: 48 ms Time for loop# 1: 26 ms Time for loop# 2: 22 ms Time for loop# 3: 22 ms Time for loop# 4: 22 ms Time for loop# 5: 22 ms Time for loop# 6: 22 ms Time for loop# 7: 22 ms Time for loop# 8: 22 ms Time for loop# 9: 23 ms 

这是非常好的改进!

这是方法的次优重新编译。

JIT编译器依赖于在解释期间收集的运行时统计信息。 当第一次编译main方法时,外部循环尚未完成其第一次迭代=>运行时统计信息告诉内部循环之后的代码永远不会执行,因此JIT不会费心编译它。 它反而产生了一个不常见的陷阱。

当内循环第一次结束时,会触发不常见的陷阱,导致该方法被去优化。

在外循环的第二次迭代中,使用新知识重新编译main方法。 现在JIT有更多的统计信息和更多的上下文来编译。 由于某种原因,它现在不会在寄存器中缓存值a[0] (可能是因为JIT被更广泛的上下文所欺骗)。 因此它生成addl指令来更新内存中的数组,这实际上是内存加载和存储的组合。

相反,在第一次编译期间,JIT在寄存器中缓存a[0]的值,只有mov指令将值存储在存储器中(无负载)。

快速循环(第一次迭代):

 0x00000000029fc562: mov %ecx,0x10(%r14) <<< array store 0x00000000029fc566: mov %r11d,%edi 0x00000000029fc569: mov %r9d,%ecx 0x00000000029fc56c: add %edi,%ecx 0x00000000029fc56e: mov %ecx,%r11d 0x00000000029fc571: add $0x10,%r11d <<< increment in register 0x00000000029fc575: mov %r11d,0x10(%r14) <<< array store 0x00000000029fc579: add $0x11,%ecx 0x00000000029fc57c: mov %edi,%r11d 0x00000000029fc57f: add $0x10,%r11d 0x00000000029fc583: cmp $0x3ffffff2,%r11d 0x00000000029fc58a: jl 0x00000000029fc562 

慢循环(重新编译后):

 0x00000000029fa1b0: addl $0x10,0x10(%r14) <<< increment in memory 0x00000000029fa1b5: add $0x10,%r13d 0x00000000029fa1b9: cmp $0x3ffffff1,%r13d 0x00000000029fa1c0: jl 0x00000000029fa1b0 

但是这个问题似乎在JDK 9中得到修复。我已经针对最近的JDK 9 Early Access版本检查了这个测试,并validation它是否按预期工作:

 Time for loop# 0: 104 ms Time for loop# 1: 101 ms Time for loop# 2: 91 ms Time for loop# 3: 63 ms Time for loop# 4: 60 ms Time for loop# 5: 60 ms Time for loop# 6: 59 ms Time for loop# 7: 55 ms Time for loop# 8: 57 ms Time for loop# 9: 59 ms