Всем привет! Меня зовут Артём и я backend-разработчик компании SimbirSoft. На протяжении восьми лет я работаю на Node.js. Сегодня хочу поделиться опытом поиска утечек памяти при gRPC-вызовах в Node.js + Nest.js. В частности, речь пойдет об отладке утечки памяти при взаимодействии между микросервисами. Статья будет полезна backend-разработчикам, которые работают с Node.js и gRPC.

Несмотря на то, что в интернете много материалов про поиск утечек памяти, все реальные примеры сводятся к устранению искусственного глобального массива. Поэтому я решил рассказать о своем опыте.

В числе задач, которые ставил перед нами клиент, были поиск и устранение утечки памяти при работе микросервисов. Задача была открыта уже давно, но не было четкого понимания, как ее решать. Судя по описанию, было несколько API, при вызове которых отделы DevOps и QA наблюдали сильный рост памяти при мониторинге системы и тестировании соответственно. В дополнении к REST API присутствовали gRPC-методы. 

gRPC — RPC-фреймворк от Google, который активно используется для взаимодействия между микросервисами. В отличие от других RPC-фреймворков, gRPC использует Protocol Buffers и HTTP 2 для передачи данных.

В данной работе я привожу результаты отладки и блоки кода из воспроизведенного примера. Суть проблемы и решения сохранена.

Собираем улики: проверяем код на правила работы с памятью

После сбора информации я выяснил, что утечка памяти может наблюдаться где угодно в разные моменты времени, то есть четкого понимания, где наблюдалась проблема, не было. Перезапуститься от переполнения памяти мог любой из микросервисов в разные моменты времени. Происходило это редко, и заходя немного вперед, стоит сказать, что перезапускались самые «востребованные» микросервисы.

Я начал исследования с API, указанных в задаче. Удивительно, но достаточно быстро получилось воспроизвести рост памяти, несмотря на то, что архитектура микросервисная и для работы нужного сервиса требуется еще около 4-5 других, некоторые из которых нужно запустить локально в debug-режиме, а для некоторых хватало проброса портов на dev-стенд.

В API было несколько запросов к БД, при отладке которых намеков на утечку памяти не было. Остались вызовы gRPC-методов других микросервисов. Условно обозначим, что микросервис А посредством gRPC-протокола вызывает API микросервиса Б. При оставленных в коде лишь gRPC-запросах и остальном закомменченном коде мониторинг памяти в k8s показывал прирост памяти примерно 0.1 МБ на 1 запрос. Как только размер кучи памяти (heap of memory) достигал ~1000 МБ, микросервис на dev-стенде перезапускался.

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

• Сборщик мусора в Node.js

В Node.js реализован свой сборщик мусора, который отвечает за высвобождение памяти. Он работает в контексте V8 и предоставляет возможность автоматической сборки мусора. Если происходит утечка памяти, значит сборщик мусора по каким-либо причинам не освобождает память от отработанных данных. 

Сборщик мусора знает все о ссылках объектов на другие объекты, определяет, когда объекты больше не требуются для работы приложения или становятся недостижимыми из-за изменения структуры ссылок в приложении и, как следствие, удаляет их из памяти.

На данном изображении отображены объекты, связанные ссылками и без них. Таким образом объекты без ссылок будут удалены из памяти сборщиком мусора.

• Глобальные переменные

Так как на глобальные переменные ссылается корневой объект (window/this), то такие объекты не будут очищены сборщиком мусора. В контексте серверного исполнения на Node.js глобальный корневой  объект — global.

• Множественные ссылки

Утечки памяти также могут наблюдаться из-за ситуаций, когда на один объект ссылается множество других объектов и одна из ссылок становится «висячей», или из-за ошибочных ссылок.

• Замыкания

Из-за запоминания окружающего контекста, ссылки на крупные объекты в замыканиях могут порождать утечки памяти.

• Таймеры и события

При использовании setTimeout, setInterval, Observers также могут наблюдаться утечки памяти, в случаях, когда ссылки на объекты кучи хранятся в их обратных вызовах.

В результате ревью кода я не выявил вышеописанных причин, поэтому принял решение изучить основные методы отладки утечек памяти в Node.js, провести, так сказать, лит. обзор.

Переходим к отладке и исправлению

Вводные данные и обзор инструментов отладки

Для начала я решил изучить такие инструменты, как: --trace-gc, process.memoryUsage(), DevTools-based debugger,  heap snapshots и их профилирование через DevTools.

trace-gc

Начал я с trace-gc, который предоставляет информацию о работе сборщика мусора. Приложение, запущенное с флагом –trace-gc, выводит в консоль информацию следующего вида:

[13973:0x110008000] 44 ms: Scavenge 2.4 (3.2) -> 2.0 (4.2) MB, 0.5 / 0.0 ms  (average mu = 1.000, current mu = 1.000) allocation failure
или:
[23521:0x10268b000]  120 ms: Mark-sweep 100.7 (122.7) -> 100.6 (122.7) MB, 0.15 / 0.0 ms  (average mu = 0.132, current mu = 0.137) deserialize GC in old space requested

Описание:

Scavenge <heapUsed before> (<heapTotal before>) -> <heapUsed after> (<heapTotal after>) MB, <how long the GC pause was>

Сама по себе куча состоит из двух основных сегментов: нового и старого пространства памяти. Новое пространство — это место, где происходят новые распределения памяти: здесь быстро собирается мусор, размер которого составляет ~1-8 МБ. Объекты, живущие в новом пространстве, называются Young generation.

Старое пространство (Old generation), куда переходят объекты, пережившие сборку мусора в новом пространстве, — называется старым поколением. Распределение памяти в старом пространстве происходит быстро, однако сбор наоборот дольше, поэтому оно выполняется нечасто.

Scavenge — это алгоритм, который будет выполнять сбор мусора в новом пространстве.

Mark-Sweep используется для сбора объектов из старого пространства. Этот алгоритм состоит из двух этапов:

• Mark: будет отмечать еще живые объекты как черные, а другие как белые.

• Sweep: сканирование белых объектов и преобразование их в свободное пространство.

Также существует еще одна фаза, о которой редко говорят — Compact.

Данная фаза оптимизирует пространство после очищения памяти.

process.memoryUsage()

Функция, которая позволяет получить данные о текущем состоянии кучи памяти. Пример:

{
  		rss: 4935680,
  		heapTotal: 1826816,
  		heapUsed: 650472,
  		external: 49879,
  		arrayBuffers: 9386
}

• rss — Resident Set Size — это объем места, занимаемого в основной памяти устройства (то есть подмножество общей выделенной памяти) для процесса, включая все объекты и код C++ и JavaScript

• heapTotal и heapUsed — объем кучи всего и объем занятого пространства памяти, соответственно

• external относится к использованию памяти объектами C++, связанными с объектами JavaScript, управляемыми V8

• arrayBuffers относится к памяти, выделенной для ArrayBuffers и SharedArrayBuffers, включая все буферы Node.js

DevTools-based debugger

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

Начиная с версии 6.3, Node.js предоставляет встроенный отладчик на основе DevTools, который является более современным инструментом, чем Node Inspector. Встроенный отладчик разработан непосредственно командой V8/Chromium и предоставляет некоторые расширенные функции (например, длинную/асинхронную трассировку стека), которые слишком сложно реализовать в Node Inspector.

Шаги отладки через DevTools-based debugger:

1. Запустить приложение с флагом --inspect-brk:

node --inspect-brk dist/main.js

2. Открыть Chrome->DevTools

3. В левом верхнем углу консоли отладчика появится значок инспектора

4. При клике на значок откроется окно инспектора со списком подключений

В данном окне в списке подключений видно только что запущенное мной, с портом 9229:

5. Во вкладке Console видно всё, что выводит Node.js приложение

6. Исходный код и дебаггер находятся во вкладке Sources

7. Для профилирования памяти вкладка Memory. На данной странице присутствуют все функции из вкладки DevTools->Memory — получить текущее состояние кучи памяти (Take snapshot), таймлайн выделения памяти (Allocation instrumentation on timeline), загрузка файла состояния памяти (Load).

DevTools-based debugger это мощный инструмент отладки, но чаще всего для этих целей достаточно IDE, из-за наличия плагинов, возможности редактировать и сохранять код.

Heap Snapshots

Это снепшоты (файлы с зафиксированным состоянием) кучи памяти, в которых содержится информация об объектах и ссылках. Их можно получить несколькими способами: 

• через инспектора,

• через внешний сигнал и флаг командной строки,

• через вызов writeHeapSnapshot внутри процесса,

• через протокол инспектора.

Опишем первые три метода, два из которых очень похожи, так как последний метод сложнее для понимания и настройки.

1. Как было описано в разделе про DevTools-based debugger, получить состояние памяти можно во вкладке Memory, запустив приложение с соответствующим флагом и перейдя в инструменты разработчика:

2. Второй метод подразумевает запуск приложения со специальным флагом (--heapsnapshot-signal):

	node --heapsnapshot-signal=SIGUSR2 index.js

и состояние памяти будет создавать в момент отправки заданного сигнала нашему приложению через терминал:

	kill -SIGUSR2 <node_id>

Полученный файл (обычно в корне проекта) открывается через инструменты разработчика:

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

	import * as v8 from 'v8';
process.on('SIGUSR1', () => {
 		const fileName = v8.writeHeapSnapshot();
  		console.log(`Created heapdump file: ${fileName}`);
});

Также отправить сигнал приложению через терминал:

		kill -SIGUSR1 <node_id>

И открыть полученный файл в инструментах разработчика.

Пошаговое решение

Убедиться в том, что куча памяти растет, а сборщик мусора при этом срабатывает, но чистит не все, мне помогли данные из process.memoryUsage() и –trace-gc. 

Далее нужно было понять, с чего начать отлаживать код. Для этого я добавил функцию получения состояния памяти (третий способ получения состояния памяти).

После получения файлов состояния памяти, я открывал их через инструменты разработчика Chrome DevTools->Memory.

Шаг 1: убедиться в том, что куча памяти растет при gRPC-запросах

Для очереди gRPC-запросов я написал bash-скрипт с использованием grpcurl, который делает n-ое количество gRPC-запросов к микросервису А (с заданным таймаутом между ними), который, в свою очередь, на каждый входящий запрос делает по одному gRPC-запросу в микросервис Б. Потенциально проблема возникала при gRPC-вызовах именно между микросервисами, а не между клиентом и микросервисом.

Код bash-скрипта для очереди запросов:

#!/bin/bash

server_address="localhost"
server_port="5001"

service="client.ClientService"
method="MakeRequest"
proto_path="/Users/artem/Work/grpc/grpc-client/src/client"
proto_file="client.proto"

count=100

for ((i = 0; i < $count; i++))
do
    grpcurl -import-path $proto_path -proto $proto_file -d '{"id": 1}' -plaintext $server_address:$server_port $service/$method
    sleep 1
done

В данном примере никаких ответов от микросервиса не ожидается — в ответ идет дублирование входящих данных. Здесь я выбрал очередь, состоящую из 100 запросов, потому что экспериментальным путем выявил, при таком количестве запросов уже заметна утечка памяти.

В результате получил данные о выделенной памяти до запуска bash-скрипта:

	{
  		rss: 134955008,
  		heapTotal: 15400960,
  	heapUsed: 13430536,
  	external: 2502618,
  	arrayBuffers: 17177
}

и после:

	{
      		rss: 79298560,
      		heapTotal: 18546688,
      		heapUsed: 16630736,
      		external: 2526203,
      		arrayBuffers: 17585
}

Если обратить внимание на heapUsed, то видно, что объем использованной памяти увеличился с 13430536 по 16630736, то есть на ~ 3.2МБ.

Значения –trace-gc на старте приложения:

	[51622:0x160008000]    33258 ms: Scavenge 14.0 (14.9) -> 13.3 (15.9) MB, 2.62 / 0.08 ms  (average mu = 0.997, current mu = 0.008) task;

и после окончания работы bash-скрипта:

	[51622:0x160008000]    132428 ms: Scavenge 16.4 (17.4) -> 15.8 (17.7) MB, 2.58 / 0.04 ms  (average mu = 0.997, current mu = 0.008) task;

В приведенных данных также виден прирост использования памяти с 13.3МБ до 15.8МБ, то есть ~2.5МБ.

Таким образом, с помощью –trace-gc и process.memoryUsage() я обнаружил рост использования памяти.

Шаг 2: получение состояния памяти до очереди запросов и после и их сравнение

После выявления факта утечки памяти при вызове gRPC-метода следующим шагом нужно было локализовать проблему — понять, на каком участке кода происходит утечка и, как следствие, провести ревью этого участка кода и затем отладить.

1. В проект добавил функцию создания файла состояния памяти writeHeapSnapshot() (третий вариант получения Heap snapshot).

2. После старта микросервисов сделал 1 gRPC-вызов, чтобы все объекты (в том числе служебные) прогрузились в память.

3. Создал снепшот состояния памяти до очереди запросов — kill -SIGUSR1 <node_id>

4. Вызвал скрипт очереди запросов.

5. Создал второй снепшот состояния памяти после очереди запросов.

После очереди gRPC-запросов, состоящих из 100 запросов с таймаутом в 1 секунду, я получил два состояния кучи памяти (сравнение кучи памяти до очереди запросов и после):

Как видно на изображении выше, используемая память увеличилась на 2.6МБ, а также появилось множество новых объектов (колонка Delta), относительно первого состояния памяти. Появились объекты, которые создавались на каждый сделанный gRPC-запрос. Среди них потенциально могут быть объекты, которые не может собрать сборщик мусора, потому что после завершения запросов, память должна очищаться от данных для работы с ними. 

Описание колонок Heap Snapshot

• Construct отображает тип конструктора объекта в памяти.

• New и Deleted отражают количество созданных и удаленных объектов в памяти относительно двух снепшотов. 

• Delta отображает разницу в количестве объектов в памяти между снепшотов. Значение может быть отрицательным и положительным, что означает количество добавленных или удаленных объектов соответственно.

• Alloc. Size, Freed Size и Size Delta — объем памяти, выделенной конструктору, объем памяти, освобожденной после удаления объектов и разница в объеме занимаемой памяти между двумя снепшотами.

Просматривая объекты и ссылки, которые добавлялись на каждый запрос, в одном из наборов объектов я увидел адрес другого микросервиса (Б), в который как раз и уходил запрос из API (А), что являлось триггером увеличения использования памяти. Это в очередной раз увеличивало вероятность того, что стоит искать утечку именно в коде, связанном с gRPC-вызовами из микросервиса А в микросервис Б.

Может и не страшно, ведь сборщик мусора почистит. А если нет? Новый замер спустя несколько минут показал, что количество удаленных объектов не увеличилось и как минимум не очистились объекты, которые связаны с подключением к микросервису Б. Значения в колонке Delta не уменьшились, следовательно объекты так и не очистились из памяти.

После дальнейшей отладки и обсуждений задачи с командой на дейли, выяснилось, что у нас используется самописная обертка над библиотекой для gRPC-вызовов. В вызове методов есть дополнительная функциональность, в которой по-прежнему не оказалось ни глобальных переменных, ни closure, ни timeouts, которые бы приводили к таким утечкам.

Шаг 3: отладка обертки над gRPC вызовами

Внутри самой обертки gRPC-запросы делает сторонняя библиотека grpc-js. Исследовав issue этой библиотеки на github, я увидел, что подобные проблемы встречают и другие разработчики:

https://github.com/grpc/grpc-node/issues/2436
https://github.com/grpc/grpc-node/issues/2448
https://github.com/grpc/grpc-node/issues/1085

Решив, что есть вероятность очередной утечки, я поспешил поделиться информацией с разработчиками библиотеки, чтобы получить от них внятный ответ. Как минимум станет ясно, находится ли проблема на стороне этой библиотеки или на стороне клиента.

Создал issue на github по проблеме утечки памяти, где выложил всю информацию со скриншотами:

https://github.com/grpc/grpc-node/issues/2629

После недолгой переписки с разработчиком и прикладывания скриншотов выяснилось, что у нас не закрываются каналы (channels) после запросов (это уже и так было понятно). Но как решить данную проблему? Переделывать код или менять библиотеку было бы трудоемко — около 10 микросервисов, которые связаны между собой, при всем этом есть еще куча боевых задач с дедлайнами.

После обсуждений с разработчиком и замеров через heap snapshots выяснилось, что каналы создаются в одной из опциональных функций callInvocationTransformer. Разработчик библиотеки не рекомендовал использовать такой подход, так как достаточно создать клиент для подключения, и он уже будет иметь один канал. Получается, что в моем случае нет причин для создания каналов на каждый запрос. Вот пример кода, который демонстрирует реализацию обертки над gRPC-запросами и ее использование, в подходе, который приводил к созданиям каналов:

AppService.ts

import { Injectable } from '@nestjs/common';
import { Channel, ChannelCredentials, Client, credentials } from '@grpc/grpc-js';

@Injectable()
export class AppService {
 public client: Client;

 clientInit(microServiceAddress: string, creds: ChannelCredentials): void {
   this.client = new Client(microServiceAddress, creds, {
callInvocationTransformer: this.callTransformer 
});
 }

 private callTransformer(props: any): any {
   const options = {...};	
   props.channel = new Channel(`localhost:5000`, credentials.createInsecure(), options);

Использование AppService в контроллере AppController.ts:

import { Controller, Inject, OnModuleInit } from '@nestjs/common';
import { ClientGrpc, GrpcMethod } from '@nestjs/microservices';
import { Id } from './server/interfaces/Id.interface';
import { Observable } from 'rxjs';
import { ChannelCredentials, ClientUnaryCall, credentials, Metadata, ServerUnaryCall } from '@grpc/grpc-js';
import { AppService } from './app.service';

import { deserialize, serialize } from 'v8';
import * as process from 'process';

interface ServerService {
  makeRequest(data: Id): Observable<Id>;
}

@Controller()
export class AppController implements OnModuleInit {
  constructor(@Inject('SERVER_PACKAGE') private readonly client: ClientGrpc, private appService: AppService) {
  }

  onModuleInit() {
    let creds: ChannelCredentials = credentials.createInsecure();
    this.appService.clientInit('localhost:5000', creds);
  }

  @GrpcMethod('ClientService', 'MakeRequest')
  requestGrpc(data: Id, metadata: Metadata, call: ServerUnaryCall<any, any>): ClientUnaryCall {
    return this.appService.client.makeUnaryRequest<Id, Id>('/server.ServerService/MakeRequest', serialize, deserialize, data, (err, val: Id): Id => {
      if (err) {
        throw new Error();
      }
      return val;
    });
  }
}

Шаг 4: исправление логики работы обертки над gRPC-вызовами

В соответствии с документацией по Nest.js, для создания клиента без дополнительных оберток и вызов gRPC-метода достаточно сделать так:

constructor(@Inject('SERVER_PACKAGE') private readonly client: ClientGrpc) {}

onModuleInit() {
 	this.serverService = this.client.getService<ServerService>('ServerService');
}

@GrpcMethod('ClientService', 'MakeRequest')
  requestGrpc(data: Id, metadata: Metadata, call: ServerUnaryCall<any, any>): ClientUnaryCall {
 	return this.serverService.makeRequest({ id: 1 });
}

В моем случае при использовании библиотеки grpc-js и самописной обертки для нее исправление ошибки заключалось в удалении функции callTransformer и передачи дополнительных опций напрямую в инициализацию клиента:

import { Injectable } from '@nestjs/common';
import { Channel, ChannelCredentials, Client, credentials } from '@grpc/grpc-js';

@Injectable()
export class AppService {
  public client: Client;
  private microServiceAddress: string;
  private creds: ChannelCredentials;

  clientInit(microServiceAddress: string, creds: ChannelCredentials, options: any): void {
    this.microServiceAddress = microServiceAddress;
    this.creds = creds;
    this.client = new Client(microServiceAddress, creds, options)
  }
}

Данная обертка была сделана для того, чтобы можно было добавить дополнительную логику обработки запросов при вызове gRCP-методов, которую в данном примере можно опустить, но был выбран не верный подход с созданием клиента и каналов — передача коллбэка для опции callInvocationTransformer и создание канала в этом коллбэке.

Шаг 5: анализ результатов после исправления

Далее проведены те же самые тесты (очередь из 100 gRPC-запросов) с использованием process.memoryUsage, –trace-gc и получением файлов состояния кучи памяти (heap snapshots) до очереди запросов и после:

process.memoryUsage() до очереди запросов:

	{
  rss: 154304512,
  heapTotal: 15925248,
  heapUsed: 13960312,
  external: 2502891,
  arrayBuffers: 17205
}

process.memoryUsage() до после очереди запросов:

{
  rss: 110870528,
  heapTotal: 16973824,
  heapUsed: 14501456,
  external: 2502674,
  arrayBuffers: 17217
}

Если обратить внимание на heapUsed, то видно, что объем использованной памяти увеличился — с 13960312 по 14501456, то есть на ~ 0.54МБ.

–trace-gc до очереди запросов:

[56226:0x128008000]   173114 ms: Mark-Compact (reduce) 13.7 (16.4) -> 13.7 (16.2) MB, 10.38 / 0.00 ms  (average mu = 1.000, current mu = 0.004) heap profiler; GC in old space requested

В приведенных данных прирост использования памяти составляет ~0.6МБ.

На данном рисунке видно, что увеличение памяти снизилось (не стоит забывать и о служебных объектах), отсутствуют объекты, связанные с запросами и вообще отсутствуют объекты, число которых было бы равно числу запросов из очереди  (100), как в примерах до исправления.

Вывод

Если сравнить последние результаты, с данными до исправления обертки для работы с запросами, то мы видим:

• по данным heapUsed (из функции process.memoryUsage()), объем использованной памяти уменьшился с 3.2МБ до 0.54МБ

• по данным –trace-gc, объем использованной памяти уменьшился с 2.5МБ до 0.6МБ

• по данным из сравнительного анализа heap snapshots, в памяти не появляются объекты, связанные с запросами

В результате получилось решить проблему с утечкой памяти при gRPC-вызовах между микросервисами. После мониторинга памяти, не выявлено перезагрузок микросервисов (как это было до исправлений) и неожиданного увеличения памяти. Метод отладки утечки памяти с помощью таких инструментов как –trace-gc, process.memoryUsage, heap snapshots с отладкой через DevTools, позволяет зафиксировать утечку памяти и предоставляет дальнейшую помощь по поиску объектов, которые занимают выделяемую память.

Полезные ссылки

1. https://betterstack.com/community/guides/scaling-nodejs/high-performance-nodejs/nodejs-memory-leaks/

2. https://blog.appsignal.com/2022/09/28/minimize-heap-allocations-in-nodejs.html

3. https://github.com/grpc/grpc-node/issues/2448

4. https://github.com/grpc/grpc-node/issues/2402

5. https://github.com/grpc/grpc-node/issues/2003

6. https://github.com/grpc/grpc-node/issues/2436

7. https://www.toptal.com/nodejs/debugging-memory-leaks-node-js-applications

8. https://sematext.com/blog/nodejs-memory-leaks/

9. https://www.useanvil.com/blog/engineering/isolating-memory-leak-in-node/

10. https://stackoverflow.com/questions/12023359/what-do-the-return-values-of-node-js-process-memoryusage-stand-for/38049633#38049633

11. https://www.nearform.com/insights/tracking-memory-allocation-node-js/

12. https://groups.google.com/g/nodejs/c/gITsLR7Zkew?pli=1

13. https://nodejs.org/en/learn/diagnostics/memory/using-gc-traces

14. https://blog.risingstack.com/node-js-at-scale-node-js-garbage-collection/

15. https://blog.risingstack.com/finding-a-memory-leak-in-node-js/

16. https://medium.com/@casperle13/memory-leaks-in-nodejs-application-66cc13c1babd

17. https://medium.com/voodoo-engineering/nodejs-internals-v8-garbage-collector-a6eca82540ec

Спасибо за внимание!

Больше авторских материалов для Backend-разработчиков от моих коллег читайте в соцсетях SimbirSoft – ВКонтакте и Telegram.