为什么这个内部循环第一次迭代通过外部循环快 4 倍？

Question

我试图重现here 中描述的一些处理器缓存效果。我知道 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 的启动而提高。

当然，在任何严重的微基准测试中都会做几个热身循环，但我很好奇是什么导致了这种行为，特别是因为如果我们知道循环可以在 24 毫秒内执行，它不是非常满意，稳态时间超过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)

更新：

以下是一些更新信息，基于一些 cmets 和一些实验：

1) 将 System.out I/O 移出循环（通过将时间存储在大小为“runs”的数组中）在时间上没有显着差异。

2) 上面显示的输出是当我在 Eclipse 中运行时。当我从命令行编译和运行（使用相同的 JDK/JVM）时，我得到的结果更温和，但仍然很重要（快 2 倍而不是 4 倍）。这看起来很有趣，因为通常在 Eclipse 中运行会减慢速度。

3) 将a 上移，移出循环，这样每次迭代都重用它没有效果。

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

这是相当的进步！

Answer 1

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

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 版本检查了这个测试，并验证它可以按预期工作：

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