Супермедленный и супербыстрый бенчмарк
В недавней статье про производительность Java разгорелась дискуссия на тему измерения производительности. Глядя на неё, с грустью приходится сознавать, что многие люди до сих пор не понимают, насколько сложно правильно измерить время выполнения того или иного кода. Кроме того, люди вообще не привыкли, что один и тот же код в разных условиях может выполняться существенно разное время. К примеру, вот одно из мнений:
Если мне надо узнать, «какой язык быстрее для меня на моей задаче», то я прогоню самый примитивный бенчмарк в мире. Если разница будет существенной (скажем, на порядок) — то скорее всего и на пользовательской машине все будет примерно также.
К сожалению, самый примитивный бенчмарк в мире — это как правило неправильно написанный бенчмарк. И не следует надеяться, что неправильный бенчмарк измерит результат хотя бы с точностью до порядка. Он может измерить что-нибудь абсолютно другое, что будет совершенно отличаться от реальной производительности программы с аналогичным кодом. Давайте рассмотрим пример.
Скажем, мы увидели Java 8 Stream API и хотим проверить, насколько быстро оно работает для простой математики. Например, для простоты возьмём стрим из целых чисел от 0 до 99999, возведём каждое в квадрат с помощью операции map, ну и на этом всё, больше ничего делать не будем. Мы же просто производительность замерить хотим, да? Но даже беглого просмотра API хватит, чтобы увидеть, что стримы ленивы и IntStream.range(0, 100_000).map(x -> x * x) по факту ничего не выполнит. Поэтому мы добавим терминальную операцию forEach, которая как-нибудь использует наш результат. Например, увеличит его на единичку. В итоге мы получим вот такой тест:
static void test() {
IntStream.range(0, 100_000).map(x -> x * x).forEach(x -> x++);
}Отлично. Как измерить, сколько он работает? Все знают: взять время в начале, время в конце и посчитать разницу! Добавим метод, который производит замер времени и возвращает результат в наносекундах:
static long measure() {
long start = System.nanoTime();
test();
long end = System.nanoTime();
return end - start;
}Ну, а теперь просто выведем результат. На моём не самом быстром Core i7 и Open JDK 8u91 64bit я в разных запусках получаю число примерно в районе от 50 до 65 миллионов наносекунд. То есть 50–65 миллисекунд. Сто тысяч возведений в квадрат за 50 миллисекунд? Это чудовищно! Это всего два миллиона раз в секунду. Двадцать пять лет назад компы и то быстрее в квадрат возводили. Java безбожно тормозит! Или нет?
На самом деле первое использование лямбд и Stream API в приложении всегда добавит задержку на 50–70 мс на современных компьютерах. Ведь за это время надо сделать немало вещей:
- Загрузить классы для генерации рантайм-представлений лямбд (см. LambdaMetafactory) и всё, что с ними связано.
- Загрузить классы самого Stream API (их там немало)
- Для лямбд, что используются в нашем коде (в нашем случае одна) и в коде Stream API (а вот там их немало) сгенерировать рантайм-представление.
- JIT-компилировать это всё добро хотя бы как-нибудь.
Всё это требует немало времени и на самом деле даже удивительно, что удаётся уложиться в 50 мс. Но всё это нужно ровно один раз.
Лирическое отступление
Вообще с наличием динамической загрузки и кэширования чего бы то ни было становится очень сложно понять, что же мы измерили. Это касается не только Java. Простой библиотечный вызов может инициировать подгрузку с жёсткого диска и инициализацию разделяемой библиотеки (а представьте, что жёсткий диск ещё и в спящий режим ушёл). В результате вызов может занять гораздо больше времени. Париться по этому поводу или нет? Иногда приходится. Например, во времена Windows 95 загрузка разделяемой библиотеки OLE32.DLL занимала существенное время и в тормозах бы объявили первую программу, которая бы попыталась загрузить OLE32. Это вынуждало разработчиков по возможности не загружать OLE32 как можно дольше, чтобы виноватыми стали другие программы. Кое-где в других библиотеках даже реализованы функции, дублирующие некоторые функции OLE32, как раз с целью избежать загрузки OLE32. Подробнее об этой истории читайте у Рэймонда Чена.
Итак, мы поняли, что наш бенчмарк супермедленный, потому что в процессе делается много вещей, которые надо сделать ровно один раз после загрузки. Если наша программа планирует работать больше секунды, скорее всего нас это сильно не волнует. Поэтому давайте «прогреем JVM» — произведём этот замер 100 тысяч раз и выведем результат последнего замера:
for (int i = 100000; i >= 0; i--) {
long res = measure();
if(i == 0)
System.out.println(res);
}Эта программа завершается быстрее, чем за секунду, и печатает на моей машине 70–90 наносекунд. Это супер! Значит, на одно возведение в квадрат приходится 0.7–0.9 пикосекунд? Java возводит в квадрат больше триллиона раз в секунду? Java супербыстрая! Или нет?
Уже на второй итерации многое из вышеприведённого списка выполнится и процесс ускорится раз в 100. Дальше JIT-компилятор будет постепенно докомпилировать разные куски кода (его внутри Stream API немало), собирая профили выполнения и оптимизируя всё больше. В конечном итоге JIT оказывается достаточно умён, чтобы заинлайнить всю цепочку лямбд и понять, что результат умножения нигде не используется. Наивная попытка использовать его через инкремент JIT-компилятор не обманула: побочного эффекта у этой операции всё равно нет. JIT-компилятору не хватило сил выкосить вообще весь стрим целиком, но он смог выкосить внутренний цикл, фактически сделав производительность теста не зависящей от количества итераций (замените IntStream.range(0, 100_000) на IntStream.range(0, 1_000_000) — результат будет тот же).
Кстати, на таких временах оказывается существенным время выполнения и гранулярность nanoTime(). Даже на одинаковом железе, но в разных OS вы можете получить существенно разный ответ. Подробнее об этом — у Алексея Шипилёва.
Итак, мы написали «самый примитивный бенчмарк». Сперва он оказался супермедленным, а после небольшой доработки — супербыстрым, почти в миллион раз быстрее. Мы хотели измерить, как быстро с помощью Stream API выполняется возведение в квадрат. Но в первом тесте эта математическая операция потонула в море других операций, а во втором тесте просто не выполнялась. Опасайтесь делать поспешные выводы.
Где же правда? Правда в том, что этот тест не имеет ничего общего с реальностью. Он не производит видимых эффектов в вашей программе, то есть фактически он ничего не делает. В реальности вы редко пишете код, который ничего не делает, и уж конечно, он вряд ли приносит вам деньги (хотя бывают и исключения). Пытаться ответить на вопрос, сколько времени на самом деле выполняется возведение в квадрат внутри Stream API, вообще малоосмысленно: это очень простая операция и в зависимости от окружающего кода JIT-компилятор может очень по-разному скомпилировать цикл с умножением. Помните, что производительность не аддитивна: если A выполняется x секунд, а B выполняется y секунд, то совсем не факт, что выполнение A и B займёт x+y секунд. Может оказаться абсолютно не так.
Если вы хотите лёгких ответов, то в реальных программах правда будет где-то посередине: накладные расходы на стрим на 100000 целых чисел, которые возводятся в квадрат, составят примерно в 1000 раз больше, чем супербыстрый результат, и примерно в 1000 раз меньше, чем супермедленный. Но в зависимости от множества факторов может быть и хуже. Или лучше.
На прошлогоднем Joker’е я рассматривал несколько более интересный пример замера производительности Stream API и копнул глубже, что там происходит. Ну и обязательная ссылка на JMH: он поможет не наступать на простые грабли при измерении производительности JVM-языков. Хотя, конечно, даже JMH волшебным образом все ваши проблемы не решит: думать всё равно придётся.
