Процесс, который продолжал умирать

В этой статье я изложил суть своего выступления, которое состоялось в рамках проводимой нашей компанией образовательной программы «Lunch n' Learn».

Если вас просто интересует, как искать утечки памяти в Node, переходите сразу к Части 2 (но тогда вы упустите всю невероятную предысторию).

Это рассказ об умершем процессе и о наших злоключениях в попытке найти его убийцу с целью призвать негодяя к правосудию. Если говорить точнее, то этот процесс продолжал умирать циклически, но такая картина нарушает проводимую мной аналогию, поэтому попрошу вас не придавать этому большого значения. Наша история начинается с периодического возникновения ошибки 502 Bad Gateway — загадки, которую предстояло разрешить.

Сразу оговорюсь, что с целью защиты невиновных имена участников и места событий были изменены.

Часть 1: обнаружение

Это была дождливая городская ночь, освещаемая мерцанием неоновых вывесок, напоминавших несбывшиеся мечты. Ко мне в кабинет вошёл Чарли, SRE-инженер, обслуживавший крупный краудфандинговый ресурс. Его бледное лицо и покрасневшие глаза говорили о том, что Чарли не спал уже несколько дней. «У меня проблема, детектив, — сказал он осипшим голосом, — ошибки 502 Bad Gateway. Они буквально разрывают нашу систему на части».

Я откинулся в кресле и выпустил в потолок клубы дыма: «502, говоришь? Возможно, проблема с вышестоящим сервером, балансировщиком нагрузки или с самой сетью. Ты точно проверил всех типичных подозреваемых?»

Он кивнул, барабаня пальцами по столу: «Я проверил всё. Такое ощущение, что в машину вселился бес».

Я окинул его взглядом и оценил степень охватившего парня отчаяния. «Хорошо, Чарли, я возьму это дело. Только учти, в ходе расследования может вскрыться правда, которая тебе не понравится. Возможно, в твоих владениях завёлся убийца».

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

Сообщения 502 Bad Gateway довольно тревожны. Каждое такое говорит о том, что кто-то при попытке войти на ваш сайт получил сообщение об ошибке. И хотя фактический процент ошибок по-прежнему оставался относительно невысок, они могли представлять разницу между теми, кто достиг своей цели, и теми, кто столкнулся со сбоем. А работа в сфере краудфандинга подразумевает высокую ответственность перед пользователями.

▍ Расследование

Как и любой хороший детектив, я начал со сбора улик. У нас все приложения завязаны с New Relic ^[1] и Sumologic ^[2], но конкретно в этом случае для формирования картины проблемы больше подходит последний инструмент. С его помощью мне удалось выяснить следующее:

• История: ошибки начали возникать как минимум три месяца назад.
• Частота: происходят каждые 3-4 часа.
• Область: ограничена приложением Next.js.
• Влияние: достаточно серьёзное, чтобы вызывать тревожные оповещения от системы PagerDuty.

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

▍ PM2 — вероятный виновник?

Первым подозреваемым был PM2, менеджер процессов демонов Node. У него была возможность маскировать проблемы так, что всё до поры до времени выглядело нормально. Он был слишком гладок и отполирован, словно мошенник в шёлковом костюме.

Я решил навестить PM2. Как и ожидалось, его логи представляли полный беспорядок. Повсюду сплошные ложные зацепки и тупиковые цепочки. Но, в конце концов, моё внимание привлекла одна запись. Она указывала на процесс, который исчерпывал свой лимит памяти. Это говорило о том, что Next.js использовал её слишком много. Курок нажимал именно PM2, перезапуская процессы и вызывая те самые ошибки 502.

Я позвонил Чарли: «Не уверен, но мне кажется, я нашёл убийцу. Его зовут PM2».

PM2 ^[3] (Process Manager 2) — это менеджер процессов активных приложений Node.js. Он позволяет поддерживать безостановочную работу приложений, перезапускать их без даунтайма, а также упрощает выполнение типичных задач по администрированию. PM2 может автоматически перезапускать приложения при их сбое или, как в нашем случае, при исчерпании ими памяти.

Выяснив, что убийцей процесса является PM2, мы скорректировали параметр ^[4] max_memory_restart в конфигурации менеджера, надеясь, что проблема заключалась в недостатке ресурсов. Результат должен был проясниться в течение одного или двух дней. Мы скрестили пальцы.

Часть 2: охота на утечку

Однажды ночью мне позвонил Чарли. Его голос дрожал и был пронизан отчаянием: «Ваше исправление не сработало, детектив. Ошибки 502 по-прежнему здесь. PM2 убивает серверы налево и направо».

Я вздохнул, потирая виски. «Хорошо, Чарли. Похоже, проблему не решить простым исправлением конфига. В вашем приложении Next.js происходит утечка памяти, и для обнаружения реальной причины придётся серьёзно покопаться».

Чарли сильно негодовал: «Что же нам делать дальше?»

«Нужно заняться изучением кода, — ответил я, — отыскать утечки и залатать эти дыры. Это будет небыстро, Чарли. Поиск утечек памяти порой сравним с поиском иголки в стоге сена».

Он тяжело вздохнул: «Хорошо, детектив, тогда приступим. Нужно как можно скорее прекратить страдания пользователей».

Дождь превратился в неистовый ливень, совпадавший с воцарившейся в моём офисе атмосферой. Я понимал, что это только начало. Отслеживание утечки памяти представляло непростую задачу, которая требовала задействования всех моих навыков. Но для меня это было не впервой. Так или иначе, но я найду виновника. В этом городе по-другому нельзя, либо ты просто потонешь в пучине собственных ошибок.

Увеличение доступных приложению ресурсов не исправило проблему. Мы выяснили, что процесс сервера просто потреблял всё больше и больше памяти, в конечном итоге требуя перезапуска. Это определённо была утечка памяти.

▍ Обнаружение утечек памяти

Отладка утечек памяти зачастую оказывается трудным и длительным процессом. К счастью, на сегодня нам доступны прекрасные инструменты. Мне требовалось проделать следующие шаги:

1. Запустить приложение и начать отладку.
2. Сделать снимок кучи.
3. Протестировать приложение под нагрузкой.
4. Сделать ещё один снимок.
5. Сравнить полученные снимки.

В качестве первой попытки инспектирования я выполнил простую команду NODE_OPTIONS='--inspect' yarn start. Однако, получив несколько озадачивающих снимков, я понял, что инспектировал не тот процесс. Параметры NODE_OPTIONS применялись только к процессу yarn, а не внутреннему серверу Next.js, который yarn вызывал. Мне удалось определить ID процесса (pid) сервера Next.js с помощью команды ps aux | grep node.

Чтобы получить возможность отладки работающего процесса Node, достаточно выполнить команду kill -USR1 {pid}, которая настроит процесс на прослушивание отладчика.

Откройте панель отладки Chrome, перейдя на страницу chrome://inspect. Откройте вкладку «Memory» и кликните «Take Snapshot».

Теперь, когда у нас есть основа, нужно пронаблюдать утечку в действии. Я отправил на сервер несколько сотен запросов с помощью следующего скрипта, размещённого на GitHub ^[5]:

# Простейший скрипт для нагрузочного тестирования. Вызывает указанный url заданное число раз.
# пример: ./loadtest.sh 25 "http://localhost:3000/my-url"
max="$1"
date
echo "url: $2
rate: $max calls / second"
START=$(date +%s);

get () {
  curl -s -v "$1" 2>&1 | tr 'rn' '\n' | awk -v date="$(date +'%r')" '{print $0"n-----", date}' >> /tmp/perf-test.log
}

while true
do
  echo $(($(date +%s) - START)) | awk '{print int($1/60)":"int($1%60)}'
  sleep 1

  for i in `seq 1 $max`
  do
    get $2 &
  done
done

На этот раз кликните круглую кнопку «Record» в верхней левой части окна.

Осталось только сравнить снимки и посмотреть, есть ли в них что-нибудь подозрительное. Вы должны заметить выпадающий список с надписью «Summary». Измените её на «Compare», затем отсортируйте таблицу по «Size Delta». Если повезёт, то в итоге проблема может оказаться прямо у вас перед носом.

Заключительная часть: выявление виновника

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

Чарли внимательно смотрел: «Не вижу».

«Это Moment.js. Он истекает памятью, как резаная свинья».

На этот раз в голосе Чарли послышалось облегчение с оттенком накопленной усталости: «И что нам теперь делать?»

«В этом пазле недостаёт одного элемента. Мы знаем, что убийцей является Moment.js, но ещё нужно найти орудие убийства».

▍ Moment.js — главный подозреваемый

После подробного изучения мы выяснили, что утечку памяти создавали вызовы moment.updateLocale. Определив, что проблема заключалась не в нашем коде, мы заглянули в репозиторий Moment.js и выяснили, что там уже есть решение ^[6]. Обновление Moment.js с версии 2.24.0 на 2.29.4 полностью устранило баг с утечкой памяти, и ошибки 502 исчезли.

Эпилог

После того, как Чарли ушёл, я выглянул в окно. Дождь, наконец, прекратился, и сквозь облака пробивались первые лучи рассвета. Дело было закрыто, но будут и другие. В этом городе всегда есть проблемы, ожидающие своего решения. Но сейчас я мог передохнуть и вдоволь насладиться спокойствием, пока не надвинулся очередной шторм.