Сервер замирал на 12 секунд каждые шесть часов: сборка мусора JVM

MAATRIX

Раз в несколько часов сервис переставал отвечать. Не падал, не писал ошибок — просто на 10-12 секунд переставал принимать запросы, а потом как ни в чём не бывало продолжал работать. CPU в этот момент был низким, диск — свободным, сеть — в порядке. Проблема с такими симптомами особенно неприятна тем, что классические подозреваемые сразу отпадают, а привычка искать причину «снаружи» процесса уводит расследование в сторону от настоящего виновника. Разберём, как нашли реальную причину и что с ней сделали.

Симптом: 12 секунд тишины каждые шесть часов

Сервис — обычное Java-приложение (Spring Boot, HTTP API поверх встроенного Tomcat), стоящее за балансировщиком вместе с ещё несколькими репликами. Первый сигнал пришёл не от инженеров, а от системы алертинга: health-check раз за разом не успевал получить ответ вовремя, балансировщик исключал ноду из пула на несколько секунд, потом возвращал обратно. Пользователи почти ничего не замечали — трафик просто перераспределялся на соседние реплики, — но в логах балансировщика и в графиках p99-задержки эти провалы были видны отчётливо.

Важная деталь, которая в итоге стала ключом к разгадке: провалы происходили не хаотично, а с заметной регулярностью — примерно раз в шесть часов, плюс-минус несколько минут. Шесть часов — не «круглый» интервал вроде часа или суток, поэтому не сразу приходит в голову, что за ним стоит конкретный запланированный процесс, а не случайность.

Что не помогало на этом этапе:

• В логах приложения на момент зависания не было ни одного исключения, ни одной строки про ошибку.
• top/htop в момент инцидента не показывали аномальной загрузки CPU — ни на хосте, ни внутри контейнера.
• Память по free -h выглядела нормально, OOM killer не срабатывал (в dmesg и journalctl -k было пусто).
• Проблема не воспроизводилась по требованию — только ждать следующего цикла и смотреть, что покажут метрики.

Первые подозреваемые: сеть, диск, соседи по хосту

Прежде чем идти внутрь JVM, команда закрыла стандартный набор версий, которые обычно стоят за подобными «необъяснимыми» паузами.

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

Диск проверяли через iostat -xz 1 за архивные интервалы, совпадающие с зависаниями — утилизация и await были в норме. То же самое с vmstat 1 — колонка wa (ожидание ввода-вывода) оставалась низкой на всём интервале.

Отдельно проверили «шумных соседей»: сервер стоял на арендованном VPS, поэтому первой мыслью было заподозрить CPU steal от других виртуалок на том же хосте:

mpstat -P ALL 1
# столбец %steal — практически нулевой на всём интервале инцидента

Раз %steal не рос, дело было не в переподписке физического CPU хостером. Заодно проверили cgroup-лимиты контейнера — не упирается ли процесс в квоту CPU:

cat /sys/fs/cgroup/cpu.stat | grep throttled
# nr_throttled и throttled_usec росли крайне медленно, не синхронно с паузами

Throttling не совпадал по времени с зависаниями, так что и версия с ограничением CPU в контейнере отпала. Проверили и системные cron-задачи (logrotate, updatedb, бэкапы) — ни одна не была запланирована с шагом в шесть часов, который совпадал бы с моментами зависания.

Что показали метрики и GC-логи

Поворотный момент случился, когда кто-то из команды открыл в Grafana не системные метрики хоста, а метрики самой JVM, которые уже собирались через micrometer/JMX-экспортер, но обычно никто на них не смотрел, кроме как для общего дашборда «жив ли сервис».

График использования памяти в старом поколении кучи (old generation) показывал классическую «пилу»: значение росло практически линейно на протяжении нескольких часов, а затем резко обрушивалось вниз — и момент обрушения с точностью до минуты совпадал с зафиксированными зависаниями. Именно этот график и стал первой уликой, указавшей внутрь JVM, а не наружу, на инфраструктуру.

Дальше в дело пошли GC-логи. В приложении они были включены не полностью — стандартный вывод без деталей, — поэтому первым делом добавили унифицированное логирование сборщика мусора (доступно начиная с Java 9+):

-Xlog:gc*:file=/var/log/app/gc.log:time,uptime,level,tags:filecount=10,filesize=50M

Уже на следующем цикле (том самом, шестичасовом) в логе нашлась строка вида:

[2026-08-19T03:14:07.912+0000] GC(482) Pause Full (Ergonomics)
[2026-08-19T03:14:19.664+0000] GC(482) Pause Full (Ergonomics) 11842M->2103M(16384M) 11.752s

Длительность паузы почти один в один совпадала с тем, что видели на балансировщике — 10-12 секунд простоя. Дополнительно подтвердили картину через jstat, запущенный в фоне на протяжении нескольких часов:

jstat -gcutil <pid> 5s
   S0     S1     E      O      M     CCS    YGC   YGCT    FGC   FGCT     GCT
   0.00  12.34  45.21  97.88  95.10  93.40   842   6.210     0    0.000    6.210
   0.00  12.34  48.90  99.95  95.10  93.40   851   6.340     1   11.752   18.092

Колонка O (occupancy старого поколения) перед паузой подходила вплотную к 100%, а после паузы резко падала — ровно то, что и предсказывал график в Grafana. Про то, зачем вообще разделять логи, метрики и трассировки и как они дополняют друг друга в расследованиях, у нас есть отдельная статья — логи, метрики и трассы: чем отличаются. Здесь именно связка метрики плюс лог дала однозначный ответ: зависания — это Full GC, останавливающий все потоки приложения (stop-the-world) на время полной очистки и уплотнения кучи.

Настоящая причина: тяжёлая задача раз в 6 часов и неподходящий сборщик мусора

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

Проверка списка запланированных задач в приложении (@Scheduled в Spring) нашла кандидата — фоновую задачу пересборки внутреннего кеша отчётов с периодом в шесть часов. Логика была простой и на вид безобидной: выгрузить данные из базы, полностью собрать новую версию отчёта в памяти (список объектов и Map на несколько сотен тысяч записей), а затем одним присваиванием подменить ссылку на старый кеш — классический паттерн «собрать копию, потом атомарно подменить указатель». Проблема в том, что в момент подмены в памяти на короткое время одновременно существуют старая и новая версии структуры, и обе уже успели дожить до старого поколения кучи, потому что сборка была не мгновенной.

Совпадение двух факторов и давало эффект: задача создавала резкий скачок объёма живых данных в старом поколении, а сборщик, работавший без настройки под короткие паузы (по сути ориентированный на пропускную способность, а не на задержку) на куче в несколько десятков гигабайт, реагировал единственным доступным способом — полной остановкой мира и уплотнением всей кучи. Чем крупнее куча и чем больше в ней живых данных к моменту паузы, тем дольше идёт полная сборка — отсюда и заметная пауза вместо привычных миллисекунд молодых сборок.

Чтобы подтвердить гипотезу, а не просто поверить в правдоподобную теорию, сняли дамп кучи в момент, когда old-gen occupancy уже подбиралась к пиковым значениям:

jcmd <pid> GC.heap_dump /tmp/heap-before-pause.hprof

Анализ в Eclipse MAT по «Dominator Tree» показал, что львиную долю retained-памяти в этот момент держали временные коллекции той самой задачи пересборки кеша — обе версии одновременно, старая и новая. Отдельно свериться стоило и с настройками контейнера: если приложение работает внутри Docker/Kubernetes, лимит памяти cgroup и параметр -Xmx должны быть согласованы, иначе JVM либо неверно оценивает доступную память, либо упирается в лимит контейнера ещё до собственных порогов кучи — эта грабля разобрана в статье как cgroups ограничивают контейнер. В данном случае лимиты были согласованы корректно, но проверка обязательна. Общий подход к поиску утечек и аномального роста потребления памяти по шагам описан в статье утечка памяти: как поймать за неделю до падения — здесь утечки как таковой не было, память освобождалась после каждой Full GC полностью, но методика поиска пригодилась та же самая.

Что изменили: сборщик мусора, память, сама задача

Правку сделали в трёх направлениях сразу — тюнинг одной только JVM без исправления задачи убрал бы симптом лишь частично, а исправление задачи без пересмотра настроек GC оставило бы систему хрупкой к следующей похожей нагрузке.

Переписали саму задачу. Полную пересборку отчёта целиком в памяти заменили на потоковую обработку: данные из базы читаются постранично (курсором, ограниченными порциями), новая версия кеша собирается инкрементально, а старая не держится целиком в памяти параллельно с новой — в любой момент в памяти не больше одной полной копии, а не двух. Это убрало сам источник скачка объёма живых данных, а не просто спрятало его за более щедрым сборщиком мусора.

Перешли на G1 с явной целью по паузам вместо ранее использовавшегося сборщика, ориентированного на пропускную способность:

-XX:+UseG1GC
-XX:MaxGCPauseMillis=200
-Xms16g -Xmx16g

Отдельно зафиксировали -Xms равным -Xmx — это убирает паузы на изменение размера кучи во время работы и делает поведение GC предсказуемее с самого старта процесса, а не только после прогрева.

Пересчитали память с запасом на служебные нужды JVM, а не только на кучу — метапространство классов, стеки потоков, прямые буферы NIO тоже занимают память контейнера. Вместо жёстко зашитого -Xmx перешли на:

-XX:MaxRAMPercentage=70.0
-XX:+UseContainerSupport

так JVM сама берёт долю от реального лимита памяти контейнера — удобно ещё и тем, что при смене тарифа сервера не нужно вручную пересчитывать -Xmx под новый объём памяти.

Коротко, чем базовые варианты сборщиков отличаются по компромиссам — не как рецепт «что лучше», а как ориентир для собственного выбора:

Как не попасть в такую же историю: мониторинг и алерты

Главный вывод команды был не «мы починили одну задачу», а «мы не видели, что искать, потому что не смотрели на правильные метрики». Вместе с фиксом добавили постоянный мониторинг именно тех сигналов, которые привели к разгадке.

GC-логирование оставили включённым на постоянной основе — накладные расходы на unified-логи минимальны, а без них расследование заняло бы намного больше времени. Ротация (filecount/filesize в самой команде логирования) не даёт логам копиться бесконечно.

Настроили алерт на длительность пауз GC и на занятость старого поколения через экспортер метрик JVM (jvm_gc_pause_seconds_* или аналог из используемой библиотеки метрик). Примерное правило для Prometheus/Alertmanager:

- alert: JVMFullGCPauseTooLong
  expr: increase(jvm_gc_pause_seconds_sum{action="end of major GC"}[10m]) > 5
  for: 1m
  labels:
    severity: warning
  annotations:
    summary: "Долгие Full GC паузы на {{ $labels.instance }}"

Конкретные пороги стоит подбирать по своей нагрузке и типу сборщика — цифра выше лишь ориентир. Отдельно добавили дашборд с занятостью старого поколения кучи рядом с общими системными метриками — раньше эти графики существовали, но на них смотрели только при явных ошибках приложения, а не при «тихих» зависаниях без исключений в логах.

Отдельный урок касается периодических фоновых задач вообще, не только в Java: любая задача, которая раз в несколько часов «пересобирает всё целиком в памяти», — частый источник именно таких трудноуловимых пауз, потому что нагрузка на память кратковременная и не видна на обычных дашбордах CPU. Похожий по духу случай, только с сетевой задержкой, а не с GC, разобран в статье скачки задержки в три-пятнадцать: бэкап соседа забивал канал — тот же принцип: регулярность инцидента почти всегда указывает на такую же регулярную задачу где-то в системе, и первым делом стоит сверять время инцидентов с расписанием cron/scheduler, а не только с системными метриками хоста.

Частые вопросы