Вместо того чтобы ждать, пока Java-приложение окончательно "зависнет" из-за GC, инженеры Netflix сделали jvmquake — инструмент, который сам определяет, что JVM уже не спасти, вызывает дамп памяти и аккуратно завершает процесс. Меньше тревог, больше аптайма. 

Подробности - в новом переводе от команды Spring АйО. 

Команда Cloud Data Engineering в Netflix поддерживает различные приложения, работающие на JVM, включая популярные хранилища данных, такие как Cassandra и Elasticsearch. Хотя большинство наших кластеров стабильно функционируют с выделенной им памятью, время от времени возникает ситуация с «фатальным запросом» или багом в самом хранилище, что приводит к неконтролируемому потреблению памяти. Это может спровоцировать зацикливание сборки мусора (GC) или даже привести к исчерпанию памяти JVM.

Мы высоко ценим инструмент jvmkill, который помогает справляться с подобными ситуациями. jvmkill — это агент, работающий внутри процесса JVM с использованием API JVMTI. Когда JVM исчерпывает память или не может создать новый поток, jvmkill вмешивается и завершает весь процесс. Мы используем jvmkill в сочетании с флагом Hotspot -XX:HeapDumpOnOutOfMemoryError, чтобы впоследствии проанализировать дамп кучи и выяснить причину нехватки ресурсов. Для наших приложений такой подход является оптимальным: JVM, столкнувшаяся с нехваткой памяти, не может продолжать работу, и после вмешательства jvmkill система systemd перезапускает сбойный процесс с нуля.

Тем не менее, даже с jvmkill мы продолжаем сталкиваться с проблемами в ситуациях, когда JVM почти — но ещё не полностью — исчерпала память.

Комментарий от Евгения Сулейманова

Здесь отлично показан крайне "коварный" случай из прода: не "чистый OOM", а near‑OOM. Формально ресурсы еще не исчерпаны, поэтому стандартные триггеры (ResourceExhausted, OOM‑хуки) молчат - но для пользователей узел уже фактически недоступен, потому что mutator utilization падает почти до нуля. В этом смысле "GC‑долг" - очень удачная операционная метрика: она измеряет не абстрактное "плохой GC", а накопленное время, которое процесс "задолжал"" системе из‑за STW‑пауз. Это ровно тот уровень выявления, который коррелирует с SLO: узел либо выполняет полезную работу, либо его нужно быстро вывести из оборота и перезапустить.

Такие Java-процессы застревают в бесконечных циклах сборки мусора, практически не выполняя полезной работы между паузами. Поскольку ресурсы ещё не полностью исчерпаны, jvmkill не распознаёт проблему. Клиенты же, напротив, быстро замечают, что пропускная способность их узлов хранилища данных, как правило, падает в десять тысяч раз.

Чтобы проиллюстрировать это поведение, мы можем воспроизвести «фатальный запрос» в JVM Cassandra¹, запросив у Cassandra несколько раз подряд загрузку всего набора данных в память:

cqlsh> PAGING OFF
Disabled Query paging.
cqlsh> SELECT * FROM large_ks.large_table;
OperationTimedOut: errors={}, last_host=some host
cqlsh> SELECT * FROM large_ks.large_table;
Warning: schema version mismatch detected, which might be caused by DOWN nodes; if this is not the case, check the schema versions of your nodes in system.local and system.peers.
Schema metadata was not refreshed. See log for details.

Затем мы используем jstat и журналы GC, чтобы убедиться, что машина действительно находится в спирали смерти сборки мусора:

$ sudo -u cassandra jstat -gcutil $(pgrep -f Cassandra) 100ms
S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT
0.00 100.00 100.00 100.00  97.96  95.10     21    8.678    11  140.498  149.176
0.00 100.00 100.00 100.00  97.96  95.10     21    8.678    11  140.498  149.176
0.00 100.00 100.00 100.00  97.96  95.10     21    8.678    11  140.498  149.176
$ grep "stopped" gclog | tail
2019-03-05T02:59:15.111+0000: 1057.680: Total time for which application threads were stopped: 18.0113457 seconds, Stopping threads took: 0.0001798 seconds
2019-03-05T02:59:16.159+0000: 1058.728: Total time for which application threads were stopped: 1.0472826 seconds, Stopping threads took: 0.0001542 seconds
2019-03-05T02:59:40.461+0000: 1083.030: Total time for which application threads were stopped: 24.3016592 seconds, Stopping threads took: 0.0001809 seconds
2019-03-05T03:00:16.263+0000: 1118.832: Total time for which application threads were stopped: 35.8020625 seconds, Stopping threads took: 0.0001307 seconds
2019-03-05T03:00:51.599+0000: 1154.168: Total time for which application threads were stopped: 35.3361231 seconds, Stopping threads took: 0.0001517 seconds
2019-03-05T03:01:09.470+0000: 1172.039: Total time for which application threads were stopped: 17.8703301 seconds, Stopping threads took: 0.0002151 seconds
view rawjvmquake gclog hosted with ❤ by GitHub

По данным из журнала GC мы отчетливо видим повторяющиеся паузы продолжительностью более 20 секунд, и можем использовать инструмент GCViewer для графической интерпретации информации, содержащейся в логах:

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

  1. Легко выявляется

  2. Имеет простое решение

  3. Выигрывает от быстрого вмешательства

Другими словами, мы решили автоматизировать последний удар, который раньше выполнялся вручную.

Решение: проактивное выявление и завершение проблемных JVM

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

Мы также рассмотрели существующие опции JVM, такие как GCHeapFreeLimit, GCTimeLimit, OnOutOfMemoryError, ExitOnOutOfMemoryError и CrashOnOutOfMemoryError. Мы обнаружили, что эти опции либо не работают стабильно на всех JVM и сборщиках мусора, либо их сложно настроить и понять, либо они попросту не работают в различных пограничных случаях. Из-за непоследовательности и сложности (или невозможности) настройки существующих классификаторов исчерпания ресурсов JVM мы решили разработать собственный классификатор, чтобы дополнить их.

Так появилась наша разработка — jvmquake, начавшаяся с вечерней мысли: «насколько же это может быть сложно?» Мы начали с идеи, что для любой рабочей нагрузки JVM должна тратить значительную часть времени на выполнение кода программы, а не на паузы, связанные со сборкой мусора. Если доля времени, затраченного на выполнение программы, слишком долго остаётся ниже определённого порога — JVM явно находится в нездоровом состоянии и должна быть завершена.

Мы реализовали эту идею, смоделировав время, которое JVM тратит на паузы для сборки мусора, как «долг». Если JVM проводит 200 мс в сборке мусора, это добавляет 200 мс к её счётчику долга. Время, затраченное на выполнение кода программы, «погашает» накопленный долг — но не ниже нуля. Таким образом, если программа затем выполняется не менее 200 мс, счётчик долга снова опускается до нуля.

Комментарий от Михаила Поливаха

Этот как раз моделирование алгоритма "Token Bucket", который часто используют для рейт лимита.

Если JVM тратит больше времени на выполнение программы, чем на GC (т.е. достигает пропускной способности >50% при соотношении работы к GC >1:1), её долг будет стремиться к нулю. Напротив, если пропускная способность ниже 50%, долг будет стремиться к бесконечности. Такой подход к расчёту «долга» аналогичен алгоритму протекающего ведра, применённому к контролю пропускной способности. В нашем случае «вода» добавляется со скоростью, пропорциональной времени сборки мусора, и удаляется со скоростью, пропорциональной времени выполнения приложения:

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

Если бы jvmquake был подключён к этой JVM, её работа была бы остановлена на уровне пунктирной линии.

Мы остановились на настраиваемом пороге с довольно щадящим значением по умолчанию — 30 секунд: если JVM завершает сборку мусора с накопленным «долгом» более 30 секунд, jvmquake завершает процесс. Для замера этих значений мы использовали обратные вызовы JVMTI — GarbageCollectionStart и GarbageCollectionFinish.

Помимо порога долга, мы добавили ещё два параметра настройки:

  • runtime_weight: применяется как множитель ко времени, затраченному на выполнение кода программы, что позволяет задать целевой уровень пропускной способности, отличный от соотношения 1:1 (50%). Например, значение runtime_weight = 2 соответствует цели 1:2 (33% пропускной способности). В более общем виде, runtime_weight со значением x означает соотношение 1:x (пропускная способность 100 % / (x + 1)). Серверные JVM обычно работают с пропускной способностью более 95 %, поэтому даже минимум в 50 % — это довольно консервативный порог.

  • action: jvmkill всегда отправляет процессу только SIGKILL, но в jvmquake мы добавили возможность преднамеренно вызвать OOM в JVM, а также отправлять произвольные сигналы самому себе до SIGKILL. В следующем разделе мы объясним, зачем могут понадобиться такие дополнительные действия.

После применения jvmquake, если снова запустить тот же самый «фатальный запрос» к узлу Cassandra, теперь мы видим:

Как и раньше, JVM начинает погружаться в спираль смерти из-за сборки мусора, но на этот раз jvmquake замечает проблему после накопления 30 секунд «долга» по GC (при runtime_weight 4:1) и завершает работу JVM. Вместо того чтобы продолжать медленно умирать, как раньше, JVM теперь быстро и решительно уничтожается.

Не выбрасывайте улики!

Когда мы использовали jvmkill или завершали процесс вручную, у нас всегда была возможность собрать дамп кучи с помощью параметра -XX:HeapDumpOnOutOfMemoryError или утилиты jmap. Эти дампы критически важны для отладки и выяснения первопричины утечки памяти. К сожалению, ни один из этих методов не работает, если jvmquake отправляет си��нал SIGKILL в JVM, которая ещё не столкнулась с OutOfMemoryError.

Комментарий от Михаила Поливаха

Поясню, почему для авторов это не работало. Дело в том, что SIGKILL обрабатывает ядро, и этот сигнал, by design, нельзя обработать, в отличие например от SIGTERM. Поэтому, получая SIGKILL, если вы не успели сформировать HPROF, то вы в пролёте.

Наше решение этой проблемы оказалось простым: при срабатывании jvmquake запускается поток, который начинает выделять в куче большие массивы, намеренно вызывая OutOfMemoryError. Это активирует механизм -XX:HeapDumpOnOutOfMemoryError, после чего процесс окончательно завершается.

Однако у такого подхода возникла серьёзная проблема: дампы кучи Java записываются и сохраняются на диск, и при многократных автоматических завершениях процессов наши диски могли быстро заполняться. Поэтому мы начали искать способы получения нативных core dump-файлов от ОС, вместо специфичных для JVM дампов кучи. Мы поняли, что если заставить «нездоровую» JVM отправить себе сигнал SIGABRT вместо SIGKILL, то ядро Linux автоматически создаст core dump. Этот подход нам понравился, потому что он является стандартным для всех сред выполнения (включая, в частности, Node.js и Python), а главное — он позволяет собирать даже очень большие core/heap дампы и записывать их в канал (pipe), без необходимости выделять дополнительное дисковое пространство под их хранение.

Комментарий от Михаила Поливаха

SIGABRT во многом похож на SIGTERM, только первый посылается как правило самим процессом. Само ядро интерпретирует SIGABRT как контролируемую "panic" и перед тем как терминировать процесс снимает core dump.

Core Dump это по сути снапшот состояния процесса прямо до его "смерти". Во многом, концептуально конечно, служит для той же цели, что и heap dump, то есть для разбора полетов. Core Dump-ы содержат состояние стеков, регистров проца, флагов ОС и т.д. То есть там прямо полноценный снапшот который можно GDB дебагером пройти и хотя бы понять, в каком состоянии процесс был терминирован.

Когда Linux формирует core dump, поведение по умолчанию — сохранить файл с именем core в рабочем каталоге аварийного процесса. Чтобы избежать ситуаций, при которых запись core-файла может полностью занять диск, в Linux предусмотрены ограничения ресурсов (через ulimit -c) на размер создаваемых core-файлов. По умолчанию это ограничение равно нулю, и ядро вообще не сохраняет core-файл. Но с помощью параметра kernel.core_pattern в sysctl можно задать программу, в которую будет направлен дамп через pipe (см. раздел «Piping core dumps to a program» в man-странице core).

В соответствии с этим механизмом мы написали скрипт, который сжимает core-файл и выполняет потоковую загрузку в S3, где он сохраняется вместе с метаданными об аварийном процессе.

После завершения потоковой загрузки systemd перезапускает JVM, завершившуюся из-за OOM. Это осознанный компромисс: мы синхронно загружаем core-файл в S3, чтобы избежать необходимости локального хранения. На практике мы смогли стабильно загружать core-файлы объёмом 16 ГБ менее чем за две минуты.

Узнаем, что пошло не так

Теперь, когда core dump-файл сохранён, мы можем проанализировать его и выяснить причину — это был некорректный запрос, аппаратная проблема или ошибка в конфигурации? В большинстве случаев причина становится очевидной по используемым классам и их объёму в памяти.

Наша команда внедрила jvmquake во все Java-хранилища данных. На сегодняшний день он уже предотвратил десятки инцидентов — каждый раз за считанные минуты — и повысил доступность некоторых из наших важнейших кластеров баз данных в продакшене. Кроме того, потоковая загрузка core dump-файлов и инструменты для оффлайн-конверсии помогли нам отлаживать и исправлять сложные ошибки в Cassandra и Elasticsearch, обеспечивая нашим приложениям действительно «всегда доступные» хранилища данных.

Мы уже передали множество исправлений обратно сообществу и с нетерпением ждём возможности находить и устранять ещё больше проблем в будущем.

Присоединяйтесь к русскоязычному сообществу разработчиков на Spring Boot в телеграм — Spring АйО, чтобы быть в курсе последних новостей из мира разработки на Spring Boot и всего, что с ним связано.