Как мы переходили на Node.JS v16, или История о сломанном GC

26 октября 2021 года вышел новый релиз Node.JS 16.13.0 ^[1] который стал Active LTS.
Как мы переводили на него наш сервис мониторинга и анализа логов PostgreSQL ^[2] и с какими проблемами столкнулись — в статье ниже.

Переключаться между версиями Node.Js удобно с помощью утилиты nvm ^[3].

nvm install 16.13.0

Запускаем тестовые коллекторы ^[4] нашей системы под Node.Js v16 и внимательно смотрим за изменениями в работе приложения. Мы отслеживаем довольно много метрик — по серверу в целом, использование приложением системных ресурсов, метрики среды выполнения, а также различные показатели самого приложения. Так что какие-либо изменения не останутся незамеченными. Кстати, подробности о методике мониторинга приложения можно узнать в этой статье ^[5].

Итак, приложение работает, но в сравнении с Node.Js v14 при той же нагрузке мы наблюдаем увеличение потребления процессорного времени и времени работы GC.

И при этом сильное ухудшение по метрикам event-loop latency:

Как узнать причину увеличения latency? Выполняем профайлинг приложения и обнаруживаем, что наиболее вероятной причиной увеличения latency является GC:

Пробуем запуститься на одном из ранних релизов v16 — результат примерно тот же.
После отката обратно на Node.Js v14 значения GC и latency возвращаются в норму:

Логично было предположить, что причиной увеличения event-loop latency в v16 являются какие-то изменения в самой Node.JS, а именно в работе GC.

Смотрим еще раз Release Notes ^[1], но никаких упоминаний об изменениях в GC не находим.
Проверяем также изменения в релизах V8 ^[6], т.к. в Node.Js v16 перешли на новую ветку V8 version 9, но и там ничего.

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

На всякий случай проверяем настройки по умолчанию для V8:

node --v8-options

и видим очень странные изменения:

т.е. обе оптимизации нового сборщика мусора Orinoco — concurrent_marking и parallel_marking, которые были включены по умолчанию в Node.Js начиная с v10, оказались выключены в v16!

Об этих оптимизациях GC можно почитать в этой статье ^[7], но если кратко — в прежних реализациях GC работал по принципу «stop-the-world»:

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

GC в основном потоке разгружается на 65-70%:

Т.е. отключение этих оптимизаций приводит к увеличению времени GC в основном потоке и как следствие к увеличению event-loop latency. Как раз наш случай!

Пробуем их включить:

node --concurrent-marking --parallel-marking

И снова проблема — node выдает фатальную ошибку с генерацией core dump:

Порывшись в исходниках, нашли что включить эти опции возможно только если они были включены на этапе компиляции:

Причину мы установили, но для исправления обращаемся в сообщество и составляем Bug report ^[8]. Ошибку оперативно исправили ^[9] и подготовили небольшой patch ^[10], которого еще нет в Node.Js 16.13.1 ^[11], но в следующем релизе вероятно будет.

Мы попробовали собрать Node.Js с этим патчем, на RHEL 7 сразу это сделать не получилось — для новой версии Node.JS на Linux подняты минимальные требования к gcc до 8.3 ^[12]:

Поэтому на старых версиях Linux потребуется установить пакеты devtoolset-8 или обновить ОС.
Обновляемся, собираем Node.Js и в результате получаем:

Опции --concurrent-marking и --parallel-marking включены по умолчанию:

Garbage collector потребляет 2-3% вместо 13:

Event-loop latency значительно снизились:

Для сравнения — latency до применения патча:

Все пришло в норму.

В заключение хотим отметить, что мониторинг только общих метрик (CPU, памяти и т.п.) не выявил бы эту проблему. Нужно выполнять комплексный анализ, например, так как это делаем мы ^[5] для сервиса мониторинга и анализа логов PostgreSQL ^[2].

Спасибо Kilor ^[13] и andrydl ^[14] за помощь в подготовке статьи.