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`);
}

// execution
(() => {
  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 与 --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
值含义
13973运行进程的 PID
0x110008000Isolate,即 JavaScript 堆实例
44 ms自进程启动以来的毫秒数
ScavengeGC 类型或阶段
2.4GC 前已用堆内存,MB
(3.2)GC 前堆总量,MB
2.0GC 后已用堆内存,MB
(4.2)GC 后堆总量,MB
0.5 / 0.0 ms (average mu = 1.000, current mu = 1.000)与 GC 耗时有关的信息,单位毫秒
allocation failure触发 GC 的原因

本文只关注两种事件:Scavenge 和 Mark-sweep。

堆被划分为多个空间,其中包括“新生代空间”和“老年代空间”。实际结构更复杂,本文使用简化模型。更多细节可观看 Peter Marshall 关于 Orinoco 的演讲。

Scavenge

Scavenge 是在新生代执行垃圾回收的算法。对象在新生代创建,这个空间设计得较小,以便快速回收。

设想已经分配对象 A、B、C、D:

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

现在需要分配 E,但剩余空间不足,于是触发垃圾回收。死亡对象被回收,存活对象留下。假设 B 和 D 已死亡:

| A | C | <unallocated> |

现在就可以分配 E:

| A | C | E | <unallocated> |

经过两次 Scavenge 仍未被回收的对象,会被 V8 提升到老年代。完整过程见 Scavenge 场景说明。

Mark-sweep

Mark-sweep 用于回收老年代中的对象,老年代保存的是在新生代中存活下来的对象。它由两个阶段组成:

  • Mark,标记:把仍存活的对象标为黑色,其他对象标为白色。
  • Sweep,清扫:扫描白色对象,将其占用空间转为空闲空间。
标记与清扫垃圾回收算法动画
标记与清扫垃圾回收算法动画

实际的标记和清扫过程更加复杂,详情见原文链接的相关文档。

实际使用 –trace-gc

内存泄漏

回到前面的终端,会看到大量 Mark-sweep 事件,而且每次回收之后释放的内存非常少。由此可能推断存在内存泄漏,但如何确认?本例很明显,在真实应用中还需要定位分配上下文。

获取异常分配的上下文

假设观察到老年代持续增长:

  1. 减小 --max-old-space-size,让堆总量更接近限制。
  2. 运行程序,直到发生内存不足。生成的日志会显示失败上下文。
  3. 发生 OOM 后,将堆大小增加约 10%,重复几次。如果反复出现相同模式,就表明可能存在泄漏。
  4. 如果不再发生 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 MB:

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

注意:真实应用中,可能很难在代码里找到泄漏对象。堆快照可以提供帮助,参见 堆快照专门指南。

运行缓慢

如何判断垃圾回收过于频繁,或造成了过多开销?观察连续两次回收之间的时间,以及 GC 自身的耗时:

  • 两次 GC 间隔小于 GC 耗时,说明应用严重缺乏执行时间。
  • GC 间隔与 GC 耗时都很长,应用可能适合使用更小的堆。
  • 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`);
}

// execution
(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 MB,而最初的脚本超过 130 MB。新版本对内存施加的压力更小,因此这样的结果很合理。

进一步思考:新脚本明显较慢,还能怎样改进?可以再次使用 Set 缓冲数据,但只在内存达到特定大小时写入文件。getheapstatistics API 可能派上用场。

补充:以编程方式跟踪垃圾回收

使用 v8 模块

如果不希望记录进程整个生命周期中的跟踪信息,可以在进程内部动态设置标志。v8 模块提供了相应 API:

import v8 from 'v8';

// enabling trace-gc
v8.setFlagsFromString('--trace-gc');

// disabling trace-gc
v8.setFlagsFromString('--notrace-gc');

使用性能钩子

Node.js 还可以通过 performance hooks 跟踪垃圾回收。

CommonJS:

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

// Create a performance observer
const obs = new PerformanceObserver(list => {
  const entry = list.getEntries()[0];
  /*
  The entry is an instance of PerformanceEntry containing
  metrics of a single garbage collection event.
  For example:
  PerformanceEntry {
    name: 'gc',
    entryType: 'gc',
    startTime: 2820.567669,
    duration: 1.315709,
    kind: 1
  }
  */
});

// Subscribe to notifications of GCs
obs.observe({ entryTypes: ['gc'] });

// Stop subscription
obs.disconnect();

ES Modules:

import { PerformanceObserver } from 'node:perf_hooks';

// Create a performance observer
const obs = new PerformanceObserver(list => {
  const entry = list.getEntries()[0];
  /*
  The entry is an instance of PerformanceEntry containing
  metrics of a single garbage collection event.
  For example:
  PerformanceEntry {
    name: 'gc',
    entryType: 'gc',
    startTime: 2820.567669,
    duration: 1.315709,
    kind: 1
  }
  */
});

// Subscribe to notifications of GCs
obs.observe({ entryTypes: ['gc'] });

// Stop subscription
obs.disconnect();

解读性能钩子跟踪

在 PerformanceObserver 回调中,可以通过 PerformanceEntry 获取 GC 统计,例如:

{
  "name": "gc",
  "entryType": "gc",
  "startTime": 2820.567669,
  "duration": 1.315709,
  "kind": 1
}
属性含义
name性能条目名称
entryType性能条目类型
startTime标识条目开始时刻的高精度毫秒时间戳
duration该条目持续的总毫秒数
kind发生的垃圾回收操作类型
flags关于 GC 的附加信息

更多信息见 性能钩子文档。


原文:Node.js:Tracing garbage collection。作者/维护者:Node.js 文档贡献者。本文为原文的中文译文;代码保留原文内容。

© 版权声明
THE END
喜欢就支持一下吧
点赞0 分享
评论 抢沙发

请登录后发表评论

    暂无评论内容