Программа Java работает медленнее, когда код, который никогда не выполняется, закомментирован

Я наблюдал какое-то странное поведение в одной из моих программ 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;
    }
}

у меня есть две функции, functionA() и functionB() которые вызывают друг друга рекурсивно. Обе функции принимают recursionDepth параметр, управляющий завершением рекурсии. functionA() звонки functionB() только с recursionDepth без изменений. functionB() звонки functionA() 16 раз с recursionDepth - 1. Рекурсия завершается, когда functionA() С recursionDepth на 0.

functionB() блок кода System.out.println() звонки. Этот блок никогда не вводится, так как вход контролируется a boolean recursionFlag переменная, которая имеет значение true и никогда не изменяется во время выполнения программы. Однако, комментируя даже один из println() вызовы заставляют программу работать медленнее. На моей машине время выполнения составляет println() вызовы присутствуют, и >2s когда один из вызовов закомментирован.

что может быть причиной такого поведения? Я только предполагаю, что существует некоторая наивная оптимизация компилятора, которая запускается параметром, связанным с длиной блока кода (или количеством вызовов функций и т. д.). Любое дальнейшее понимание этого будет высоко оценено!

Edit: я использую JDK 1.8.

3 57
javascript compiler-optimization recursion

3 ответа:

полный ответ представляет собой комбинацию ответов k5_ и Тони.

код, опубликованный OP, пропускает цикл прогрева для запуска компиляции HotSpot перед выполнением теста; следовательно, 10-кратное (на моем компьютере) ускорение при включении инструкций печати объединяет как время, проведенное в HotSpot для компиляции байт-кода в инструкции CPU, так и фактическое выполнение инструкций CPU.

если я добавлю отдельный цикл прогрева перед циклом синхронизации, существует только 2,5-кратное ускорение с оператором печати.

это указывает на то, что компиляция HotSpot/JIT занимает больше времени, когда метод встроен (как объяснил Тони), а также что выполнение кода занимает больше времени, вероятно, из-за худшей производительности кэша или предсказания ветвей/конвейерной обработки, как показал 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);
}
21

прокомментированный код влияет на то, как обрабатывается встраивание. Если functionB становится длиннее / больше (больше инструкций байт-кода), он не будет встроен в functionA.

таким образом, @J3D1 смог использовать VMOptions для ручного отключения встраивания для functionB ():-XX:CompileCommand=dontinline,com.jd.benchmarking.StrangeBeh‌​aviour::functionB это, кажется, устраняет задержку с более короткой функцией.

С помощью параметров виртуальной машины вы можете отображать встраивание -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

более короткая версия попытается встроить 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

в основном угадывание, но более крупный / встроенный байт-код вызовет проблемы с предсказанием ветвей и кэшированием

41

Я с @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.

верхняя информация без комментариев, следующее с комментарием, который уменьшает размер метода с 326 байт до 318 байт. И вы можете заметить идентификатор задачи в столбце 1 производства, настолько больше в последнем, что вызывает больше время.

  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.

и если вы измените код на следующий (добавьте две строки и запишите строку печати), вы можете увидеть, что размер кода изменяется на 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("...");
        }

Новое время и 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.

в заключение:

  • когда размер метода превышает некоторые пределы, JIT не будет встроить эту функцию;
  • и если мы закомментируем строку, которая уменьшится до размера ниже порог, JIT решили встроить его;
  • встраивание этой функции вызывает много задач JIT, которые замедляют работу программы.

обновление:

Accroding to мое последнее испытание, ответа на этот вопрос не так просто:

как показывает мой пример кода, нормальная встроенная оптимизация будет

  • ускоряет программы
  • и не стоит много работы компилятора (в моем тесте, это даже стоить меньше работы, когда встроенный происходит).

но в этой проблеме код вызывает много работы JIT и замедляет работу программы, которая кажется ошибкой JIT. И до сих пор не ясно, почему это вызывает так много работы JIT.

18