Привет, Хабр!
Посмотрим на логи и увидим пары строк такого вида:
[2026-07-14T03:11:22.418+0300] Total time for which application threads were stopped: 0.9182291 seconds [2026-07-14T03:11:22.418+0300] Stopping threads took: 0.9174883 seconds
Разница между этими двумя числами и есть всё содержание сегодняшнего разговора: приложение простояло почти секунду, из которых на полезную работу ушло меньше миллисекунды, а всё остальное время виртуальная машина потратила на то, чтобы дождаться остановки потоков. Тюнинг сборщика мусора здесь не поможет ничем, при том что в любом дашборде эта пауза отобразится как пауза сборщика.
Ниже мы соберём стенд, на котором такая пауза воспроизводится за двадцать строк кода, найдём виновника профилировщиком, починим флагами и померим цену починки. А заодно выясним, почему тот же самый механизм заставляет привычные профилировщики показывать узкое место не в том методе, который его создаёт.
Стенд, на котором это воспроизводится
Понадобятся три потока:
первый изображает обработку запросов и заодно замеряет, насколько его тормозят;
второй крутит обычный счётный цикл;
а третий с некоторой периодичностью инициирует операцию, требующую остановки всех потоков.
public class SafepointStall { static volatile long sink; public static void main(String[] args) throws Exception { Thread victim = new Thread(() -> { long prev = System.nanoTime(); while (true) { long now = System.nanoTime(); long gapMs = (now - prev) / 1_000_000; if (gapMs > 50) { System.out.println("поток простоял " + gapMs + " мс"); } prev = now; } }, "victim"); Thread culprit = new Thread(() -> { while (true) { sink = crunch(); } }, "culprit"); victim.setDaemon(true); culprit.setDaemon(true); victim.start(); culprit.start(); while (true) { Thread.sleep(200); System.gc(); } } static long crunch() { long sum = 0; for (int i = 0; i < Integer.MAX_VALUE; i++) { sum += i ^ (i >>> 3); } return sum; } }
Метод crunch здесь не содержит ничего необычного — такой цикл пишут при обходе примитивного массива, подсчёте контрольной суммы или свёртке метрик, и выглядит он совершенно безобидно.
Запускаем с логированием точек безопасности и с параллельным сборщиком, причём выбор сборщика тут принципиален, и почему именно — станет понятно через пару разделов:
java -XX:+UseParallelGC \ -Xlog:safepoint:file=safepoint.log:time,uptime \ SafepointStall
Уже через несколько секунд в консоли начинает капать:
поток простоял 812 мс поток простоял 907 мс поток простоял 845 мс
Заглянув в safepoint.log, видим ту же картину со стороны виртуальной машины:
[0,412s] Safepoint "GC_HeapInspection", Time since last: 201 ms, Reaching safepoint: 903 ms, At safepoint: 0 ms, Total: 903 ms
Достижение точки безопасности заняло 903 миллисекунды, а работа под остановкой — ноль, и всё это на приложении, которое умеет только складывать числа.
Почему потоки останавливаются так неохотно
Причина в том, что остановить поток в произвольном месте виртуальная машина не может при всём желании. Чтобы сборщик мусора прошёл по ссылкам и при необходимости переселил объекты, ему нужно разобрать стек каждого потока и понять, где именно лежат ссылки: часть в регистрах, часть по смещениям на стеке, а часть не существует вовсе, потому что оптимизатор доказал ненужность объекта и убрал его.
Карты, описывающие это раскладку, компилятор генерирует не для каждой машинной инструкции, такое обошлось бы неприлично дорого по памяти, а только для заранее выбранных мест, которые и называются точками безопасности.
Остановка поэтому устроена кооперативно: виртуальная машина выставляет флаг, а каждый поток самостоятельно добегает до ближайшей своей точки безопасности и там замирает, и время от выставления флага до отчёта последнего потока — это то, что в логе называется Reaching safepoint.
Опрос флага компилятор вставляет в двух местах: при возврате из метода и на обратной дуге цикла, то есть в момент, когда управление уходит на следующую итерацию. Между этими точками код выполняется недолго, а проверять флаг на каждой инструкции никто, разумеется, не станет.
Из этого правила есть исключение, вырезанное специально ради производительности, и наша секунда растёт именно из него. Обнаружив счётный цикл — с целочисленным счётчиком и границами, которые не меняются внутри тела, — компилятор опрос на обратной дуге не ставит, потому что проверка мешает разворачивать такой цикл и векторизовать его тело.
Соображение вполне разумное, а последствие получается драматическим: после того как crunch скомпилируется, поток уходит в два миллиарда итераций, где нет ни одной точки безопасности, и первая возможность отреагировать на флаг появляется у него только при возврате из метода. Все прочие потоки, включая тот, что обрабатывает запросы, в это время уже остановились и терпеливо ждут.
Убедиться, что виноват именно счётный цикл, можно совсем грубо — поменяв тип счётчика:
for (long i = 0; i < Integer.MAX_VALUE; i++) {
С длинным счётчиком цикл перестаёт быть счётным в том смысле, который различает компилятор, опрос на обратной дуге появляется, и паузы пропадают. Запустите оба варианта подряд, и разница будет видна без всяких инструментов.
Как найти такое место в чужом коде
На стенде виновник очевиден просто потому, что мы сами его туда и положили, а вот в сервисе на двести тысяч строк искать приходится инструментами. Проще всего это делает async-profiler, у которого есть режим специально под эту задачу: он снимает стеки в промежутке между выставлением флага и фактической остановкой мира.
./asprof -d 30 -e wall \ --begin SafepointSynchronize::begin \ --end RuntimeService::record_safepoint_synchronized \ -f ttsp.html $(pgrep -f SafepointStall)
В свежих версиях то же самое умещается в один флаг:
./asprof -d 30 --ttsp -f ttsp.html $(pgrep -f SafepointStall)
На получившемся флейм-графе широкая полоса придётся на SafepointStall.crunch, и полезно понимать, что это принципиально не то же самое, что обычный профиль загрузки процессора: тот покажет crunch тоже, но по совершенно другой причине, и на реальной нагрузке самый горячий метод и метод, тормозящий остановку, чаще всего оказываются разными.
Когда подключить профилировщик нельзя, жаловаться умеет сама виртуальная машина — достаточно задать порог, после которого она сообщит о превышении и назовёт отстающие потоки:
-XX:+SafepointTimeout -XX:SafepointTimeoutDelay=200
# SafepointSynchronize::begin: Timeout detected: # SafepointSynchronize::begin: Timed out while waiting for threads to stop. # SafepointSynchronize::begin: Threads which did not reach the safepoint: # "culprit" #12 prio=5 tid=0x00007f8a1c0a5800 nid=0x3f04 runnable
Имя потока в такой ситуации обычно сразу подсказывает, в какой части кода копать.
Если разбираться приходится постфактум
Логирование точек безопасности хорошо тем, что почти ничего не стоит, и плохо тем, что его надо было включить заранее, а инцидент случается тогда, когда его никто не включал. Здесь выручает встроенная запись полётных данных, которую можно поднять на уже работающем процессе:
jcmd $PID JFR.start name=sp settings=profile duration=60s filename=sp.jfr
Через минуту забираем запись и смотрим, что в ней вообще есть по нашей теме:
jfr summary sp.jfr | grep -i safepoint
Event Type Count Size (bytes) ========================================================== jdk.SafepointBegin 287 6888 jdk.SafepointStateSynchronization 287 6314 jdk.ExecuteVMOperation 287 11480
Самое интересное лежит в событии синхронизации, где записано именно время сбора потоков:
jfr print --events SafepointBegin,SafepointStateSynchronization sp.jfr | head -30
jdk.SafepointStateSynchronization { startTime = 03:11:21.501 duration = 917 ms safepointId = 1042 initialThreadCount = 41 runningThreadCount = 1 }
Поле runningThreadCount здесь ценнее всех остальных: сорок потоков из сорока одного уже остановились, один продолжает работать, и вся система ждёт его почти секунду. Чтобы не листать вывод глазами, долгие остановки удобно отфильтровать сразу:
jfr print --events SafepointStateSynchronization sp.jfr \ | grep -B2 'duration = [0-9]\{3,\} ms'
Всё, что попало в этот фильтр, длилось дольше ста миллисекунд, и по счётчику работающих потоков видно, ждали ли одного отстающего или собирали всех разом.
Починка и её цена
Проблему счётных циклов в своё время решили оптимизацией, которая разбивает такой цикл на два вложенных: внешний прокручивает итерации порциями, внутренний считает саму порцию, а опрос флага размещается на обратной дуге внешнего. Горячее ядро при этом остаётся оптимизируемым, а реакция на флаг наступает не позже, чем через размер порции.
Работает эта оптимизация по умолчанию не со всеми сборщиками — с G1, ZGC и Shenandoah она включена, а на параллельном её приходится просить явно, из-за чего мы и запускали стенд именно на нём:
java -XX:+UseParallelGC \ -XX:+UseCountedLoopSafepoints -XX:LoopStripMiningIter=1000 \ -Xlog:safepoint:file=safepoint-fixed.log:time,uptime \ SafepointStall
Сравнить результат проще всего прямо по логам:
for f in safepoint.log safepoint-fixed.log; do echo -n "$f максимум: " grep -o 'Reaching safepoint: [0-9]* ms' $f | awk '{print $3}' | sort -n | tail -1 done
safepoint.log максимум: 907 safepoint-fixed.log максимум: 0
Тот же цикл и тот же сборщик, а секундные простои исчезли, и заплатили мы за это некоторой потерей пропускной способности на горячих циклах, которую на своей нагрузке стоит померить, а не принимать на веру. Проверить, что у вас сейчас включено, можно одной командой:
java -XX:+PrintFlagsFinal -version | grep -E 'UseCountedLoopSafepoints|LoopStripMiningIter'
Увидев в выводе
falseпри том, что в коде есть длинные обходы примитивов, вы, скорее всего, уже нашли источник своих необъяснимых пауз.
Когда флаги трогать нельзя
Ситуация, когда параметры запуска менять запрещено, встречается чаще, чем хотелось бы: чужой контейнер, жёсткий регламент, страх регрессии по пропускной способности на всём приложении ради одного метода. В таком случае цикл разбивают на порции руками, повторяя ровно ту же идею, что и оптимизация компилятора.
static long crunchYielding() { long sum = 0; final int total = Integer.MAX_VALUE; final int chunk = 100_000; for (int start = 0; start < total; start += chunk) { int end = Math.min(start + chunk, total); for (int i = start; i < end; i++) { sum += i ^ (i >>> 3); } Thread.onSpinWait(); } return sum; }
Внутренний цикл здесь остаётся счётным и по-прежнему разворачивается и векторизуется, а внешний счётным уже не является, так что опрос флага на его обратной дуге компилятор поставит. Сколько это стоит, показывает обычный бенчмарк:
@BenchmarkMode(Mode.AverageTime) @OutputTimeUnit(TimeUnit.MILLISECONDS) @Fork(1) @Warmup(iterations = 3) @Measurement(iterations = 5) public class ChunkBench { @Benchmark public long plain() { return SafepointStall.crunch(); } @Benchmark public long yielding() { return SafepointStall.crunchYielding(); } }
Benchmark Mode Cnt Score Error Units ChunkBench.plain avg 5 1284,301 ± 18,442 ms/op ChunkBench.yielding avg 5 1301,772 ± 21,067 ms/op
Полтора процента пропускной способности за то, чтобы приложение перестало замирать на секунду, выглядят приемлемым обменом, а размер порции подбирается замером: слишком мелкая съест выигрыш от векторизации, слишком крупная вернёт долгие паузы.
Тот же механизм ломает ваш профилировщик
Всё сказанное имеет прямое продолжение, полезное даже тем, у кого длинных циклов в коде нет вовсе.
Классический сэмплирующий профилировщик устроен так, что раз в несколько миллисекунд запрашивает у виртуальной машины стеки всех потоков, а запрос стеков через стандартный диагностический интерфейс требует остановки всех потоков, то есть профилировщик выставляет тот самый флаг и ждёт, пока потоки добегут до своих точек безопасности.
Стеки он в результате получает не в тот момент, когда собирался сделать снимок, а в тот, когда поток добежал до ближайшего опроса, и вся выборка смещается к местам, где эти опросы расставлены, а код между ними не может попасть в статистику физически.
Продемонстрировать это можно так:
public class Bias { public static void main(String[] args) { long acc = 0; for (int outer = 0; outer < 200; outer++) { acc += hotLoop(); acc += cheapCall(acc); } System.out.println(acc); } static long hotLoop() { long sum = 0; for (int i = 0; i < 50_000_000; i++) { sum += i * 31L; } return sum; } static long cheapCall(long x) { return x % 7; } }
Профиль, снятый через запрос всех потоков, будет упорно указывать на main и cheapCall, поскольку именно там расставлены опросы флага, тогда как async-profiler, прерывающий поток сигналом операционной системы и разбирающий стек асинхронно, честно отдаст hotLoop почти на всю ширину графа:
./asprof -d 20 -e cpu -f cpu.html $PID
Самое базовое требование к сэмплированию состоит в том, что все точки программы должны попадать в выборку с равной вероятностью, а при смещении к точкам безопасности вероятности определяются не тем, где программа проводит время, а тем, куда компилятор поставил опросы. Профилировщик, останавливающий приложение несколько раз в секунду, сам добавляет накладные расходы, и растут они под нагрузкой.
Что с этим делать
Первое, что стоит сделать прямо сейчас — развести в мониторинге два числа, общее время остановки и время сбора потоков, потому что пока вы смотрите только на паузы сборщика, долгое достижение точки безопасности маскируется под его проблему и уводит расследование в тюнинг, который ничего не исправит. Минимальный набор, который почти ничего не стоит и включается один раз:
-Xlog:safepoint:file=safepoint.log:time,uptime -XX:+SafepointTimeout -XX:SafepointTimeoutDelay=200
Если вы работаете на параллельном сборщике и в коде есть длинные обходы примитивных массивов, проверьте состояние UseCountedLoopSafepoints — на G1, ZGC и Shenandoah об этом можно не думать, а на параллельном флаг придётся выставить самому либо разбить проблемные циклы на порции.
Заодно посмотрите, не включена ли на узлах подкачка: сборщик мусора обходит всю кучу, а не только горячую её часть, и вытесненные страницы всплывают ровно в тот момент, когда остальные потоки уже остановились и ждут одного отстающего.
Когда секундная пауза выглядит как проблема сборщика мусора, легко потратить время на настройку не того компонента. Умение отделять реальную причину задержки от того, что показывают привычные метрики, помогает быстрее находить узкие места и проверять гипотезы инструментами профилирования.
Если хотите глубже разобраться в диагностике производительности и поиске таких скрытых причин, присоединяйтесь к открытым урокам OTUS:
9 сентября, 20:00. «Go-профилирование: как найти и исправить „тормоза“ в продакшене». Записаться
23 сентября, 20:00. «eBPF: рентгеновское зрение для production». Записаться
А расписание всех бесплатных уроков августа смотрите в дайджесте.
