Как отлаживать/анализировать чрезвычайно длинные паузы GC в Node.js/V8

Я пытаюсь проанализировать проблему памяти /GC в относительно сложном Node.js сервере приложении. Даже при очень умеренной нагрузке он становится невосприимчивым к заметным периодам, и эти паузы растут с течением времени. Выполнение с параметром --trace-gc показывает, что очень длительное время сбора мусора является вероятной причиной:

[4805]      537 ms: Mark-sweep 17.6 (46.4) -> 10.3 (47.4) MB, 20 ms [allocation failure] [GC in old space requested].
[4805]     1338 ms: Mark-sweep 31.3 (58.4) -> 19.2 (57.2) MB, 40 ms [allocation failure] [promotion limit reached].
[4805]     2662 ms: Mark-sweep 58.0 (79.2) -> 43.9 (85.2) MB, 109 ms [Runtime::PerformGC] [promotion limit reached].
[4805]     4014 ms: Mark-sweep 90.1 (111.5) -> 70.6 (113.9) MB, 114 ms [allocation failure] [promotion limit reached].
[4805]     7283 ms: Mark-sweep 129.7 (153.9) -> 112.0 (158.9) MB, 511 ms [allocation failure] [promotion limit reached].
[4805]    10979 ms: Mark-sweep 184.6 (210.9) -> 160.3 (212.9) MB, 422 ms [Runtime::PerformGC] [promotion limit reached].
[4805]  1146869 ms: Mark-sweep 243.8 (271.4) -> 191.6 (267.9) MB, 1856 ms [allocation failure] [promotion limit reached].
[4805]  1731440 ms: Mark-sweep 282.1 (307.4) -> 197.5 (298.9) MB, 1 / 11230 ms [allocation failure] [promotion limit reached].
[4805]  2024385 ms: Mark-sweep 291.0 (320.8) -> 197.3 (306.9) MB, 9076 ms [Runtime::PerformGC] [promotion limit reached].
[4805]  2623396 ms: Mark-sweep 290.9 (317.1) -> 196.9 (311.9) MB, 1 / 15401 ms [allocation failure] [promotion limit reached].
[4805]  3223769 ms: Mark-sweep 291.4 (323.6) -> 187.8 (318.9) MB, 1 / 13385 ms [allocation failure] [promotion limit reached].
[4805]  4225777 ms: Mark-sweep 280.1 (324.2) -> 190.6 (315.9) MB, 1 / 13266 ms [allocation failure] [promotion limit reached].
[4805]  4705442 ms: Mark-sweep 286.2 (321.4) -> 195.2 (314.9) MB, 1 / 17256 ms [Runtime::PerformGC] [promotion limit reached].
[4805]  5225595 ms: Mark-sweep 288.3 (324.0) -> 201.7 (316.9) MB, 1 / 22266 ms [Runtime::PerformGC] [promotion limit reached].
[4805]  6127372 ms: Mark-sweep 296.5 (324.6) -> 200.5 (316.9) MB, 1 / 28325 ms [allocation failure] [promotion limit reached].
[4805]  6523938 ms: Mark-sweep 297.8 (328.9) -> 198.8 (323.9) MB, 1 / 27213 ms [allocation failure] [promotion limit reached].
[4805]  7355394 ms: Mark-sweep 292.1 (330.7) -> 223.9 (322.9) MB, 60202 ms [allocation failure] [promotion limit reached].

Полный (--trace-gc-verbose) вывод можно найти здесь.

Эти журналы являются результатом запуска сервера со следующими параметрами:

--expose-gc --trace-gc --trace-gc-verbose --trace-gc-ignore-scavenger --max-old-space-size=1000

Чем дольше он работает, тем дольше паузы получаются (часто несколько минут), пока он не закроется полностью через пару часов. Доступная память никогда не заканчивается, и RSS даже не приближается к 1000-миллионному временному пределу, поэтому это не похоже на утечку. Мне кажется, что в коде может быть что-то довольно необычное, что очень затрудняет работу GC в приемлемых временных рамках.

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

В стороне, я бы очень признателен за ссылки на любую документацию, в которой объясняются термины/сообщения, используемые в отладочном выпуске GC (например, достигнутый предел продвижения) и номера, указанные там. У меня очень общее представление о том, как работает V8 GC (this), но большая часть этого вывода все еще находится вне меня.

В случае, если это имеет значение: он работает на Node.js v0.10.33 на сервере Ubuntu 14.04.

EDIT: Некоторое время назад мы перешли к io.js, где эта проблема просто больше не возникает (предположительно, из-за гораздо более поздней версии V8). Я никогда не нашел причину этой проблемы с Node v0.10, хотя, не говоря уже о исправлении.

Ответ 1

Можете ли вы воспроизвести проблему на одном node? Я думаю, что если бы я был в ситуации, я бы, вероятно, сделал следующее:

Напишите загрузчик, который позволяет мне реплицировать локальный экземпляр
Если нет, поместите экземпляр в prod, который получит подмножество трафика, и измените его, чтобы сделать ниже
Добавьте node-heapdump в свой источник, вызовите его с интервалом и экспортируйте результаты в json файл с N-минутными интервалами.
Потенциально, если вы работаете локально, вы также можете воспользоваться memwatch.
Подождите, пока начнется медленный GC.
Возьмите несколько кучи кучи в то время, когда вы знаете, что медленная GC началась.
Загрузите их в хром и проанализируйте их, используя три метода оснастки снимков (я полагаю, вы могли бы назвать это методом N снимка в нашем случае )

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

Доступная память никогда не заканчивается, и RSS даже не приближается к 1000-миллионному временному пределу, поэтому это не похоже на утечку. Мне кажется, что в коде может быть что-то довольно необычное, что очень затрудняет работу GC в приемлемых временных рамках.

Здесь вы можете искать длинные и круговые деревья. Но в конце концов, даже в этом случае вы должны быть в состоянии определить, что такое корень этого дерева, что в нем и экспериментировать с способами сокращения удаления.

Я также согласен с @dandavis и подозрительными закрытиями.

Ответ 2

Этот ответ может быть не таким конкретным, как хотелось бы, но я бы предложил посмотреть хороший пакет, чтобы часть Walmart hapi.js. Он отлично справляется с расширением регистрации за пределами --trace-gc. Это монитор процесса, который прослушивает одно или несколько из следующих событий:

ops - Производительность системы и процесса - процессор, память, диск и другие показатели.
response - Информация о входящих запросах и ответах. Это отображает либо событие "ответ", либо "хвост", испускаемое серверами hapi.
log - информация о протоколировании, не связанная с конкретным запросом, например системные ошибки, фоновая обработка, ошибки конфигурации и т.д. Карты для события "log", испускаемого серверами hapi.
error - запросить ответы, содержащие код состояния 500. Это отображает событие hapi с запросом-ошибкой.
request - Запросить информацию о регистрации. Это отображает событие hapi 'request', которое испускается через request.log().

Вам нужно будет использовать libary для Hapi, чтобы это работало, но это может стоить это временно для целей отладки. В общем, я настоятельно рекомендую Hapi для масштабирования приложений Node.js, ребята из Walmart с ним делали замечательные вещи за последний год.