Трассировка сборки мусора

Это руководство пройдётся по основам трейсов сборки мусора (garbage collection).

К концу этого руководства вы сможете:

• Включать трейсы в вашем приложении на Node.js
• Интерпретировать трейсы
• Выявлять потенциальные проблемы с памятью в вашем приложении на Node.js

О том, как работает сборщик мусора, можно узнать многое, но если вы усвоите одну вещь — это то, что пока работает GC, ваш код не работает.

Возможно, вы захотите узнать, как часто и как долго работает сборка мусора, и каков её результат.

Для целей этого руководства мы используем такой скрипт:

// script.mjs

import os from 'node:os';

let len = 1_000_000;
const entries = new Set();

function addEntry() {
  const entry = {
    timestamp: Date.now(),
    memory: os.freemem(),
    totalMemory: os.totalmem(),
    uptime: os.uptime(),
  };

  entries.add(entry);
}

function summary() {
  console.log(`Total: ${entries.size} entries`);
}

// выполнение
(() => {
  while (len > 0) {
    addEntry();
    process.stdout.write(`~~> ${len} entries to record\r`);
    len--;
  }

  summary();
})();

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

Вы можете видеть трейсы сборки мусора в консольном выводе вашего процесса с помощью флага --trace-gc.

$ node --trace-gc script.mjs

Примечание: исходный код этого упражнения можно найти в репозитории Node.js Diagnostics.

Вывод должен быть примерно таким:

[39067:0x158008000]     2297 ms: Scavenge 117.5 (135.8) -> 102.2 (135.8) MB, 0.8 / 0.0 ms  (average mu = 0.994, current mu = 0.994) allocation failure
[39067:0x158008000]     2375 ms: Scavenge 120.0 (138.3) -> 104.7 (138.3) MB, 0.9 / 0.0 ms  (average mu = 0.994, current mu = 0.994) allocation failure
[39067:0x158008000]     2453 ms: Scavenge 122.4 (140.8) -> 107.1 (140.8) MB, 0.7 / 0.0 ms  (average mu = 0.994, current mu = 0.994) allocation failure
[39067:0x158008000]     2531 ms: Scavenge 124.9 (143.3) -> 109.6 (143.3) MB, 0.7 / 0.0 ms  (average mu = 0.994, current mu = 0.994) allocation failure
[39067:0x158008000]     2610 ms: Scavenge 127.1 (145.5) -> 111.8 (145.5) MB, 0.7 / 0.0 ms  (average mu = 0.994, current mu = 0.994) allocation failure
[39067:0x158008000]     2688 ms: Scavenge 129.6 (148.0) -> 114.2 (148.0) MB, 0.8 / 0.0 ms  (average mu = 0.994, current mu = 0.994) allocation failure
[39067:0x158008000]     2766 ms: Scavenge 132.0 (150.5) -> 116.7 (150.5) MB, 1.1 / 0.0 ms  (average mu = 0.994, current mu = 0.994) allocation failure
Total: 1000000 entries

Трудно читать? Пожалуй, стоит пройтись по нескольким понятиям и объяснить вывод флага --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

Мы сосредоточимся здесь только на двух событиях:

• Scavenge
• Mark-sweep

Куча делится на пространства (spaces). Среди них есть пространство под названием «new» (новое) и другое под названием «old» (старое).

👉 На самом деле структура кучи немного другая, но мы будем придерживаться упрощённой версии для этой статьи. Если хотите больше деталей, рекомендуем посмотреть этот доклад Питера Маршалла об Orinoco.

Scavenge — это название алгоритма, выполняющего сборку мусора в new space. New space — это место, где создаются объекты. New space спроектировано быть маленьким и быстрым для сборки мусора.

Представим сценарий Scavenge:

• мы выделили A, B, C и D.

  | A | B | C | D | <unallocated> |

• мы хотим выделить E
• места не хватает, память исчерпана
• тогда запускается (сборка) мусора
• «мёртвые» объекты собираются
• «живые» объекты остаются
• предположим, что B и D были мёртвыми

  | A | C | <unallocated> |

• теперь мы можем выделить E

  | A | C | E | <unallocated> |

v8 будет продвигать (promote) объекты, не собранные после двух операций Scavenge, в old space.

👉 Полный сценарий Scavenge

Mark-sweep используется для сбора объектов из old space. Old space — это место, где живут объекты, пережившие new space.

Этот алгоритм состоит из двух фаз:

• Mark (пометка): помечает всё ещё живые объекты чёрным, а остальные — белым.
• Sweep (зачистка): сканирует белые объекты и превращает их в свободные пространства.

👉 На самом деле шаги Mark и Sweep немного сложнее. Пожалуйста, прочитайте этот документ для деталей.

Теперь, если быстро вернуться к предыдущему окну терминала, вы увидите много событий Mark-sweep в консоли. Мы также видим, что объём собранной после события памяти незначителен.

Теперь мы эксперты в сборке мусора! Что можно вывести?

У нас, вероятно, утечка памяти! Но как в этом убедиться? (Напоминание: в этом примере это довольно очевидно, но как быть с реальным приложением?)

Но как нам увидеть контекст?

1. Предположим, мы наблюдаем, что old space непрерывно растёт.
2. Уменьшите --max-old-space-size, чтобы вся куча была ближе к лимиту
3. Запускайте программу, пока не упрётесь в out of memory.
4. Полученный лог покажет падающий контекст.
5. Если вы упираетесь в OOM, увеличьте размер кучи на ~10% и повторите несколько раз. Если наблюдается тот же паттерн, это указывает на утечку памяти.
6. Если OOM нет, зафиксируйте размер кучи на этом значении — плотно упакованная куча снижает потребление памяти и задержку вычислений.

Например, попробуйте запустить script.mjs следующей командой:

node --trace-gc --max-old-space-size=50 script.mjs

Вы должны получить OOM:

[...]
<--- Last few GCs --->
[40928:0x148008000]      509 ms: Mark-sweep 46.8 (65.8) -> 40.6 (77.3) MB, 6.4 / 0.0 ms  (+ 1.4 ms in 11 steps since start of marking, biggest step 0.2 ms, walltime since start of marking 24 ms) (average mu = 0.977, current mu = 0.977) finalize incrementa[40928:0x148008000]      768 ms: Mark-sweep 56.3 (77.3) -> 47.1 (83.0) MB, 35.9 / 0.0 ms  (average mu = 0.927, current mu = 0.861) allocation failure scavenge might not succeed
<--- JS stacktrace --->
FATAL ERROR: Reached heap limit Allocation failed - JavaScript heap out of memory [...]

Теперь попробуйте для 100 МБ:

node --trace-gc --max-old-space-size=100 script.mjs

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

<--- Last few GCs --->
[40977:0x128008000]     2066 ms: Mark-sweep (reduce) 99.6 (102.5) -> 99.6 (102.5) MB, 46.7 / 0.0 ms  (+ 0.0 ms in 0 steps since start of marking, biggest step 0.0 ms, walltime since start of marking 47 ms) (average mu = 0.154, current mu = 0.155) allocati[40977:0x128008000]     2123 ms: Mark-sweep (reduce) 99.6 (102.5) -> 99.6 (102.5) MB, 47.7 / 0.0 ms  (+ 0.0 ms in 0 steps since start of marking, biggest step 0.0 ms, walltime since start of marking 48 ms) (average mu = 0.165, current mu = 0.175) allocati

Примечание: в контексте реального приложения найти утекший объект в коде может быть непросто. Heap snapshot может помочь его найти. Загляните в руководство, посвящённое heap snapshot

Как определить, происходит ли слишком много сборок мусора или создают ли они накладные расходы?

1. Просмотрите данные трейса, а именно время между последовательными сборками.
2. Просмотрите данные трейса, конкретно время, потраченное в GC.
3. Если время между двумя GC меньше времени, потраченного в GC, приложение сильно «голодает».
4. Если и время между двумя GC, и время, потраченное в GC, очень велики, вероятно, приложение может обойтись меньшей кучей.
5. Если время между двумя GC намного больше времени, потраченного в GC, приложение относительно здорово.

Теперь давайте устраним утечку. Вместо того чтобы использовать объект для хранения наших записей, мы могли бы использовать файл.

Немного изменим наш скрипт:

// script-fix.mjs
import fs from 'node:fs/promises';
import os from 'node:os';

let len = 1_000_000;
const fileName = `entries-${Date.now()}`;

async function addEntry() {
  const entry = {
    timestamp: Date.now(),
    memory: os.freemem(),
    totalMemory: os.totalmem(),
    uptime: os.uptime(),
  };
  await fs.appendFile(fileName, JSON.stringify(entry) + '\n');
}

async function summary() {
  const stats = await fs.lstat(fileName);
  console.log(`File size ${stats.size} bytes`);
}

// выполнение
(async () => {
  await fs.writeFile(fileName, '----START---\n');
  while (len > 0) {
    await addEntry();
    process.stdout.write(`~~> ${len} entries to record\r`);
    len--;
  }

  await summary();
})();

Использование Set для хранения данных вовсе не плохая практика; вам просто стоит следить за потреблением памяти вашей программой.

Примечание: исходный код этого упражнения можно найти в репозитории Node.js Diagnostics.

Теперь давайте выполним этот скрипт.

node --trace-gc script-fix.mjs

Вы должны заметить две вещи:

• События Mark-sweep появляются реже
• потребление памяти не превышает 25 МБ против более чем 130 МБ у первого скрипта.

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

Вывод: как думаете, можно ли улучшить этот скрипт? Вы, вероятно, видите, что новая версия скрипта медленная. Что, если снова использовать Set и записывать его содержимое в файл только тогда, когда память достигает определённого размера?

API getheapstatistics может вам помочь.

Возможно, вы захотите не получать трейсы за всё время жизни процесса. В этом случае установите флаг изнутри процесса. Модуль v8 предоставляет API, чтобы выставлять флаги на лету.

import v8 from 'v8';

// включаем trace-gc
v8.setFlagsFromString('--trace-gc');

// выключаем trace-gc
v8.setFlagsFromString('--notrace-gc');

В Node.js можно использовать performance hooks, чтобы трассировать сборку мусора.

const { PerformanceObserver } = require('node:perf_hooks');

// Создаём performance observer
const obs = new PerformanceObserver(list => {
  const entry = list.getEntries()[0];
  /*
  Запись — это экземпляр PerformanceEntry, содержащий
  метрики одного события сборки мусора.
  Например:
  PerformanceEntry {
    name: 'gc',
    entryType: 'gc',
    startTime: 2820.567669,
    duration: 1.315709,
    kind: 1
  }
  */
});

// Подписываемся на уведомления о GC
obs.observe({ entryTypes: ['gc'] });

// Останавливаем подписку
obs.disconnect();

Вы можете получить статистику GC как PerformanceEntry из колбэка в PerformanceObserver.

Например:

{
  "name": "gc",
  "entryType": "gc",
  "startTime": 2820.567669,
  "duration": 1.315709,
  "kind": 1
}

Для дополнительной информации можно обратиться к документации о performance hooks.