Я пытаюсь проанализировать проблему памяти/GC в относительно сложном серверном приложении Node.js. Даже при очень умеренной нагрузке он становится невосприимчивым к заметным периодам, и эти паузы растут с течением времени. Запуск с параметром --trace-gc
показывает, что очень длительное время для сбора мусора является вероятной причиной:Как отлаживать/анализировать чрезвычайно длинные GC-паузы в Node.js/V8
[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
) выход может быть найден here.
Эти журналы являются результатом работы сервера со следующими параметрами:
--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, хотя, не говоря уже об исправлении.
RSS - это не то, сколько памяти используется, по крайней мере, не в указанном смысле, heapUsed ближе к тому, что вы хотите посмотреть. похоже, что «старые указатели» - это то место, где идет баран, поэтому я подозреваю, что закрытие случайно зашифровано, возможно, чрезмерно великодушно проходящий объект req/res. см. некоторые сведения о термине и в целом по адресу http://jayconrod.com/posts/55/a-tour-of-v8-garbage-collection – dandavis
Хорошая точка - графики для heapUsed и heapTotal следуют кривой RSS точно в моем мониторинге (хотя, по мере того, как я могу сказать, не происходит обмена). Спасибо за подсказку «старые указатели» - я буду внимательно изучать это. – d0gb3r7
Использовать прототипы и ООП, а не закрывать вложенные внутренние затворы, вложенные внутри закрытий ad infinitum – Esailija