Java循环在某些运行/ JIT的错误之后变慢？

邹山

2023-03-14

问题内容：

因此，我想对一些基本的Java功能进行基准测试，以为该问题添加一些信息：将方法声明为static有什么好处。

我知道编写基准有时并不容易，但是在这里发生的事情我无法解释。

请注意，我对如何解决此问题不感兴趣，但对为什么会发生*

测试类：

public class TestPerformanceOfStaticVsDynamicCalls {

    private static final long RUNS = 1_000_000_000L;

    public static void main( String [] args ){

        new TestPerformanceOfStaticVsDynamicCalls().run();
    }

    private void run(){

        long r=0;
        long start, end;

        for( int loop = 0; loop<10; loop++ ){

            // Benchmark

            start = System.currentTimeMillis();
            for( long i = 0; i < RUNS; i++ ) {
                r += addStatic( 1, i );
            }
            end = System.currentTimeMillis();
            System.out.println( "Static: " + ( end - start ) + " ms" );

            start = System.currentTimeMillis();
            for( long i = 0; i < RUNS; i++ ) {
                r += addDynamic( 1, i );
            }
            end = System.currentTimeMillis();
            System.out.println( "Dynamic: " + ( end - start ) + " ms" );

            // Do something with r to keep compiler happy
            System.out.println( r );

        }

    }


    private long addDynamic( long a, long b ){

        return a+b;
    }

    private static long addStatic( long a, long b ){

        return a+b;
    }

}

我期望第一个循环可以进行预热，而随后的循环可以更快。

在Eclipse中运行它会产生一些奇怪的结果：

Static: 621 ms
Dynamic: 631 ms
1000000001000000000
Static: 2257 ms
Dynamic: 2501 ms
2000000002000000000
Static: 2258 ms
Dynamic: 2469 ms
3000000003000000000
Static: 2231 ms
Dynamic: 2464 ms
4000000004000000000

那么wtf？它变慢了。为了进行交叉检查，我使用java / c 7运行了相同的代码：

Static: 620 ms
Dynamic: 627 ms
1000000001000000000
Static: 897 ms
Dynamic: 617 ms
2000000002000000000
Static: 901 ms
Dynamic: 615 ms
3000000003000000000
Static: 888 ms
Dynamic: 616 ms
4000000004000000000

因此，在以下循环中，只有静态调用变慢了。如果将代码重新安排为仅r在最终循环之后才打印，则更奇怪了，我在Eclipse中得到了以下代码：

Static: 620 ms
Dynamic: 635 ms
Static: 2285 ms
Dynamic: 893 ms
Static: 2258 ms
Dynamic: 900 ms
Static: 2280 ms
Dynamic: 905 ms
4000000004000000000

而在Java / C 7中：

Static: 620 ms
Dynamic: 623 ms
Static: 890 ms
Dynamic: 614 ms
Static: 890 ms
Dynamic: 616 ms
Static: 886 ms
Dynamic: 614 ms
4000000004000000000

同时在Eclipse中更改动态/静态基准测试的顺序：

Dynamic: 618 ms
Static: 626 ms
1000000001000000000
Dynamic: 632 ms
Static: 2524 ms
2000000002000000000
Dynamic: 617 ms
Static: 2528 ms
3000000003000000000
Dynamic: 622 ms
Static: 2506 ms
4000000004000000000

并在java / c 7中：

Dynamic: 625 ms
Static: 646 ms
1000000001000000000
Dynamic: 2470 ms
Static: 633 ms
2000000002000000000
Dynamic: 2459 ms
Static: 635 ms
3000000003000000000
Dynamic: 2464 ms
Static: 645 ms
4000000004000000000

那么这里发生了什么？

编辑：一些系统信息：

Java version "1.7.0_55"
OpenJDK Runtime Environment (IcedTea 2.4.7) (7u55-2.4.7-1ubuntu1)
OpenJDK 64-Bit Server VM (build 24.51-b03, mixed mode)

Intel(R) Core(TM) i7-2720QM CPU @ 2.20GHz

编辑2：

使用Java8：

Static: 620 ms
Dynamic: 624 ms
1000000001000000000
Static: 890 ms
Dynamic: 618 ms
2000000002000000000
Static: 891 ms
Dynamic: 616 ms
3000000003000000000
Static: 892 ms
Dynamic: 617 ms
4000000004000000000

其他代码顺序在此处产生类似的奇怪（但其他）结果。

问题答案：

序言：手动编写微基准几乎注定要失败。
有些框架已经解决了常见的基准测试问题。

JIT编译单元是一种方法。将多个基准测试整合到一个方法中会导致无法预测的结果。
JIT严重依赖于执行配置文件，即运行时统计信息。如果某个方法长时间运行第一个方案，JIT将为其优化生成的代码。当该方法突然切换到另一个方案时，不要指望它以相同的速度运行。
JIT可能会跳过优化未执行的代码。它将为该代码留下一个不常见的陷阱。如果遇到陷阱，JVM将取消优化已编译的方法，切换到解释器，然后使用新知识重新编译代码。例如，当您的方法run在第一个热循环中第一次编译时，JIT尚不知道System.out.println。一旦执行完成println，较早的编译代码很可能会被优化。
方法越大，为JIT编译器进行优化就越难。例如，似乎没有足够的备用寄存器来容纳所有局部变量。这就是您的情况。

综上所述，您的基准测试似乎通过了以下情形：

第一个热循环（addStatic）触发run方法的编译。执行概要除了addStatic方法外什么都不知道。
System.out.println触发去优化，然后第二个热循环（addDynamic）导致run方法重新编译。
现在执行配置文件仅包含有关的信息addDynamic，因此JIT优化了第二个循环，而第一个循环似乎有额外的寄存器溢出：

优化循环：

0x0000000002d01054: add    %rbx,%r14
0x0000000002d01057: add    $0x1,%rbx          ;*ladd
                                              ; - TestPerformanceOfStaticVsDynamicCalls::addDynamic@2
                                              ; - TestPerformanceOfStaticVsDynamicCalls::run@105

0x0000000002d0105b: add    $0x1,%r14          ; OopMap{rbp=Oop off=127}
                                              ;*goto
                                              ; - TestPerformanceOfStaticVsDynamicCalls::run@116

0x0000000002d0105f: test   %eax,-0x1c91065(%rip)        # 0x0000000001070000
                                              ;*lload
                                              ; - TestPerformanceOfStaticVsDynamicCalls::run@92
                                              ;   {poll}
0x0000000002d01065: cmp    $0x3b9aca00,%rbx
0x0000000002d0106c: jl     0x0000000002d01054

循环产生额外的寄存器溢出：

0x0000000002d011d0: mov    0x28(%rsp),%r11  <---- the problem is here
0x0000000002d011d5: add    %r10,%r11
0x0000000002d011d8: add    $0x1,%r10
0x0000000002d011dc: add    $0x1,%r11
0x0000000002d011e0: mov    %r11,0x28(%rsp)    ;*ladd
                                              ; - TestPerformanceOfStaticVsDynamicCalls::addStatic@2
                                              ; - TestPerformanceOfStaticVsDynamicCalls::run@33

0x0000000002d011e5: mov    0x28(%rsp),%r11  <---- the problem is here
0x0000000002d011ea: add    $0x1,%r11          ; OopMap{[32]=Oop off=526}
                                              ;*goto
                                              ; - TestPerformanceOfStaticVsDynamicCalls::run@44

0x0000000002d011ee: test   %eax,-0x1c911f4(%rip)        # 0x0000000001070000
                                              ;*goto
                                              ; - TestPerformanceOfStaticVsDynamicCalls::run@44
                                              ;   {poll}
0x0000000002d011f4: cmp    $0x3b9aca00,%r10
0x0000000002d011fb: jl     0x0000000002d011d0  ;*ifge
                                              ; - TestPerformanceOfStaticVsDynamicCalls::run@25

PS 以下JVM选项对于分析JIT编译很有用：

-XX:+PrintCompilation -XX:+UnlockDiagnosticVMOptions -XX:+PrintInlining -XX:+PrintAssembly -XX:CompileOnly=TestPerformanceOfStaticVsDynamicCalls

Java循环在某些运行/ JIT的错误之后变慢？

相关阅读

相关文章

相关问答

相关工具

相关文档