追踪垃圾回收

本指南将贯穿所有关于垃圾回收跟踪机制的基础部分。

当你完成本章节阅读之后,你将会了解:

  • 如何在 Node.js 应用程序中启用跟踪
  • 解析跟踪信息
  • 识别可能潜在 Node.js 应用程序内与内存相关的问题

垃圾回收是如何工作的,实在有太多的东西需要学习。但有一点必须清楚:那便是当 GC 运行 的时候,你的代码是不工作的。

或许你想知道垃圾回收运行的频率,以及需要运行多久,以及结果是什么。

脚本构建

为本章讲解之目的,我们将使用以下脚本:

// script.mjs
import os from '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 症状分析的练习中找到相关源码。

运行之后,输出如下效果:

[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运行中进程的编号
0x110008000独立内存地址 (JS 堆实例)
44 ms自开始运行的时间(毫秒)
Scavenge类型 / GC 阶段
2.4GC 运行前占有内存(MiB)
(3.2)GC 运行前总占有内存(MiB)
2.0GC 运行后占有内存(MiB)
(4.2)GC 运行后总占有内存(MiB)
0.5 / 0.0 ms (average mu = 1.000, current mu = 1.000)GC 花费的时间(ms)
allocation failureGC 具体原因

在此我们只需关注两件事:

  • Scavenge
  • 标记—清除

内存堆被分割成了若干 区间 块。在这些区间块里边,我们有“新”区间,还有“旧”区间。

👉 实际上,堆的结构本文表述有差异,但我们为了简化期间而故意为之。 如果你想了解更多的细节,我们建议你看 talk of Peter Marshall

Scavenge

“Scavenge” 是一种算法的名称,它将执行垃圾回收,并把无用空间转化成可用的新空间。 新空间就是新对象存放的地方。新空间被设计成又小又快的样子,以便于垃圾回收。

我们假设以下使用了 Scavenge 的场景:

  • 我们分配了 A, B, CD 四块内存变量
    | A | B | C | D | <unallocated> |
    
  • 我们继续想要分配 E
  • 可用空间不够,内存耗尽了
  • 然后垃圾回收机制被触发
  • 无用的对象被回收了
  • 可用对象仍然得到保留
  • 假设 BD 是无用对象,那么回收后如下所示
    | A | C | <unallocated> |
    
  • 现在我们就可以为对象 E 分配空间了
    | A | C | E | <unallocated> |
    

v8 会提升对象,因此对无用空间进行两次 Scavenge 操作之后不再进行垃圾收集。

👉 参考这里完整的 Scavenge 情形

标记—清除

“标记—清除”用于从旧空间收集对象,“旧空间”指新空间中幸存下来的物体居住的地方。

该算法分成两个阶段:

  • 标记: 把“可用对象”(活对象)标记成黑,其余则为白。
  • 清除: 扫描收集所有白色区域,并回收它们转换成为可用空间。

👉 实际上,“标记—清除”仍然有一些东西值得说道。请阅读此文档以便于了解更多详情。

--trace-gc 参数实际作用

内存泄露

现在如果你快速回头看前一个中断控制台窗口,你会发现许多 Mark-sweep 事件的输出。 与此同时我们也观察到在这事件变得不再重要的时候,相关内存被收集了。

现在我们是垃圾收集方面的专家了!我们可以得出什么推论?

我们或许有内存泄露问题,但我们如何确定呢(友情提示:这个示例中很明显,但对于一个现实世界里 的程序呢)?

同时我们又如何观察上下文?

如何捕获糟糕的内存分配上下文?

  1. 假设我们观察到旧内存持续不断地增长
  2. 反复使用 --max-old-space-size,直到堆内存接近于极限值
  3. 运行程序,直到触发“内存耗尽”的提示。
  4. 这将记录下内存获取失败的上下文信息
  5. 如果触发了“内存耗尽”,不断提高堆的大小(每次10%),尝试数次之后如仍观察到此现象的发生,这意味着内存存在泄露。
  6. 如果无法触发“内存耗尽”,保持你的堆栈大小固定成那个值——因为一个被压缩的堆减少了内存空间量,以及计算过程中的延迟。

打个比方。请使用如下的命令运行 script.mjs

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

你应该会遇到如下信息的“内存耗尽”:

[...]
<--- 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 [...]

现在请调整堆大小至 100mb:

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

请注意:在实际应用程序的上下文中,通过代码寻找泄露对象非常困难。不过“堆捕获”可以帮助到你,详情请看堆捕获相关指南

速度慢

如何确定你的内存回收次数太多,亦或者导致性能损耗?

  1. 观察跟踪的数据,尤其是在连续不断的内存回收之间的时间。
  2. 观察跟踪的数据,尤其是在 GC 发生前后的时间。
  3. 如果两次 GC 间的时间小于执行一次 GC 所用时间,说明该程序内存严重不足。
  4. 如果两次 GC 间的时间和执行一次 GC 所用时间都异常高,说明该程序使用的内存小了些。
  5. 如果两次 GC 间的时间远大于执行一次 GC 所用时间,程序就相对来说很健康。

如何修复内存泄露

现在让我们修复这个问题吧。我们将用一个文件,而不是一个对象来存储相关信息。

我们对脚本做一点如下的修改:

// script-fix.mjs
import os from 'os';
import fs from 'fs/promises';
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 症状分析的练习中找到相关源码。

现在则是我们执行该脚本的时候:

node --trace-gc script-fix.mjs

你应该观察到两件事情:

  • “标记—清除” 事件频率减少
  • 与之前(第一个脚本)相比内存占用超过 130MB 而言,本次内存相关记录显示不超过 25MB。

相对于第一个脚本而言,新版本的脚本在内存上施加的压力更小,自然更容易甄别出。

拓展: 你如何考虑提升这个脚本?或许你已经注意到这个新版本的脚本太慢了。 如果我们再次使用 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 里你还可以使用 性能钩子 来追踪垃圾回收信息。

const { PerformanceObserver } = require('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 一样的信息。

举个例子:

PerformanceEntry {
  name: 'gc',
  entryType: 'gc',
  startTime: 2820.567669,
  duration: 1.315709,
  kind: 1
}
属性名解释
name性能名称
entryType性能类型
startTime回收开始时间(单位:高精度毫秒时间戳)
duration本次回收总时间(单位:毫秒)
kind本次垃圾收集的类型
flags垃圾回收的其余信息

预知更多详情,请参考性能钩子的相关文档

回到页顶