Объяснение производительности: код работает медленнее после прогрева
Приведенный ниже код выполняет один и тот же расчет 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;
}
}
2 ответа
Коротко: Компилятор 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.
Для меня в первой компиляции кажется, что на самом деле компилируется только первый блок в main, это можно узнать по номерам строк. Он содержит такие забавные вещи, как это:
0x00007fa35505fc5b: add $0x1,%r8 ;*ladd
; - weird$CountByOne::getNext@6 (line 12)
; - weird::main@28 (line 31)
0x00007fa35505fc5f: mov %r8,0x10(%rbx) ;*putfield i
; - weird$CountByOne::getNext@7 (line 12)
; - weird::main@28 (line 31)
0x00007fa35505fc63: add $0x1,%r14 ;*ladd
; - weird::main@31 (line 31)
(Действительно, это очень долго, из-за раскручивания и наматывания петли)
По-видимому, во время перекомпиляции main, второй И третий блок компилируется. Второй блок там очень похож на первый вариант. (Опять просто выдержка)
0x00007fa35505f05d: add $0x1,%r8 ;*ladd
; - weird$CountByOne::getNext@6 (line 12)
; - weird::main@101 (line 42)
0x00007fa35505f061: mov %r8,0x10(%rbx) ;*putfield i
; - weird$CountByOne::getNext@7 (line 12)
; - weird::main@101 (line 42)
0x00007fa35505f065: add $0x1,%r13 ;*ladd
ОДНАКО третий блок компилируется по-разному. Без врезки и раскатывания
На этот раз весь цикл выглядит так:
0x00007fa35505f20c: xor %r10d,%r10d
0x00007fa35505f20f: xor %r8d,%r8d ;*lload
; - weird::main@171 (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::main@174 (line 53)
; {optimized virtual_call}
0x00007fa35505f224: mov 0x8(%rsp),%r10
0x00007fa35505f229: add %rax,%r10 ;*ladd
; - weird::main@177 (line 53)
0x00007fa35505f22c: mov 0x10(%rsp),%r8d
0x00007fa35505f231: inc %r8d ;*iinc
; - weird::main@180 (line 52)
0x00007fa35505f234: cmp $0x5f5e100,%r8d
0x00007fa35505f23b: jl 0x00007fa35505f212 ;*if_icmpge
; - weird::main@168 (line 52)
Я предполагаю, что JIT определил, что эта часть кода используется нечасто, так как он использовал информацию профилирования при выполнении второго блока, и поэтому не сильно оптимизировал ее. Также JIT кажется ленивым в том смысле, что не перекомпилирует один метод после того, как все соответствующие части были скомпилированы. Помните, что первый результат компиляции не содержал исходного кода для второго / третьего блока AT all, поэтому JIT пришлось его перекомпилировать.
Вы должны поместить каждый цикл в другой метод. Причина, по которой вам нужно это сделать, заключается в том, что JIT собирает статистику о том, как выполнялся код, и это используется для оптимизации кода. Однако метод оптимизируется после того, как он вызывается 10000 раз или цикл запускается 10000 раз.
В вашем случае первый цикл вызывает оптимизацию всего метода, даже если последующие циклы не выполнялись, поэтому статистика не собиралась. Поместите каждый цикл в свой метод, и этого не произойдет.