如何在Node.js/V8中调试/分析极长的GC暂停

Question

我试图在一个相对复杂的Node.js服务器应用程序中分析内存/ GC问题.即使在非常适中的负载下,它也会在明显的时期内变得无法响应,并且随着时间的推移这些停顿会变得更长.使用--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可以在此处找到full()输出.

这些日志是使用以下参数运行服务器的结果:

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

它运行的时间越长,停顿时间越长(通常为几分钟),直到最后几小时后完全锁定.可用内存永远不会用完,RSS甚至没有接近1000mb旧空间限制,因此它似乎不是泄漏.在我看来,代码中可能存在一些相当不寻常的东西,这使得GC在可接受的时间范围内完成工作非常"困难".

我的问题是:我如何进一步分析这个问题,并缩小可能的原因？任何可以推荐的工具来帮助解决这样的问题？我本质上是在寻找一种更有效的方法,而不是天真地关闭和部分代码,这是非常麻烦和耗时的.

顺便说一句,我非常感谢任何文档的链接,这些文档解释了GC调试输出中使用的术语/消息(例如"达到促销限制")以及那里列出的数字.我对V8 GC的工作方式有了非常基本的了解(这有很大帮助),但大部分输出仍然超出了我的范围.

如果重要:这是在Ubuntu 14.04服务器上的Node.js v0.10.33上运行的.

编辑: 前一段时间我们转移到io.js,这个问题根本不再发生(可能是由于更新的V8版本).我从来没有找到Node v0.10这个问题的原因,更不用说修复了.

Answer 1

您是否能够在单个节点上重现该问题？我想如果我处于这种情况，我可能会做以下混合：

• 编写一个加载器，让我在本地实例上进行复制
• 如果没有，将一个实例放入 prod 中，它将接收流量的子集，并修改它以执行以下操作
• 将node-heapdump添加到您的源中，每隔一段时间调用它，并在 N 分钟的时间间隔内将结果导出到 json 文件。
• 潜在地，如果您在本地运行，您也可以利用memwatch。
• 等待慢速 GC 启动。
• 当您知道慢 GC 开始发生时，抓取一些堆转储。
• 将它们加载到 chrome 中并使用三快照技术分析它们（我想在我们的例子中你可以称之为 N 快照技术）

基本上，您将加载堆并开始查看它们以尝试了解什么类型的东西正在堆积，什么东西在保持它，结果您将了解为什么 GC 需要这么长时间。

可用内存永远不会耗尽，RSS 甚至没有接近 1000mb 的旧空间限制，因此它似乎不是泄漏。在我看来，代码中可能有一些相当不寻常的东西，这使得 GC 在可接受的时间范围内完成其工作非常“困难”。

在这里，您可能正在寻找长而圆形的保留树。但在一天结束时，即使是这种情况，您也应该能够确定那棵树的根是什么，里面有什么，并尝试减少删除的方法。

我也同意@dandavis 并怀疑关闭。