Прежде чем перейти к статье, хочу вам представить, экономическую онлайн игру Brave Knights, в которой вы можете играть и зарабатывать. Регистируйтесь, играйте и зарабатывайте!
26 октября 2021 года вышел новый релиз Node.JS 16.13.0 который стал Active LTS.
Как мы переводили на него наш сервис мониторинга и анализа логов PostgreSQL и с какими проблемами столкнулись — в статье ниже.
Переключаться между версиями Node.Js удобно с помощью утилиты nvm.
Запускаем тестовые коллекторы нашей системы под 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:
и видим очень странные изменения:
т.е. обе оптимизации нового сборщика мусора Orinoco — concurrent_marking и parallel_marking, которые были включены по умолчанию в Node.Js начиная с v10, оказались выключены в v16!
Об этих оптимизациях GC можно почитать в этой статье, но если кратко — в прежних реализациях GC работал по принципу «stop-the-world»:
новый GC выносит часть операций по сборке мусора в пул рабочих потоков, снижая время выполнения операций GC в основном потоке и тем самым снижая его задержки:
GC в основном потоке разгружается на 65-70%:
Т.е. отключение этих оптимизаций приводит к увеличению времени GC в основном потоке и как следствие к увеличению event-loop latency. Как раз наш случай!
Пробуем их включить:
И снова проблема — 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 за помощь в подготовке статьи.
Как мы переводили на него наш сервис мониторинга и анализа логов 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 за помощь в подготовке статьи.
