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(). Этот блок никогда не вводится, поскольку запись управляется переменной boolean recursionFlag, которая установлена на true и никогда не изменяется во время выполнения программы. Однако комментирование даже одного из вызовов println() заставляет программу работать медленнее. На моей машине время выполнения составляет < 0,2 с всеми присутствующими вызовами println() и > 2s, когда один из вызовов закомментирован.

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

Изменить: я использую JDK 1.8.

Ответы

Ответ 1

Полный ответ - это комбинация ответов k5_ и Tony.

Код, который опубликовал 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);
}

Ответ 2

Прокомментированный код влияет на обработку обработки. Если функция Б становится длиннее/больше (больше инструкций байт-кода), она не будет включена в функцию.

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

с параметрами vm, которые вы можете отобразить вложение -XX:+UnlockDiagnosticVMOptions -XX:+PrintInlining

Большая версия, не встроенная функция B

@ 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

Более короткая версия попытается встроить функцию B, вызывая несколько дальнейших попыток.

@ 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

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

Ответ 3

Я с @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, которые замедляют работу программы.

Обновление

Подтверждая мое последнее испытание, ответ на этот вопрос не так прост:

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

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

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