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


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

nvm install 16.13.0

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

Итак, приложение работает, но в сравнении с 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, но никаких упоминаний об изменениях в GC не находим.
Проверяем также изменения в релизах V8, т.к. в Node.Js v16 перешли на новую ветку V8 version 9, но и там ничего.

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

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

node --v8-options

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



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

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



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



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


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

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

node --concurrent-marking --parallel-marking

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


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


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

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



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

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


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


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


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


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

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

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