Почему два последовательных вызова одного и того же метода дают разное время выполнения?

Question

Вот пример кода:

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 в командную строку, но не было никакой разницы.

Answer 1

Есть несколько причин. JIT (Just In Time) компилятор может не работать. JVM может выполнять оптимизации, которые отличаются между вызовами. Вы измеряете прошедшее время, поэтому, возможно, на вашем компьютере работает что-то кроме Java. Кэши процессора и ОЗУ, вероятно, «прогреваются» при последующих вызовах.

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

Answer 2

Проблемы, упомянутые Andreas , и непредсказуемость JIT верны, но еще одна проблема - загрузчик классов :

Первый вызов fOne радикально отличается от последних, потому что именно это делает первый вызов System.out.println, что означает, что загрузчик классов будет из кэша диска или файловой системы (обычно он кэшируется). все классы, которые необходимы для печати текста. Передайте JVM параметр -verbose:class, чтобы увидеть, сколько классов фактически загружено во время этой маленькой программы.

Я заметил похожее поведение при запуске модульных тестов - первый тест для вызова большого фреймворка занимает гораздо больше времени (в случае с 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.

Answer 3

1. Проверенный код довольно тривиален. самое дорогое предпринятое действие -

    System.out.println(k);
   

   Итак, что вы измеряете, так это то, как быстро записываются выходные данные отладки. Это сильно варьируется и может даже зависеть от положения окна отладки на экране, если ему нужно прокрутить его размер и т. Д.

2. JIT / Hotspot постепенно оптимизирует часто используемые пути кода.

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

4. Ваш размер выборки слишком мал. Такие микробенчмарки обычно выполняют фазу прогрева, и вы можете увидеть, насколько интенсивно это нужно сделать, например Java действительно быстро ничего не делает .

Answer 4

В дополнение к JITting, другие факторы могут быть:

• Блокировка выходного потока процесса при вызове System.out.println
• Ваш процесс запланирован другим процессом
• Сборщик мусора, выполняющий некоторую работу в фоновом потоке

Если вы хотите получить хорошие тесты, вы должны

• Выполните код, который вы тестируете, большое количество раз, по крайней мере, несколько тысяч, и рассчитайте среднее время.
• Игнорировать время первых нескольких вызовов (из-за JITting и т. Д.)
• Отключите GC, если можете; это не может быть вариантом, если ваш код генерирует много объектов.
• Удалите запись (вызовы println) из тестируемого кода.

На нескольких платформах есть библиотеки бенчмаркинга, которые помогут вам в этом; они также могут рассчитывать стандартные отклонения и другие статистические данные.

Answer 5

Наиболее вероятный виновник - движок горячей точки JIT (точно в срок). Как правило, при первом выполнении временного кода машинный код «запоминается» JVM, а затем повторно используется в будущих выполнениях.

Answer 6

Ну, наиболее вероятный ответ - инициализация. JIT, безусловно, не правильный ответ, так как для его оптимизации требуется гораздо больше циклов. Но в самый первый раз может быть:

• поиск классов (кэшируется, поэтому второй поиск не требуется)
• загрузка классов (после загрузки остается в памяти)
• получение дополнительного кода из нативной библиотеки (кешируется нативный код)
• наконец, он загружает код для выполнения в кэш-память L1 ЦП. Это наиболее вероятный случай ускорения в вашем смысле и в то же время причина, по которой эталон (будучи микробенчмарком) мало что говорит. Если ваш код достаточно мал, второй вызов цикла может быть полностью выполнен изнутри ЦП, что быстро. В реальном мире этого не происходит, потому что программы больше, а повторное использование кэша L1 далеко не так велико.

Answer 7

Как уже было предложено, виновником может быть JIT, но так же, как и время ожидания ввода-вывода, а также время ожидания ресурса, если в этот момент другие процессы на машине использовали ресурсы.

Мораль этой истории в том, что микробенчмаркинг - сложная проблема, особенно для Java. Я не знаю, почему вы это делаете, но если вы пытаетесь выбрать между двумя подходами к проблеме, не измеряйте их таким образом. Используйте шаблон разработки стратегии и запустите всю программу с двумя разными подходами и измерьте всю систему. Это делает небольшие потери времени обработки даже равномерными в долгосрочной перспективе, и дает вам гораздо более реалистичное представление о том, насколько производительность всего вашего приложения ограничена в этот момент (подсказка: это, вероятно, меньше, чем вы думаете).

Answer 8

Я думаю, это потому, что во второй раз сгенерированный код уже был оптимизирован после первого запуска.