Node.js v8

В этой статье мы разберем особенности мониторинга многопоточного Node.JS приложения на примере нашего коллектора для сервиса мониторинга и анализа логов серверов PostgreSQL.


Для масштабирования коллектора мы используем многопроцессный подход, с одним управляющим и несколькими рабочими процессами, межпроцессное взаимодействие происходит только между рабочим и управляющим процессом.
Рабочие процессы выполняют одинаковые задачи сбор, обработка и запись логов с серверов PostgreSQL. При этом сбор и запись это по сути IO-задачи, в которых nodejs очень хороша. А вот обработка и парсинг планов запросов это довольно CPU-емкая задача, блокирующая event-loop. Поэтому такие задачи лучше выносить в отдельный воркер или пул воркеров, передавая им данные на обработку посредством обмена IPC-сообщениями.

Раньше, для задачи обработки и парсинга планов запросов мы использовали именно такой подход. Но у него есть недостаток большие объемы передаваемых данных по IPC могут привести к значительному увеличению затрат на сериализацию в JSON и обратно.

Например при передаче по IPC буфера, в которой содержится строка 'test' происходит передача строки:

'{"type":"Buffer","data":[116,101,115,116]}'

При большом количестве передаваемых данных накладные расходы могут стать такими:


Решением для нас стало использование worker_threads, появившихся в Node.JS 10.5.0, работающих в рамках одного процесса и позволяющих использовать новые методы коммуникации между потоками.
Архитектура изменилась:

А вместе с ней и подходы к мониторингу. Например, использование CPU внутри worker_thread традиционным способом измерить не получится.
Т.е. раньше, для каждого процесса-воркера, мы измеряли CPU-usage с помощью process.cpuUsage() и process.hrtime() примерно так:

let startCpuUsage = process.cpuUsage();let startTime = process.hrtime();let n = 1000;while (n--) Math.sin(n);let {user, system} = process.cpuUsage(startCpuUsage); // время в микросекундахlet time = process.hrtime(startTime); // наносекундыlet cpuUsage = 100 * 1000 * (user + system) / (time[0] * 1e9 + time[1]);

Но для процесса с worker_threads вызов process.cpuUsage() выдает процессорное время для всего процесса в целом, суммируя все его потоки. И такой же результат мы получим, если вызовем process.cpuUsage() изнутри worker_thread.
Почему так происходит?
Дело в то что process.cpuUsage() использует вызов uv_getrusage, а тот в ОС Linux выполняет системный вызов getrusage с параметром RUSAGE_SELF, т.е. возвращает статистику для вызывающего процесса как сумму по всем его потокам, при этом не важно из какого потока мы делаем этот вызов во всех потоках он будет возвращать одинаковые значения.

Как же получить CPU-usage для worker_threads и почему в Node.JS нет встроенных методов для профилирования CPU worker_threrads?
Здесь есть ответ разработчика worker_threads.
Предложено два варианта либо с помощью системного вызова gettid() получить tid для worker_thread и просматривать данные в /proc/${tid}, либо использовать getrusage() с параметром RUSAGE_THREAD, позволяющим получать статистику только для вызывающего потока.
Кстати, таким же образом можно получать метрики использования CPU и для основного потока процесса, без учета всех дополнительных потоков и worker_threads.

Итак, разобравшись с этим вопросом, мы стали искать готовые модули для мониторинга worker_threads, и не нашли Поэтому сделали свой , заодно добавив в него выдачу всех остальных метрик для мониторинга Node.JS приложения. Серверные метрики мы уже получаем с помощью своей системы сбора метрик .

Мониторинг CPU

Для анализа использования CPU мы берем метрики от воркеров и worker_threads, а также метрики общей загруженности CPU и в разрезе ядер:

• Для воркеров в целом:
  
  
  
  
• Для основных потоков воркеров:
  
  
  
  
• Для worker_threads (по первым из пула, но полезным будет и суммарный в разрезе воркера):
  
  
  
  
• Общая загрузка CPU на сервере:
  
  
  
  

С метриками CPU разобрались, а что насчет профайлинга worker_threads?
Проверим, запустив этот небольшой тест с параметром node --prof

В результате получили два isolate-* файла, для основного потока и для worker_thread.
Далее, с помощью node --prof-process <isolate_file> можем посмотреть нужный профайл.
Кстати, с опцией --no-logfile-per-isolate вместо нескольких isolate* файлов будет один v8.log с суммарным результатом по всем потокам, включая основной.

И еще используя опцию node --inspect или послав сигнал SIGUSR1 работающему процессу с целью снять CPU профайл в Chrome DevTools, мы увидим данные только по основному потоку.

Использование памяти

Также как и для CPU, снимая профайл в Chrome DevTools мы получим Heap snapshot только основного потока.
К счастью, с версии node 12.17.0 появилась возможность получить heap snapshot прямо из кода worker_threads с помощью вызова worker.getHeapSnapshot(), а с версии 11.13.0 также для основного потока вызовом v8.getHeapSnapshot()


Послав сигнал SIGUSR2 процессу, мы получим два heapsnapshot, которые затем можно проанализировать в Chrome DevTools:

• Основной процесс:
  
  
  
  
• worker_thread:
  
  
  
  

Какие метрики памяти интересны для анализа?
Мы используем те, что выдает process.memoryUsage() rss, heapTotal, heapUsed, external.
И также v8.getHeapSpaceStatistics(), с его помощью можно получить данные по сегментам Heap new_space, old_space, code_space, large_object_space.
rss всегда выдается для всего процесса, а остальные метрики в рамках вызывающего контекста.

• Суммарный по воркерам:
  
  
  
  
• По воркеру:
  
  
  
  
• По worker_threads:
  
  
  
  

Сборка мусора

Т.к. в каждом worker_thread запускается свой инстанс Node.JS с v8/libuv, то и GC у каждого тоже свой и мониторить их надо по отдельности.
Для мониторинга GC нам нужно получать данные об общей продолжительности сборки мусора, а также количество запусков и время выполнения каждого цикла.
Уже довольно давно, с версии 8.5.0, в Node.JS появился механизм PerformanceObserver, позволяющий кроме всего прочего получить всю необходимую информацию по циклам GC.


Этот метод работает как в основном потоке так и в worker_threads, для нашего коллектора мы получаем графики с метриками за секунду:

• По воркерам
  
  
  
  
• По worker_threads
  
  
  
  
• Общее время GC в разрезе воркеров
  
  
  
  
• Общее время GC в разрезе worker_threads
  
  
  
  

Event-loop latency

Для мониторинга задержек event-loop удобно использовать появившийся в версии 11.10.0 monitorEventLoopDelay тут можно получить не только среднее и предельные значения, но и различные перцентили.
Мы используем max, min, mean, и percentile(99):

• Суммарный по всем воркерам
  
  
  
  
• Суммарный по worker_threads
  
  
  
  
• По воркеру
  
  
  
  
• По worker_thread
  
  
  
  

Мониторинг пула worker_threads

Системные показатели работы пула уже приведены выше, а здесь поговорим о метриках производительности многопоточного приложения.
При старте каждый воркер коллектора запускает пул с одним worker_thread, который обрабатывает очередь поступающих планов запросов.
Дополнительные worker_thread запускаются при увеличении размера очереди и при нахождении задач в очереди дольше определенного времени. Также они автоматически завершаются после периода неактивности.

Важными метриками пула worker_thread являются размер очереди и количество работающих потоков:

• 
  
  

Кроме этого мы мониторим скорость и производительность worker_thread и воркеров в целом:

• Скорость обработки планов запросов:
  
  
  
  
• Производительность воркеров по количеству задач:
  
  
  
  
• Производительность воркеров по объему данных:
  
  
  
  
• Производительность worker_thread по количеству задач:
  
  
  
  
• Производительность worker_thread по объему данных:
  
  
  
  

Заключение

Мы рассмотрели особенности мониторинга многопоточного приложения Node.JS.
Для комплексного анализа работы приложения необходимо отслеживать массу показателей метрики по серверу в целом, использование приложением системных ресурсов, метрики среды выполнения, а также различные показатели самого приложения. В общем всего, что включает в себя APM.