Почему два последовательных вызова одного и того же метода дают разное время выполнения?
Вот пример кода:
public class TestIO{
public static void main(String[] str){
TestIO t = new TestIO();
t.fOne();
t.fTwo();
t.fOne();
t.fTwo();
}
public void fOne(){
long t1, t2;
t1 = System.nanoTime();
int i = 10;
int j = 10;
int k = j*i;
System.out.println(k);
t2 = System.nanoTime();
System.out.println("Time taken by 'fOne' ... " + (t2-t1));
}
public void fTwo(){
long t1, t2;
t1 = System.nanoTime();
int i = 10;
int j = 10;
int k = j*i;
System.out.println(k);
t2 = System.nanoTime();
System.out.println("Time taken by 'fTwo' ... " + (t2-t1));
}
}
Это дает следующий результат: 100 Время, затраченное 'fOne' ... 390273 100 Время, затраченное 'fTwo' ... 118451 100 Время, затраченное 'fOne' ... 53359 100 Время, затраченное 'fTwo' ... 115936 Нажмите любую клавишу для продолжения.,,
Почему выполнение первого и того же метода в первый раз занимает значительно больше (значительно больше), чем последовательные вызовы?
Я пытался дать -XX:CompileThreshold=1000000 в командной строке, но не было никакой разницы.
8 ответов
Есть несколько причин. JIT (Just In Time) компилятор может не работать. JVM может выполнять оптимизации, которые отличаются между вызовами. Вы измеряете прошедшее время, поэтому, возможно, на вашем компьютере работает что-то кроме Java. Кэши процессора и ОЗУ, вероятно, "греются" при последующих вызовах.
Вам действительно нужно сделать несколько вызовов (тысячами), чтобы получить точное время выполнения метода.
Проблемы, упомянутые Андреасом, и непредсказуемость JIT верны, но еще одна проблема - загрузчик классов:
Первый звонок fOne коренным образом отличается от последних, потому что это то, что делает первый вызов System.out.printlnЭто означает, что загрузчик классов извлекает из кэша диска или файловой системы (обычно это кэшируется) все классы, необходимые для печати текста. Дай параметр -verbose:class в JVM, чтобы увидеть, сколько классов на самом деле загружается во время этой маленькой программы.
Я заметил аналогичное поведение при запуске модульных тестов - первый тест для вызова большой платформы занимает гораздо больше времени (в случае с Guice около 250 мс на C2Q6600), даже если тестовый код будет таким же, потому что первый вызов - это когда сотни классов загружаются загрузчиком классов.
Так как ваша примерная программа очень короткая, накладные расходы, вероятно, связаны с очень ранними JIT-оптимизациями и загрузкой классов. Сборщик мусора, вероятно, даже не запустится до завершения программы.
Обновить:
Теперь я нашел надежный способ узнать, что действительно занимает время. Никто еще не узнал об этом, хотя это тесно связано с загрузкой классов - это было динамическое связывание нативных методов!
Я изменил код следующим образом, чтобы журналы показывали, когда начинаются и заканчиваются тесты (путем просмотра, когда загружаются эти пустые классы маркеров).
TestIO t = new TestIO();
new TestMarker1();
t.fOne();
t.fTwo();
t.fOne();
t.fTwo();
new TestMarker2();
Команда для запуска программы с правильными параметрами JVM, которые показывают, что действительно происходит:
java -verbose:class -verbose:jni -verbose:gc -XX:+PrintCompilation TestIO
И вывод:
* snip 493 lines *
[Loaded java.security.Principal from shared objects file]
[Loaded java.security.cert.Certificate from shared objects file]
[Dynamic-linking native method java.lang.ClassLoader.defineClass1 ... JNI]
[Loaded TestIO from file:/D:/DEVEL/Test/classes/]
3 java.lang.String::indexOf (166 bytes)
[Loaded TestMarker1 from file:/D:/DEVEL/Test/classes/]
[Dynamic-linking native method java.io.FileOutputStream.writeBytes ... JNI]
100
Time taken by 'fOne' ... 155354
100
Time taken by 'fTwo' ... 23684
100
Time taken by 'fOne' ... 22672
100
Time taken by 'fTwo' ... 23954
[Loaded TestMarker2 from file:/D:/DEVEL/Test/classes/]
[Loaded java.util.AbstractList$Itr from shared objects file]
[Loaded java.util.IdentityHashMap$KeySet from shared objects file]
* snip 7 lines *
И причина этой разницы во времени заключается в следующем: [Dynamic-linking native method java.io.FileOutputStream.writeBytes ... JNI]
Мы также видим, что JIT-компилятор не влияет на этот тест. Есть только три метода, которые компилируются (например, java.lang.String::indexOf в приведенном фрагменте), и все они происходят до fOne метод называется.
Тестируемый код довольно тривиален. самое дорогое предпринятое действие
System.out.println(k);Итак, что вы измеряете, так это то, как быстро записываются выходные данные отладки. Это сильно варьируется и может даже зависеть от положения окна отладки на экране, если ему нужно прокрутить его размер и т. Д.
JIT / Hotspot постепенно оптимизирует часто используемые пути кода.
Процессор оптимизирует для ожидаемых путей кода. Используемые пути чаще выполняются быстрее.
Ваш размер выборки слишком мал. Такие микробенчмарки обычно выполняют фазу прогрева, и вы можете видеть, насколько интенсивно это должно быть сделано, поскольку Java действительно быстро ничего не делает.
В дополнение к JITting, другие факторы могут быть:
- Блокировка выходного потока процесса при вызове System.out.println
- Ваш процесс запланирован другим процессом
- Сборщик мусора, выполняющий некоторую работу в фоновом потоке
Если вы хотите получить хорошие тесты, вы должны
- Выполните код, который вы тестируете, большое количество раз, по крайней мере, несколько тысяч, и рассчитайте среднее время.
- Игнорировать время первых нескольких вызовов (из-за JITting и т. Д.)
- Отключите GC, если можете; это не может быть вариантом, если ваш код генерирует много объектов.
- Удалите запись (вызовы println) из кода, который тестируется.
На нескольких платформах есть библиотеки бенчмаркинга, которые помогут вам в этом; они также могут рассчитывать стандартные отклонения и другую статистику.
Наиболее вероятный виновник - движок горячей точки JIT (точно в срок). В основном, первый тайм-код выполняется, машинный код "запоминается" JVM, а затем повторно используется в будущих выполнениях.
Как уже было предложено, виновником может быть JIT, но так же, как и время ожидания ввода-вывода, а также время ожидания ресурса, если в этот момент другие процессы на машине использовали ресурсы.
Мораль этой истории в том, что микробенчмаркинг - сложная проблема, особенно для Java. Я не знаю, почему вы это делаете, но если вы пытаетесь выбрать между двумя подходами к проблеме, не измеряйте их таким образом. Используйте шаблон разработки стратегии и запустите всю программу с двумя различными подходами и измерьте всю систему. Это делает небольшие потери времени обработки даже равномерными в долгосрочной перспективе, и дает вам гораздо более реалистичное представление о том, насколько узко ограничена производительность всего вашего приложения (подсказка: это, вероятно, меньше, чем вы думаете).
Ну, наиболее вероятный ответ - инициализация. JIT, безусловно, не является правильным ответом, так как для его оптимизации требуется намного больше циклов. Но в самый первый раз может быть:
- поиск классов (кэшируется, поэтому второй поиск не требуется)
- загрузка классов (после загрузки остается в памяти)
- получение дополнительного кода из нативной библиотеки (нативный код кэшируется)
- наконец, он загружает код для выполнения в кэш-память L1 ЦП. Это наиболее вероятный случай для ускорения в вашем смысле и в то же время причина, по которой эталон (будучи микробенчмарком) не говорит о многом. Если ваш код достаточно мал, второй вызов цикла может быть полностью выполнен изнутри ЦП, что быстро. В реальном мире этого не происходит, потому что программы больше, а повторное использование кэша L1 далеко не так велико.
Я думаю, это потому, что во второй раз сгенерированный код был уже оптимизирован, после первого запуска.