Производительность Объяснение: код работает медленнее после разогрева

В приведенном ниже коде выполняется один и тот же расчет 3 раза (он не делает много: в основном добавляет все числа от 1 до 100 м). Первые 2 блока работают примерно в 10 раз быстрее, чем третий. Я запустил эту тестовую программу более 10 раз, и результаты показывают очень небольшую дисперсию.

Во всяком случае, я ожидаю, что третий блок будет работать быстрее (компиляция JIT), но типичный вывод:

35974537
36368455
296471550

Может кто-нибудь объяснить, что происходит? (Чтобы быть ясным, я не пытаюсь ничего исправить здесь, просто пытаюсь лучше понять, что происходит)

Примечание:

  • GC не запускается во время программы (контролируется с помощью -XX:+PrintGC)
  • тестируется с версиями Oracle JDK 1.6.0_30, 1.7.0_02 и 1.7.0_05
  • также тестировался со следующими параметрами: -XX:+PrintGC -Xms1000m -Xmx1000m -XX:NewSize=900m = > тот же результат
  • блок вместо этого помещается в цикл, все прогоны
  • если блок извлекается в метод, все прогоны выполняются быстро (независимо от того, вызван ли метод 3 раза или в цикле не имеет значения)
public static void main(String... args) {
    //three identical blocks
    {
        long start = System.nanoTime();
        CountByOne c = new CountByOne();
        int sum = 0;
        for (int i = 0; i < 100000000; i++) {
            sum += c.getNext();
        }
        if (sum != c.getSum()) throw new IllegalStateException(); //use sum
        long end = System.nanoTime();
        System.out.println((end - start));
    }
    {
        long start = System.nanoTime();
        CountByOne c = new CountByOne();
        int sum = 0;
        for (int i = 0; i < 100000000; i++) {
            sum += c.getNext();
        }
        if (sum != c.getSum()) throw new IllegalStateException(); //use sum
        long end = System.nanoTime();
        System.out.println((end - start));
    }
    {
        long start = System.nanoTime();
        CountByOne c = new CountByOne();
        int sum = 0;
        for (int i = 0; i < 100000000; i++) {
            sum += c.getNext();
        }
        if (sum != c.getSum()) throw new IllegalStateException(); //use sum
        long end = System.nanoTime();
        System.out.println((end - start));
    }
}

public static class CountByOne {

    private int i = 0;
    private int sum = 0;

    public int getSum() {
        return sum;
    }

    public int getNext() {
        i += 1;
        sum += i;
        return i;
    }
}

Ответы

Ответ 1

Короткие: компилятор Just In Time не работает.

Прежде всего, вы можете использовать опцию -XX:+PrintCompilation, чтобы увидеть КОГДА JIT что-то делает. Затем вы увидите что-то вроде этого:

$ java -XX:+PrintCompilation weird
    168    1             weird$CountByOne::getNext (28 bytes)
    174    1 %           weird::main @ 18 (220 bytes)
    279    1 %           weird::main @ -2 (220 bytes)   made not entrant
113727636
    280    2 %           weird::main @ 91 (220 bytes)
106265475
427228826

Итак, вы видите, что метод main скомпилирован иногда во время первого и второго блоков.

Добавление параметров -XX:+PrintCompilation -XX:+UnlockDiagnosticVMOption даст вам больше информации о том, что делает JIT. Обратите внимание, для этого требуется hsdis-amd64.so, который, как представляется, не очень хорошо доступен в распространенных дистрибутивах Linux. Возможно, вам придется скомпилировать его самостоятельно из OpenJDK.

Что вы получаете, это огромный кусок кода ассемблера для getNext и main.

Для меня в первой компиляции кажется, что только первый блок в основном компилируется, вы можете указать номера строк. Он содержит такие забавные вещи:

  0x00007fa35505fc5b: add    $0x1,%r8           ;*ladd
                                                ; - weird$CountByOne::[email protected] (line 12)
                                                ; - weird::[email protected] (line 31)
  0x00007fa35505fc5f: mov    %r8,0x10(%rbx)     ;*putfield i
                                                ; - weird$CountByOne::[email protected] (line 12)
                                                ; - weird::[email protected] (line 31)
  0x00007fa35505fc63: add    $0x1,%r14          ;*ladd
                                                ; - weird::[email protected] (line 31)

(Действительно, он очень длинный из-за разворачивания и вставки петли)

В процессе перекомпиляции main, второй и третий блок компилируется. Второй блок выглядит очень похоже на первую версию. (Снова просто выдержка)

 0x00007fa35505f05d: add    $0x1,%r8           ;*ladd
                                                ; - weird$CountByOne::[email protected] (line 12)
                                                ; - weird::[email protected] (line 42)
  0x00007fa35505f061: mov    %r8,0x10(%rbx)     ;*putfield i
                                                ; - weird$CountByOne::[email protected] (line 12)
                                                ; - weird::[email protected] (line 42)
  0x00007fa35505f065: add    $0x1,%r13          ;*ladd

ОДНАКО третий блок скомпилирован по-разному. Без инкрустации и разворачивания

На этот раз весь цикл выглядит следующим образом:

  0x00007fa35505f20c: xor    %r10d,%r10d
  0x00007fa35505f20f: xor    %r8d,%r8d          ;*lload
                                                ; - weird::[email protected] (line 53)
  0x00007fa35505f212: mov    %r8d,0x10(%rsp)
  0x00007fa35505f217: mov    %r10,0x8(%rsp)
  0x00007fa35505f21c: mov    %rbp,%rsi
  0x00007fa35505f21f: callq  0x00007fa355037c60  ; OopMap{rbp=Oop off=580}
                                                ;*invokevirtual getNext
                                                ; - weird::[email protected] (line 53)
                                                ;   {optimized virtual_call}
  0x00007fa35505f224: mov    0x8(%rsp),%r10
  0x00007fa35505f229: add    %rax,%r10          ;*ladd
                                                ; - weird::[email protected] (line 53)
  0x00007fa35505f22c: mov    0x10(%rsp),%r8d
  0x00007fa35505f231: inc    %r8d               ;*iinc
                                                ; - weird::[email protected] (line 52)
  0x00007fa35505f234: cmp    $0x5f5e100,%r8d
  0x00007fa35505f23b: jl     0x00007fa35505f212  ;*if_icmpge
                                                ; - weird::[email protected] (line 52)

Я предполагаю, что JIT определил, что эта часть кода не используется много, поскольку она использовала профилирующую информацию из второго исполнения блока и, следовательно, не очень оптимизировала ее. Кроме того, JIT представляется ленивым в некотором смысле не перекомпилировать один метод после того, как все соответствующие части были скомпилированы. Помните, что первый результат компиляции не содержал исходный код для второго/третьего блока AT, поэтому JIT пришлось перекомпилировать это.

Ответ 2

Вам нужно поместить каждый цикл в другой метод. Причина, по которой вам нужно сделать это, - это то, что JIT собирает статистику о том, как был запущен код, и это используется для оптимизации кода. Тем не менее, метод оптимизируется после того, как он называется 10000 раз, или цикл выполняется 10000 раз.

В вашем случае первый цикл запускает весь оптимизируемый метод, хотя последующие циклы не выполнялись, поэтому статистические данные не собирались. Поместите каждый цикл в свой собственный метод, и этого не произойдет.