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

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

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


java benchmarking microbenchmark
person Vini    schedule 29.04.2009    source источник

Ответы (8)


arrow_upward
7
arrow_downward

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

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

person Steve Kuo    schedule 29.04.2009

arrow_upward
7
arrow_downward

Проблемы, упомянутые Андреас и непредсказуемость 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.

person Community    schedule 29.04.2009

arrow_upward
5
arrow_downward

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

     System.out.println(k);

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

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

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

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

person Andreas Petersson    schedule 29.04.2009

arrow_upward
3
arrow_downward

Помимо JITting, другими факторами могут быть:

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

Если вы хотите получить хорошие бенчмарки, вам следует

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

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

person Jens Alfke    schedule 29.04.2009

arrow_upward
2
arrow_downward

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

person cletus    schedule 29.04.2009

arrow_upward
1
arrow_downward

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

person eKek0    schedule 29.04.2009

arrow_upward
1
arrow_downward

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

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

person Kai    schedule 29.04.2009

arrow_upward
1
arrow_downward

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

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