26 октября 2021 года вышел новый релиз Node.JS 16.13.0 который стал Active LTS.
Как мы переводили на него наш сервис мониторинга и анализа логов PostgreSQL и с какими проблемами столкнулись — в статье ниже.
Переключаться между версиями Node.Js удобно с помощью утилиты nvm.
Запускаем тестовые коллекторы нашей системы под Node.Js v16 и внимательно смотрим за изменениями в работе приложения. Мы отслеживаем довольно много метрик — по серверу в целом, использование приложением системных ресурсов, метрики среды выполнения, а также различные показатели самого приложения. Так что какие-либо изменения не останутся незамеченными. Кстати, подробности о методике мониторинга приложения можно узнать в этой статье.
Итак, приложение работает, но в сравнении с Node.Js v14 при той же нагрузке мы наблюдаем увеличение потребления процессорного времени и времени работы GC.
И при этом сильное ухудшение по метрикам event-loop latency:
![](https://habrastorage.org/webt/cb/wa/40/cbwa40rkxra5smymcccfogfpgue.png)
Как узнать причину увеличения latency? Выполняем профайлинг приложения и обнаруживаем, что наиболее вероятной причиной увеличения latency является GC:
![](https://habrastorage.org/webt/e2/-n/wk/e2-nwkbtmlebqmgkuadw5y2e4jo.png)
Пробуем запуститься на одном из ранних релизов v16 — результат примерно тот же.
После отката обратно на Node.Js v14 значения GC и latency возвращаются в норму:
![](https://habrastorage.org/webt/cj/u5/ya/cju5yaecd96yhpncqcqbmvrxxxo.png)
Логично было предположить, что причиной увеличения event-loop latency в v16 являются какие-то изменения в самой Node.JS, а именно в работе GC.
Смотрим еще раз Release Notes, но никаких упоминаний об изменениях в GC не находим.
Проверяем также изменения в релизах V8, т.к. в Node.Js v16 перешли на новую ветку V8 version 9, но и там ничего.
Что еще могло поменяться, чтобы так сильно замедлить работу GC?
На всякий случай проверяем настройки по умолчанию для V8:
и видим очень странные изменения:
![](https://habrastorage.org/webt/is/fa/p0/isfap0poyvmdegpremchnvwfbbc.png)
т.е. обе оптимизации нового сборщика мусора Orinoco — concurrent_marking и parallel_marking, которые были включены по умолчанию в Node.Js начиная с v10, оказались выключены в v16!
Об этих оптимизациях GC можно почитать в этой статье, но если кратко — в прежних реализациях GC работал по принципу «stop-the-world»:
![](https://habrastorage.org/webt/rt/j_/3b/rtj_3bbd6bidypwcurqhwj3ntqg.png)
новый GC выносит часть операций по сборке мусора в пул рабочих потоков, снижая время выполнения операций GC в основном потоке и тем самым снижая его задержки:
![](https://habrastorage.org/webt/ks/rc/cm/ksrccmpdxaxmwtswym2kkjrnaxg.png)
GC в основном потоке разгружается на 65-70%:
![](https://habrastorage.org/webt/su/d1/cc/sud1ccu6fy9116edxqlu5nsbhyk.png)
Т.е. отключение этих оптимизаций приводит к увеличению времени GC в основном потоке и как следствие к увеличению event-loop latency. Как раз наш случай!
Пробуем их включить:
И снова проблема — node выдает фатальную ошибку с генерацией core dump:
![](https://habrastorage.org/webt/ef/aw/nb/efawnbszdkaqrcdixx1yj-dfgfs.png)
Порывшись в исходниках, нашли что включить эти опции возможно только если они были включены на этапе компиляции:
![](https://habrastorage.org/webt/tx/l7/rs/txl7rsxjzjzegxykqn-8kidic5g.png)
Причину мы установили, но для исправления обращаемся в сообщество и составляем Bug report. Ошибку оперативно исправили и подготовили небольшой patch, которого еще нет в Node.Js 16.13.1, но в следующем релизе вероятно будет.
Мы попробовали собрать Node.Js с этим патчем, на RHEL 7 сразу это сделать не получилось — для новой версии Node.JS на Linux подняты минимальные требования к gcc до 8.3:
![](https://habrastorage.org/webt/4f/si/nu/4fsinuvjl-g8jvnugtuqswbc_za.png)
Поэтому на старых версиях Linux потребуется установить пакеты devtoolset-8 или обновить ОС.
Обновляемся, собираем Node.Js и в результате получаем:
Опции --concurrent-marking и --parallel-marking включены по умолчанию:
![](https://habrastorage.org/webt/ee/3f/26/ee3f26qg_ymrf7yhzibgiabgnwg.png)
Garbage collector потребляет 2-3% вместо 13:
![](https://habrastorage.org/webt/r7/nd/a1/r7nda1knkyv3znlqpywck_qg06s.png)
Event-loop latency значительно снизились:
![](https://habrastorage.org/webt/y1/ps/iq/y1psiqltcgkkwhvjk_hypgd-evw.png)
Для сравнения — latency до применения патча:
![](https://habrastorage.org/webt/xj/0k/ni/xj0kniqy1uhg9cvmkol0ez3eckc.png)
Все пришло в норму.
В заключение хотим отметить, что мониторинг только общих метрик (CPU, памяти и т.п.) не выявил бы эту проблему. Нужно выполнять комплексный анализ, например, так как это делаем мы для сервиса мониторинга и анализа логов PostgreSQL.
Спасибо Kilor и andrydl за помощь в подготовке статьи.
Как мы переводили на него наш сервис мониторинга и анализа логов PostgreSQL и с какими проблемами столкнулись — в статье ниже.
![](https://habrastorage.org/webt/qj/2c/yd/qj2cydetffi3era8uhj5ky3mjjo.png)
Переключаться между версиями Node.Js удобно с помощью утилиты nvm.
nvm install 16.13.0
Запускаем тестовые коллекторы нашей системы под Node.Js v16 и внимательно смотрим за изменениями в работе приложения. Мы отслеживаем довольно много метрик — по серверу в целом, использование приложением системных ресурсов, метрики среды выполнения, а также различные показатели самого приложения. Так что какие-либо изменения не останутся незамеченными. Кстати, подробности о методике мониторинга приложения можно узнать в этой статье.
Итак, приложение работает, но в сравнении с Node.Js v14 при той же нагрузке мы наблюдаем увеличение потребления процессорного времени и времени работы GC.
И при этом сильное ухудшение по метрикам event-loop latency:
![](https://habrastorage.org/webt/cb/wa/40/cbwa40rkxra5smymcccfogfpgue.png)
Как узнать причину увеличения latency? Выполняем профайлинг приложения и обнаруживаем, что наиболее вероятной причиной увеличения latency является GC:
![](https://habrastorage.org/webt/e2/-n/wk/e2-nwkbtmlebqmgkuadw5y2e4jo.png)
Пробуем запуститься на одном из ранних релизов v16 — результат примерно тот же.
После отката обратно на Node.Js v14 значения GC и latency возвращаются в норму:
![](https://habrastorage.org/webt/cj/u5/ya/cju5yaecd96yhpncqcqbmvrxxxo.png)
Логично было предположить, что причиной увеличения event-loop latency в v16 являются какие-то изменения в самой Node.JS, а именно в работе GC.
Смотрим еще раз Release Notes, но никаких упоминаний об изменениях в GC не находим.
Проверяем также изменения в релизах V8, т.к. в Node.Js v16 перешли на новую ветку V8 version 9, но и там ничего.
Что еще могло поменяться, чтобы так сильно замедлить работу GC?
На всякий случай проверяем настройки по умолчанию для V8:
node --v8-options
и видим очень странные изменения:
![](https://habrastorage.org/webt/is/fa/p0/isfap0poyvmdegpremchnvwfbbc.png)
т.е. обе оптимизации нового сборщика мусора Orinoco — concurrent_marking и parallel_marking, которые были включены по умолчанию в Node.Js начиная с v10, оказались выключены в v16!
Об этих оптимизациях GC можно почитать в этой статье, но если кратко — в прежних реализациях GC работал по принципу «stop-the-world»:
![](https://habrastorage.org/webt/rt/j_/3b/rtj_3bbd6bidypwcurqhwj3ntqg.png)
новый GC выносит часть операций по сборке мусора в пул рабочих потоков, снижая время выполнения операций GC в основном потоке и тем самым снижая его задержки:
![](https://habrastorage.org/webt/ks/rc/cm/ksrccmpdxaxmwtswym2kkjrnaxg.png)
GC в основном потоке разгружается на 65-70%:
![](https://habrastorage.org/webt/su/d1/cc/sud1ccu6fy9116edxqlu5nsbhyk.png)
Т.е. отключение этих оптимизаций приводит к увеличению времени GC в основном потоке и как следствие к увеличению event-loop latency. Как раз наш случай!
Пробуем их включить:
node --concurrent-marking --parallel-marking
И снова проблема — node выдает фатальную ошибку с генерацией core dump:
![](https://habrastorage.org/webt/ef/aw/nb/efawnbszdkaqrcdixx1yj-dfgfs.png)
Порывшись в исходниках, нашли что включить эти опции возможно только если они были включены на этапе компиляции:
![](https://habrastorage.org/webt/tx/l7/rs/txl7rsxjzjzegxykqn-8kidic5g.png)
Причину мы установили, но для исправления обращаемся в сообщество и составляем Bug report. Ошибку оперативно исправили и подготовили небольшой patch, которого еще нет в Node.Js 16.13.1, но в следующем релизе вероятно будет.
Мы попробовали собрать Node.Js с этим патчем, на RHEL 7 сразу это сделать не получилось — для новой версии Node.JS на Linux подняты минимальные требования к gcc до 8.3:
![](https://habrastorage.org/webt/4f/si/nu/4fsinuvjl-g8jvnugtuqswbc_za.png)
Поэтому на старых версиях Linux потребуется установить пакеты devtoolset-8 или обновить ОС.
Обновляемся, собираем Node.Js и в результате получаем:
Опции --concurrent-marking и --parallel-marking включены по умолчанию:
![](https://habrastorage.org/webt/ee/3f/26/ee3f26qg_ymrf7yhzibgiabgnwg.png)
Garbage collector потребляет 2-3% вместо 13:
![](https://habrastorage.org/webt/r7/nd/a1/r7nda1knkyv3znlqpywck_qg06s.png)
Event-loop latency значительно снизились:
![](https://habrastorage.org/webt/y1/ps/iq/y1psiqltcgkkwhvjk_hypgd-evw.png)
Для сравнения — latency до применения патча:
![](https://habrastorage.org/webt/xj/0k/ni/xj0kniqy1uhg9cvmkol0ez3eckc.png)
Все пришло в норму.
В заключение хотим отметить, что мониторинг только общих метрик (CPU, памяти и т.п.) не выявил бы эту проблему. Нужно выполнять комплексный анализ, например, так как это делаем мы для сервиса мониторинга и анализа логов PostgreSQL.
Спасибо Kilor и andrydl за помощь в подготовке статьи.
Комментарии (4)
black1277
09.12.2021 01:57Не сразу понял что такое GK, пока не дочитал до Garbage collector(почти в самом конце).
vitkarpov
Любопытно, что мейнтерены пропустили это. В ишьюсах была какая-то переписка на этот счет, в смысле, почему так вышло, что пропустили флаги?
MGorkov Автор
Было обсуждение https://github.com/nodejs/node/issues/41012
Похоже была уверенность что изменения флагов в V8 автоматом подтянутся в nodejs, но нет...
vitkarpov
Спасибо.