Измерение времени: от Java до ядра и обратно

Постановка задачи

Даже самые основные проблемы становятся интересными, когда вы копаете достаточно глубоко. Сегодня я хотел бы глубоко погрузиться в измерение времени на Java. Мы начнем с самых основ Java API и постепенно опустимся в нашем стеке: через исходный код OpenJDK, glibc, вплоть до ядра Linux. Мы посмотрим на производительность в различных средах и попытаемся обдумать результаты.

Мы собираемся исследовать измерение прошедшего времени: количество времени, которое проходит от начального события до конечного события некоторой деятельности. Это полезно для повышения производительности, оперативного мониторинга и контроля времени ожидания.

Следующий псевдокод является распространенной идиомой, которую мы можем видеть практически в любой кодовой базе:

Иногда это менее явно. Мы могли бы использовать принципы Аспектно-ориентированного программирования, чтобы избежать загрязнения нашего бизнес-кода тем, что по сути является операционным вопросом, но он все еще присутствует в той или иной форме.

Прошедшее время на Яве

Java предлагает два основных примитива для измерения времени: System.currentTimeMillis() и System.nanoTime() . Есть несколько различий между этими двумя вызовами, давайте разберем их.

1. Стабильность пункта происхождения

System.currentTimeMillis() возвращает количество миллисекунд с начала эпохи Unix — 1 января 1970 года по Гринвичу. С другой стороны, System.nanoTime() возвращает количество наносекунд с некоторой произвольной точки в прошлом.

Это сразу говорит нам, что самая точная гранулярность currentTimeMillis() составляет 1 миллисекунду. Это делает невозможным измерение менее 1 мс. Тот факт, что currentTimeMillis() использует 1 января 1970 года UTC в качестве ориентира, является как хорошим, так и плохим.

Почему это хорошо? Мы можем сравнивать значения currentTimeMillis() возвращаемые двумя разными JVM и даже двумя разными компьютерами.
Почему это плохо? Сравнение не будет очень полезным, когда у наших компьютеров нет синхронизированного времени. Часы в типичных серверных фермах не идеально синхронизированы, и всегда будет некоторый разрыв. Это все еще может быть приемлемо, если я сравниваю файлы журналов из двух разных систем: это нормально, если метки времени не синхронизированы идеально. Однако иногда разрыв может привести к катастрофическим результатам, например, когда он используется для разрешения конфликтов в распределенных системах.

2. Часы Монотонность

Другая проблема заключается в том, что возвращаемые значения не гарантируются монотонно увеличивающимися. Что это означает? Если у вас есть 2 последовательных вызова currentTimeMillis() , второй вызов может вернуть более низкое значение, чем первый. Это противоречит здравому смыслу и может привести к бессмысленным результатам, таким как прошедшее время, являющееся отрицательным числом. Понятно, что currentTimeMillis() не является хорошим выбором для измерения прошедшего времени внутри приложения. Что насчет nanoTime() ?

System.nanoTime() не использует эпоху Unix в качестве ориентира, но в прошлом не указывалось ни одной неуказанной точки. Точка остается неизменной во время одного выполнения JVM, но это все. Таким образом, бессмысленно даже сравнивать значения nanoTime() возвращаемые двумя разными JVM, работающими на одном компьютере, не говоря уже о разных компьютерах. Опорная точка обычно связана с последним запуском компьютера, но это просто деталь реализации, и мы не можем на нее полностью положиться. Преимущество состоит в том, что даже если время настенных часов в компьютере по какой-то причине идет в обратном направлении, это не окажет никакого влияния на nanoTime() . Вот почему nanoTime() является отличным инструментом для измерения истекшего времени между двумя событиями в одной JVM, но мы не можем сравнивать временные метки из двух разных JVM.

Реализация на Java

Давайте рассмотрим, как currentTimeMillis() и nanoTime() реализованы в Java. Я собираюсь использовать источники из текущей главы OpenJDK 14 . System.currentTimeMillis() является нативным методом, поэтому наша Java IDE не расскажет нам, как он реализован. Этот нативный код выглядит немного лучше:

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

Этот код делегирует функции gettimeofday() . Эта функция возвращает простую структуру:

Структура содержит количество секунд с начала эпохи и количество микросекунд в данной секунде. Контракт currentTimeMillis() должен возвращать количество миллисекунд с начала эпохи, поэтому он должен выполнить простое преобразование: jlong(time.tv_sec) * 1000 + jlong(time.tv_usec / 1000)

Функция gettimeofday() реализована glibc, которая в конечном итоге вызывает ядро ​​Linux. Мы посмотрим глубже позже.

Давайте посмотрим, как nanoTime() : оказывается, он не слишком отличается — System.nanoTime() также является нативным методом: public static native long nanoTime(); и jvm.cpp делегирует для конкретной реализации ОС:

Реализация javaTimeNanos () в Linux довольно интересна:

Есть 2 ветви: если ОС поддерживает монотонные часы, она будет использовать их, а в противном случае она делегирует нашему старому другу gettimeofday() . Gettimeofday() — это тот же вызов Posix, который используется System.currentTimeMillis() ! Очевидно, что конверсия выглядит немного иначе, поскольку гранулярность nanoTime() выше, но это тот же вызов Posix! Это подразумевает, что при некоторых обстоятельствах System.nanoTime() использует эпоху Unix в качестве ссылки, поэтому он может вернуться в прошлое! Другими словами: это не гарантировано быть монотонным!

Хорошей новостью является то, что, насколько мне известно, все современные дистрибутивы Linux поддерживают монотонные часы. Я предполагаю, что эта ветка существует для совместимости с древними версиями ядра / glibc. Если вам интересны подробности того, как HotSpot определяет, поддерживает ли ОС монотонные часы, посмотрите этот код . Для большинства из нас важно знать, что OpenJDK практически всегда вызывает функцию clock_gettime() которая реализована в делегатах glibc и glibc для ядра Linux.

Тест I — Локальный ноутбук

На данный момент у нас есть некоторая интуиция, как nanoTime() и currentTimeMillis() . Давайте посмотрим, быстро ли они сверкают или медленно. Вот простой тест JMH:

Когда я запускаю этот тест на своем ноутбуке с Ubuntu 19.10, я получаю следующие результаты:

эталонный тест	Режим	Cnt	Гол	ошибка	Единицы измерения
Bench.millis	avgt	25	29,625	± 2.172	нс / оп
Bench.nano	avgt	25	25,368	± 0,643	нс / оп

System.currentTimeMillis() занимает около 29 наносекунд на вызов, а System.nanoTime() около 25 наносекунд. Не здорово, не ужасно. Это подразумевает, что, вероятно, неразумно использовать System.nano() для измерения чего-либо, занимающего менее нескольких десятков наносекунд, поскольку накладные расходы нашего инструментария будут выше, чем измеренный интервал. Мы также должны избегать использования nanoTime() в тесных циклах, потому что задержка быстро увеличивается. С другой стороны, представляется целесообразным использовать nanoTime() для измерения, например, времени отклика с удаленного сервера или продолжительности дорогостоящих вычислений.

Тест II — AWS

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

Давайте раскрутим машину c5.xlarge с Ubuntu 16.04 LTS и воспользуемся замечательным инструментом SDKMAN для установки Java 13, созданной замечательными людьми в проекте AdoptOpenJDK :

Вот результаты:

эталонный тест	Режим	Cnt	Гол	ошибка	Единицы измерения
Bench.millis	avgt	25	28,467	± 0.034	нс / оп
Bench.nano	avgt	25	27,331	± 0,003	нс / оп

Это почти так же, как на ноутбуке, не так уж плохо. Теперь давайте попробуем экземпляр c3.large. Это старшее поколение, но все еще часто используется:

эталонный тест	Режим	Cnt	Гол	ошибка	Единицы измерения
Bench.millis	avgt	25	362,491	± 0.072	нс / оп
Bench.nano	avgt	25	367,348	± 6.100	нс / оп

Это не выглядит хорошо на всех! c3.large — более старый и меньший экземпляр, поэтому ожидается некоторое замедление, но это слишком много! И currentTimeMillis() и nanoTime() на один порядок медленнее. Поначалу 360 нс могут показаться не такими уж плохими, но подумайте об этом: чтобы измерить прошедшее время только один раз, вам нужно два вызова. Таким образом, каждое измерение стоит примерно 0,7 мкс. Если у вас есть 10 зондов, измеряющих различные стадии выполнения, то вы находитесь на 7 мкс. Для сравнения: сетевые карты на 40 Гбит / с имеют обратную связь около 10 мкс. Это означает, что добавление нескольких зондов к нашему горячему пути может оказать очень существенное влияние на задержку!

Немного о расследовании ядра

Почему экземпляр c3 намного медленнее моего ноутбука или экземпляра c5? Оказывается, это связано с источниками синхронизации Linux и, что более важно, с интерфейсом glibc – kernel. Мы уже знаем, что каждый вызов nanoTime() или currentTimeMillis() вызывает собственный код в OpenJDK, который вызывает glibc, который вызывает ядро ​​Linux.

Интересной частью является переход ядра glibc – Linux: обычно, когда процесс вызывает функцию ядра Linux, также известную как syscall, он включает переход из режима пользователя в режим ядра и обратно. Этот переход является относительно дорогой операцией, включающей много шагов:

• хранить регистры процессора в стеке ядра
• запустить код ядра с фактической функцией
• скопировать результат из пространства ядра в пространство пользователя
• восстановить регистры процессора из стека ядра
• вернуться к пользовательскому коду

Это никогда не было дешевой операцией, и она становится все дороже с появлением атак по побочным каналам безопасности и связанных с ними методов смягчения.

Чувствительные к производительности приложения обычно усердно работают, чтобы избежать перехода пользователь-ядро. Само ядро ​​Linux предлагает ярлык для некоторых очень частых системных вызовов, называемый vDSO — виртуальный динамический общий объект . По сути, он экспортирует некоторые из своих функций и отображает их в адресное пространство процесса. Пользовательский процесс может вызывать эти функции, как если бы они были обычными функциями из обычной общей библиотеки. Оказывается, что как в clock_gettime() и в gettimeofday() реализован такой ярлык, поэтому, когда glibc вызывает clock_gettime() , он фактически просто переходит на адрес памяти без выполнения дорогостоящего перехода пользователь-ядро.

Все это звучит как интересная теория, но не объясняет, почему System.nanoTime() намного медленнее в экземпляре c3.

Время эксперимента

Мы будем использовать другой замечательный инструмент Linux для мониторинга количества системных вызовов: perf . Самым простым тестом, который мы можем сделать, является запуск нашего теста производительности и подсчет всех системных вызовов в нашей операционной системе. Синтаксис perf для этого довольно прост:
sudo perf stat -e raw_syscalls:sys_enter -I 1000 -a
Это даст нам общее количество системных вызовов в секунду. Одна важная деталь: он даст нам только реальные системные вызовы с полным переходом пользовательского режима в режим ядра. Звонки vDSO не учитываются. Вот как это выглядит при работе на экземпляре c5:

Вы можете видеть около 130 системных вызовов каждую секунду. Учитывая, что каждая итерация нашего теста занимает менее 30 нс, очевидно, что приложение использует vDSO для обхода системных вызовов.

Вот как это выглядит на экземпляре c3:

Это более 1 300 000 системных вызовов в секунду! Кроме того, задержка как nanoTime() и currentTimeMillis() примерно удвоилась до 700 нс / операция. Это довольно убедительное указание на то, что каждая итерация запускает реальный системный вызов!

Давайте использовать другую команду perf для сбора дополнительных доказательств. Эта команда подсчитает все системные вызовы, вызванные за 5 секунд, и сгруппирует их по имени:
sudo perf stat -e 'syscalls:sys_enter_*' -a sleep 5
При работе на экземпляре c5 ничего необычного не происходит. Однако при работе на экземпляре c3 мы можем видеть это:

Это наш дымящийся пистолет! Очень убедительное доказательство того, что когда тест выполняется на блоке c3, он выполняет настоящий системный вызов gettimeofday() ! Но почему?

Это соответствующая часть ядра 4.4 (используется в Ubuntu 16.04):

Эта функция отображается в пользовательской памяти и вызывается glibc, когда Java вызывает System.currentTimeMillis() . Он вызывает do_realtime() который заполняет struct tv текущим временем, а затем возвращает обратно вызывающей стороне. Важно то, что все это выполняется в пользовательском режиме, без каких-либо медленных системных вызовов. Хорошо, если do_realtime() возвращает VCLOCK_NONE . В этом случае он вызывает vdso_fallback_gtod() который будет выполнять медленный системный вызов.

Почему экземпляр c3 выполняет резервный системный вызов, а c5 — нет? Ну, это связано с изменением техники виртуализации! AWS использует виртуализацию Xen с самого начала. Около 2 лет назад они объявили о переходе с Xen на виртуализацию KVM . Экземпляры C3 используют виртуализацию Xen, более новые экземпляры C5 используют KVM. Для нас важно то, что каждый метод использует свою реализацию Linux Clock. Linux показывает текущий источник синхронизации в /sys/devices/system/clocksource/clocksource0/current_clocksource .

Это с3:

И это с5:

Оказывается, реализация kvm-clock устанавливает vclock_mode в VCLOCK_PVCLOCK что означает, что медленная vclock_mode VCLOCK_PVCLOCK выше, не берется. Источник синхронизации Xen вообще не устанавливает этот режим и остается на VCLOCK_NONE . Это приведет к vdso_fallback_gtod() функцию vdso_fallback_gtod() которая в конечном итоге инициирует настоящий системный вызов!

Преимущество Linux в том, что он легко настраивается и часто дает нам достаточно веревки, чтобы повеситься. Мы можем попытаться изменить источник синхронизации на c3 и повторно запустить тест. Доступные источники видны через $ cat /sys/devices/system/clocksource/clocksource0/available_clocksource
xen tsc hpet acpi_pm $ cat /sys/devices/system/clocksource/clocksource0/available_clocksource
xen tsc hpet acpi_pm

TSC означает счетчик меток времени , довольно быстрый источник и, что важно для нас, правильную реализацию vDSO. Давайте переключим источник синхронизации в экземпляре c3 с Xen на TSC:

Проверьте, действительно ли оно переключено:

Выглядит неплохо! Теперь мы можем повторно запустить наш тест:

эталонный тест	Режим	Cnt	Гол	ошибка	Единицы измерения
Bench.millis	avgt	25	25,558	± 0.070	нс / оп
Bench.nano	avgt	25	24,101	± 0.037	нс / оп

Числа выглядят довольно хорошо! На самом деле лучше, чем экземпляр C5 с KVM-часы. Количество системных вызовов в секунду соответствует уровню экземпляра c5:

Некоторые люди рекомендуют переключать источник синхронизации на TSC даже при использовании виртуализации Xen. Я не знаю достаточно о его возможных побочных эффектах, но, очевидно, даже некоторые крупные компании делают / делали это в производстве. Очевидно, это не доказывает, что это безопасно, но это признак того, что это работает для некоторых.

Заключительные слова

Мы видели, как детали реализации низкого уровня могут оказать существенное влияние на производительность обычных вызовов Java. Это не теоретическая проблема, видимая только в микробенчмарках, реальные системы тоже подвержены влиянию . Вы можете прочитать немного больше о vDSO непосредственно в дереве исходных текстов ядра Linux .

Я не смог бы провести это расследование без моих замечательных коллег в Hazelcast . Это команда мирового уровня, и я многому у них научился! Я хотел бы поблагодарить Брендана Грегга за его коллекцию трюков , моя память довольно слаба, и Брендан создал отличную таблицу.

И последнее, но не менее важное: если вы заинтересованы в производительности, времени выполнения или распределенных системах, следуйте за мной !