问题 一些运行/ JIT的故障后Java循环变慢了?


所以我想对一些基本的java功能进行基准测试,以便为这个问题添加一些信息: 将方法声明为静态有什么好处

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

请注意,我并没有考虑如何解决这个问题,而是为什么会发生这种情况*

测试类:

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

EDIT2:

使用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

其他代码排序在这里产生类似的奇怪(但是更好)的结果。


3390
2017-07-22 08:55


起源

stackoverflow.com/questions/504103/... 可能会帮助你 - Harry Blargle
在我的系统上:Eclipse Kepler,Java 1.7.0,Windows 7 64位我没有看到您的测试有任何问题:静态:1870 ms动态:1901 ms 1000000001000000000静态:1871 ms动态:1901 ms 2000000002000000000静态:1861 ms动态:1901 ms 3000000003000000000静态:1871 ms动态:1891 ms 4000000004000000000静态:1871 ms动态:1881 ms 5000000005000000000静态:1871 ms动态:1911 ms 6000000006000000000静态:1860 ms动态:1881 ms 7000000007000000000静态:1871 ms动态:1891 ms 8000000008000000000 - Eric Nicolas
我无法在Win 7机器上使用JDK 8重现您的结果。我总是得到相同的时间 dynamic 和 static 电话, static 其中约快3-5%。有所不同的是对实例或静态变量的赋值。使 r 静态,你会得到更快的执行。两种类型的电话在我的机器上大约另外5%。 - MicSim
@ Eric / MicSim:感谢您尝试重现。你能提供更详细的输出吗? java -v?奇怪的是,即使使用java8,我也得到了类似的结果...... - Scheintod
我刚刚运行代码 -server 选项,它会有所作为。现在时间不同了,相互减少约50%。如果 r 那么是一个实例变量 dynamic 需要50%的时间 static如果你宣布,反之亦然 r 静止的。这将以某种方式匹配您的代码重新排列结果。在没有跑步的情况下跑步几乎没有区别 -server 选项。 - MicSim


答案:


序言:手动编写微基准测试几乎总是注定要失败。
构架 已经解决了常见的基准问题。

  1. JIT编译单元是一种方法。将几个基准合并到一个方法中会导致不可预测的结果。

  2. JIT严重依赖于执行配置文件,即运行时统计信息。如果方法长时间运行第一个场景,JIT将优化生成的代码。当方法突然切换到另一个方案时,不要指望它以相同的速度运行。

  3. JIT可能会跳过优化未执行的代码。它将为此代码留下一个不常见的陷阱。如果陷阱被击中,JVM将取消优化编译的方法,切换到解释器,然后用新知识重新编译代码。例如。当你的方法 run 在第一个热循环内首次编译,JIT不知道 System.out.println 然而。一旦执行到达 println,早期编译的代码可能会被去优化。

  4. 方法越大 - 为JIT编译器优化它就越困难。例如。可能看起来没有足够的备用寄存器来保存所有局部变量。这就是你的情况。

总结一下,您的基准测试似乎通过以下场景:

  1. 第一个热循环(addStatic)触发编译 run 方法。执行配置文件除了以外什么都不知道 addStatic 方法。
  2. System.out.println 触发去优化,然后是第二个热循环(addDynamic)导致重新编译 run 方法。
  3. 现在,执行配置文件仅包含有关的信息 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

附: 以下JVM选项对于分析JIT编译很有用:

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

10
2017-07-22 14:01



你好。感谢您的回答。我有两个问题需要理解:1。我的汇编程序有点生锈(反正限制为68k)。但我猜对了吗 0x28(%rsp),%r11 它是对应的移动寄存器到堆栈又回来了吗? - Scheintod
其次:我仍然不明白为什么代码 慢一点 对于第二个循环。必须有一个优化的工作版本吗?你是否建议jit抛弃快速版本的crapy? - Scheintod
@Scheintod对, 0x28(%rsp),%r11 从堆栈加载寄存器,和 %r11,0x28(%rsp) 将R11存储到堆栈中。 - apangin
@Scheintod“你是否建议jit抛弃快速版本的crapy版本?” - 是的当第二个基准开始时,JIT重新编译整个 run为第二个基准优化它的方法。编译代码的第一个版本(针对第一个基准进行了优化)将被丢弃。 - apangin
@Scheintod我的意思是没有为这两个基准测试优化的版本。 loop=0 由两个不同的汇编执行。在第一个基准测试之后,第一个被放弃了,因为这个编译还没有准备好处理 println 以及内部循环。第二次编译是为了执行整个外部循环,但仅针对第二个基准进行了优化(因为编译是在执行第二个基准测试期间进行的)。 - apangin


看起来Java是将值添加到变量的方式 r。 我做了一些改动,添加了方法 run2()

public class TestPerformanceOfStaticVsDynamicCalls {
    private static final long RUNS = 1_000_000_000L;
    public static void main(String[] args) {
        System.out.println("Test run 1 =================================");
        new TestPerformanceOfStaticVsDynamicCalls().run();
        System.out.println("Test run 2 =================================");
        new TestPerformanceOfStaticVsDynamicCalls().run2();
    }
    private void run2() {
        long r = 0;
        long start, end;
        for (int loop = 0; loop < 10; loop++) {
            // Benchmark
            long stat = 0;
            start = System.currentTimeMillis();
            for (long i = 0; i < RUNS; i++) {
                stat += addStatic(1, i);
            }
            end = System.currentTimeMillis();
            System.out.println("Static: " + (end - start) + " ms");
            long dyna = 0;
            start = System.currentTimeMillis();
            for (long i = 0; i < RUNS; i++) {
                dyna += addDynamic(1, i);
            }
            end = System.currentTimeMillis();
            System.out.println("Dynamic: " + (end - start) + " ms");
            // If you really want to have values in "r" then...
            r += stat + dyna;
            // Do something with r to keep compiler happy
            System.out.println(r);
        }
    }
    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");
            // If you really want to have values in "r" then...
            // 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;
    }
}

结果是:

Test run 1 =================================
Static: 582 ms
Dynamic: 579 ms
1000000001000000000
Static: 2065 ms
Dynamic: 2352 ms
2000000002000000000
Static: 2084 ms
Dynamic: 2345 ms
3000000003000000000
Static: 2095 ms
Dynamic: 2347 ms
4000000004000000000
Static: 2102 ms
Dynamic: 2338 ms
5000000005000000000
Static: 2073 ms
Dynamic: 2345 ms
6000000006000000000
Static: 2074 ms
Dynamic: 2341 ms
7000000007000000000
Static: 2102 ms
Dynamic: 2355 ms
8000000008000000000
Static: 2062 ms
Dynamic: 2354 ms
9000000009000000000
Static: 2057 ms
Dynamic: 2350 ms
-8446744063709551616
Test run 2 =================================
Static: 584 ms
Dynamic: 582 ms
1000000001000000000
Static: 587 ms
Dynamic: 577 ms
2000000002000000000
Static: 577 ms
Dynamic: 579 ms
3000000003000000000
Static: 577 ms
Dynamic: 577 ms
4000000004000000000
Static: 578 ms
Dynamic: 579 ms
5000000005000000000
Static: 578 ms
Dynamic: 580 ms
6000000006000000000
Static: 577 ms
Dynamic: 579 ms
7000000007000000000
Static: 578 ms
Dynamic: 577 ms
8000000008000000000
Static: 580 ms
Dynamic: 578 ms
9000000009000000000
Static: 576 ms
Dynamic: 579 ms
-8446744063709551616

至于为什么直接添加到 r, 我没有任何线索。也许有人可以提供有关访问原因的更多见解 r 在 - 的里面 loop block 使事情变得更慢。


1
2017-07-22 14:03





只需一个注意事项。如果我使用,我只能观察到这种奇怪的行为 long 对于 r 和 i秒。如果我将它们转换为 int 然后我得到这些时间:

Static: 352 ms
Dynamic: 353 ms
Static: 348 ms
Dynamic: 349 ms
Static: 349 ms
Dynamic: 348 ms
Static: 349 ms
Dynamic: 344 ms

所以有可能 结论 是避免 long 在那些情况下。至少在Linux / Amd64 Java7中,性能很重要。


0
2017-07-22 15:45