当从未执行的代码被注释掉时,Java程序运行得更慢

Question

当从未执行的代码被注释掉时,Java程序运行得更慢

J3D*_*3D1 57 java recursion compiler-optimization

我在一个Java程序中观察到了一些奇怪的行为.我试图尽可能地删除代码,同时仍然能够复制行为.代码全部如下.

public class StrangeBehaviour {

    static boolean recursionFlag = true;

    public static void main(String[] args) {
        long startTime = System.nanoTime();
        for (int i = 0; i < 10000; i ++) {
            functionA(6, 0);
        }
        long endTime = System.nanoTime();
        System.out.format("%.2f seconds elapsed.\n", (endTime - startTime) / 1000.0 / 1000 / 1000);
    }

    static boolean functionA(int recursionDepth, int recursionSwitch) {
        if (recursionDepth == 0) { return true; }
        return functionB(recursionDepth, recursionSwitch);
    }

    static boolean functionB(int recursionDepth, int recursionSwitch) {
        for (int i = 0; i < 16; i++) {
            if (StrangeBehaviour.recursionFlag) {
                if (recursionSwitch == 0) {
                    if (functionA(recursionDepth - 1, 1 - recursionSwitch)) return true;
                } else {
                    if (!functionA(recursionDepth - 1, 1 - recursionSwitch)) return false;
                }
            } else {
                // This block is never entered into.
                // Yet commenting out one of the lines below makes the program run slower!
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
            }
        }
        return false;
    }
}

Run Code Online (Sandbox Code Playgroud)

我有两个功能,functionA()并且functionB()该递归调用对方.这两个函数都带有一个recursionDepth控制递归终止的参数.最多functionA()调用functionB()一次,recursionDepth不变.functionB()打电话functionA()16次recursionDepth - 1.递归终止时,functionA()被称为用recursionDepth的0.

functionB()有一个包含许多System.out.println()调用的代码块.永远不会输入此块,因为条目由在程序执行期间boolean recursionFlag设置为true且从不更改的变量控制.但是,即使其中一个println()调用注释掉也会导致程序运行速度变慢.在我的机器上,所有println()调用的执行时间<0.2s,当其中一个调用被注释掉时,执行时间> 2s.

什么可能导致这种行为？我唯一的猜测是,有一些天真的编译器优化是由与代码块长度相关的参数(或函数调用的数量等)触发的.任何进一步的见解将非常感谢!

编辑:我正在使用JDK 1.8.

Answer 1

k5_*_*k5_ 41

注释代码会影响内联的处理方式.如果functionB变得更长/更大(更多字节码指令),它将不会内联到functionA中.

所以@ J3D1能够使用VMOptions手动关闭functionB()的内联:-XX:CompileCommand=dontinline,com.jd.benchmarking.StrangeBeh??aviour::functionB这似乎消除了较短函数的延迟.

使用vm选项,您可以显示内联 -XX:+UnlockDiagnosticVMOptions -XX:+PrintInlining

更大的版本,不会内联functionB

@ 8   StrangeBehaviour::functionB (326 bytes)   callee is too large
@ 21   StrangeBehaviour::functionA (12 bytes)
  @ 8   StrangeBehaviour::functionB (326 bytes)   callee is too large
@ 35   StrangeBehaviour::functionA (12 bytes)
  @ 8   StrangeBehaviour::functionB (326 bytes)   callee is too large

Run Code Online (Sandbox Code Playgroud)

较短的版本将尝试内联functionB,导致一些进一步的尝试.

@ 8   StrangeBehaviour::functionB (318 bytes)   inline (hot)
 @ 21   StrangeBehaviour::functionA (12 bytes)   inline (hot)
   @ 8   StrangeBehaviour::functionB (318 bytes)   inline (hot)
     @ 35   StrangeBehaviour::functionA (12 bytes)   recursive inlining is too deep
 @ 35   StrangeBehaviour::functionA (12 bytes)   inline (hot)
   @ 8   StrangeBehaviour::functionB (318 bytes)   inline (hot)
     @ 21   StrangeBehaviour::functionA (12 bytes)   recursive inlining is too deep
     @ 35   StrangeBehaviour::functionA (12 bytes)   recursive inlining is too deep
@ 21   StrangeBehaviour::functionA (12 bytes)   inline (hot)
 @ 8   StrangeBehaviour::functionB (318 bytes)   inline (hot)
   @ 35   StrangeBehaviour::functionA (12 bytes)   inline (hot)
     @ 8   StrangeBehaviour::functionB (318 bytes)   recursive inlining is too deep
@ 35   StrangeBehaviour::functionA (12 bytes)   inline (hot)
 @ 8   StrangeBehaviour::functionB (318 bytes)   inline (hot)
   @ 21   StrangeBehaviour::functionA (12 bytes)   inline (hot)
    @ 8   StrangeBehaviour::functionB (318 bytes)   recursive inlining is too deep
   @ 35   StrangeBehaviour::functionA (12 bytes)   inline (hot)
     @ 8   StrangeBehaviour::functionB (318 bytes)   recursive inlining is too deep

Run Code Online (Sandbox Code Playgroud)

主要是猜测,但更大/内联字节码会导致分支预测和缓存问题

所以我能够使用VMOptions手动关闭`functionB()`的内联:`-XX:CompileCommand = dontinline,com.jd.benchmarking.StrangeBehaviour :: functionB`这似乎消除了较短函数的延迟.所以至少我们知道它肯定是引起问题的内联.@ k5_你会在答案中加入这个吗？我会接受你的回答. (3认同)

Answer 2

Erw*_*idt 21

完整的答案是k5_和Tony的答案的组合.

在发布基准测试之前,OP发布的代码省略了一个热启动循环以触发HotSpot编译; 因此,当包含print语句时,10倍(在我的计算机上)加速,结合了HotSpot花费的时间来编译字节码到CPU指令,以及CPU指令的实际运行.

如果我在定时循环之前添加一个单独的预热循环,则print语句只有2.5倍的加速.

这表明HotSpot/JIT编译在内联方法时会花费更长的时间(如Tony所解释的),并且代码的运行需要更长时间,可能是因为更糟糕的缓存或分支预测/流水线性能,如k5_所示.

public static void main(String[] args) {
    // Added the following warmup loop before the timing loop
    for (int i = 0; i < 50000; i++) {
        functionA(6, 0);
    }

    long startTime = System.nanoTime();
    for (int i = 0; i < 50000; i++) {
        functionA(6, 0);
    }
    long endTime = System.nanoTime();
    System.out.format("%.2f seconds elapsed.\n", (endTime - startTime) / 1000.0 / 1000 / 1000);
}

Run Code Online (Sandbox Code Playgroud)

Answer 3

Ton*_*ony 18

我和@ k5_一起,似乎存在一个阈值来确定是否内联函数.如果JIT编译器决定内联它,它将导致大量的工作和时间来-XX:+PrintCompilation显示它:

  task-id
    158   32       3       so_test.StrangeBehaviour::functionB (326 bytes)   made not entrant
    159   35       3       java.lang.String::<init> (82 bytes)
    160   36  s    1       java.util.Vector::size (5 bytes)
    1878   37 %     3       so_test.StrangeBehaviour::main @ 6 (65 bytes)
    1898   38       3       so_test.StrangeBehaviour::main (65 bytes)
    2665   39       3       java.util.regex.Pattern::has (15 bytes)
    2667   40       3       sun.misc.FDBigInteger::mult (64 bytes)
    2668   41       3       sun.misc.FDBigInteger::<init> (30 bytes)
    2668   42       3       sun.misc.FDBigInteger::trimLeadingZeros (57 bytes)
    2.51 seconds elapsed.

Run Code Online (Sandbox Code Playgroud)

上面是没有注释的信息,下面是一个注释,它将方法大小从326字节减少到318字节.你可以注意到输出的第1列中的任务id,后者中的任务ID要大得多,这会导致更多的时间.

  task-id
    126   35       4       so_test.StrangeBehaviour::functionA (12 bytes)
    130   33       3       so_test.StrangeBehaviour::functionA (12 bytes)   made not entrant
    131   36  s    1       java.util.Vector::size (5 bytes)
    14078   37 %     3       so_test.StrangeBehaviour::main @ 6 (65 bytes)
    14296   38       3       so_test.StrangeBehaviour::main (65 bytes)
    14296   39 %     4       so_test.StrangeBehaviour::functionB @ 2 (318 bytes)
    14300   40       4       so_test.StrangeBehaviour::functionB (318 bytes)
    14304   34       3       so_test.StrangeBehaviour::functionB (318 bytes)   made not entrant
    14628   41       3       java.util.regex.Pattern::has (15 bytes)
    14631   42       3       sun.misc.FDBigInteger::mult (64 bytes)
    14632   43       3       sun.misc.FDBigInteger::<init> (30 bytes)
    14632   44       3       sun.misc.FDBigInteger::trimLeadingZeros (57 bytes)
    14.50 seconds elapsed.

Run Code Online (Sandbox Code Playgroud)

如果您将代码更改为以下内容(添加两行并将通信输出到打印行),您可以看到代码大小更改为326字节,并且现在运行得更快:

        if (StrangeBehaviour.recursionFlag) {
            int a = 1;
            int b = 1;
            if (recursionSwitch == 0) {
                if (functionA(recursionDepth - 1, 1 - recursionSwitch)) return true;
            } else {
                if (!functionA(recursionDepth - 1, 1 - recursionSwitch)) return false;
            }
        } else {
            // This block is never entered into.
            // Yet commenting out one of the lines below makes the program run slower!
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
          //System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
        }

Run Code Online (Sandbox Code Playgroud)

新时间和JIT编译器信息:

    140   34       3       so_test.StrangeBehaviour::functionB (326 bytes)   made not entrant
    145   36       3       java.lang.String::<init> (82 bytes)
    148   37  s    1       java.util.Vector::size (5 bytes)
    162   38       4       so_test.StrangeBehaviour::functionA (12 bytes)
    163   33       3       so_test.StrangeBehaviour::functionA (12 bytes)   made not entrant
    1916   39 %     3       so_test.StrangeBehaviour::main @ 6 (65 bytes)
    1936   40       3       so_test.StrangeBehaviour::main (65 bytes)
    2686   41       3       java.util.regex.Pattern::has (15 bytes)
    2689   42       3       sun.misc.FDBigInteger::mult (64 bytes)
    2690   43       3       sun.misc.FDBigInteger::<init> (30 bytes)
    2690   44       3       sun.misc.FDBigInteger::trimLeadingZeros (57 bytes)
    2.55 seconds elapsed.

Run Code Online (Sandbox Code Playgroud)

总之:

当方法大小超过某些限制时,JIT不会内联此函数;
如果我们注释掉一条线,它减小到一个低于阈值的尺寸,JIT决定内联它;
内联该函数会导致许多JIT任务,从而减慢程序的运行速度.

更新:

根据我最新的试用版,这个问题的答案并不那么容易:

正如我的代码示例所示,正常的内联优化将会

加速计划
并且不需要花费太多编译器工作(在我的测试中,当内联发生时它甚至花费更少的工作).

但是在这个问题中,代码会导致很多JIT工作并减慢程序,这似乎是JIT的一个bug.目前还不清楚为什么会导致JIT如此多的工作.

归档时间：	8 年，10 月前
查看次数：	4365 次
最近记录：	8 年，9 月前