如何 debug/analyze Node.js/V8 中超长的 GC 暂停
How to debug/analyze extremely long GC pauses in Node.js/V8
我正在尝试分析相对复杂的 Node.js 服务器应用程序中的 memory/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) 输出 here。
这些日志是 运行 服务器使用以下参数的结果：
--expose-gc --trace-gc --trace-gc-verbose --trace-gc-ignore-scavenger --max-old-space-size=1000
它运行的时间越长，暂停的时间就越长（通常是几分钟），直到它最终在几个小时后完全锁定。可用内存永远不会用完，RSS 甚至没有接近 1000mb 的旧 space 限制，所以它似乎不是泄漏。在我看来，代码中可能有些不寻常的地方，这使得 GC 在可接受的时间范围内完成工作变得非常 "difficult"。
我的问题是：如何进一步分析这个问题，并缩小可能的原因？有什么值得推荐的工具可以帮助解决此类问题吗？我本质上是在寻找一种比天真地关闭和打开部分代码更有效的方法，这非常麻烦和耗时。
顺便说一句，我将非常感谢任何解释 GC 调试输出中使用的 terms/messages（例如 "promotion limit reached"）以及其中列出的数字的文档的链接。我对 V8 GC 的工作原理有非常基本的了解（this 帮助很大），但大部分输出仍然超出我的理解范围。
以防万一：这是 运行 Node.js v0.10.33 Ubuntu 14.04 服务器上的 运行。
编辑：
不久前，我们转到 io.js，这个问题不再发生（可能是由于更新的 V8 版本）。不过，我从未在 Node v0.10 中找到此问题的原因，更不用说修复了。
这个答案可能不像您希望的那样具体，但我建议您查看 good package that's part of Walmart's hapi.js 框架。它在将日志记录扩展到 --trace-gc 之外做得很好。它是一个进程监视器，用于侦听以下一个或多个事件：
ops - 系统和进程性能 - CPU、内存、磁盘和其他指标。response - 有关传入请求和响应的信息。这映射到从 hapi 服务器发出的 "response" 或 "tail" 事件。log - 未绑定到特定请求的日志信息，例如系统错误、后台处理、配置错误等。映射到从 hapi 服务器发出的 "log" 事件。error - 请求状态代码为 500 的响应。这映射到 "request-error" hapi 事件。request - 请求日志信息。这映射到通过 request.log().
你必须引入 Hapi 库才能工作，但为了调试的目的暂时这样做可能是值得的。总的来说，我强烈推荐 Hapi 来扩展 Node.js 应用程序，沃尔玛的员工在过去一年里用它做了很多令人惊奇的事情。
您能否在单个节点上重现该问题？我想如果我处于这种情况，我可能会混合执行以下操作：
- 编写一个加载程序，让我在本地实例上进行复制
- 如果没有，将一个实例放入将接收一部分流量的 prod 中，并修改它以执行以下操作
- 将 node-heapdump 添加到您的源中，每隔一段时间调用一次，然后每隔 N 分钟将结果导出到 json 文件。
- 如果您 运行 在本地，您可能还可以利用 memwatch.
- 等待慢速 GC 启动。
- 在您知道缓慢的 GC 开始发生时抓取一些堆转储。
- 将它们加载到 chrome 并使用 three snap shot technique 分析它们（我想你可以在我们的案例中称其为 N 快照技术）
基本上，您将加载堆并开始查看它们以尝试了解正在堆积的东西的类型，持有它的是什么，因此您将了解为什么 GC 花费这么长时间.
Available memory never runs out, and the RSS does not even come close to the 1000mb old space limit, so it does not seem to be a leak. It looks to me like there might be something rather unusual within the code, making it very "difficult" for the GC to do its job in acceptable time frames.
在这里您可能正在寻找长而圆形的保留树。但归根结底，即使是这种情况，您也应该能够确定那棵树的根是什么，里面有什么，并尝试减少移除的方法。
我也同意@dandavis 并怀疑关闭。
我正在尝试分析相对复杂的 Node.js 服务器应用程序中的 memory/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) 输出 here。
这些日志是 运行 服务器使用以下参数的结果：
--expose-gc --trace-gc --trace-gc-verbose --trace-gc-ignore-scavenger --max-old-space-size=1000
它运行的时间越长，暂停的时间就越长（通常是几分钟），直到它最终在几个小时后完全锁定。可用内存永远不会用完，RSS 甚至没有接近 1000mb 的旧 space 限制，所以它似乎不是泄漏。在我看来，代码中可能有些不寻常的地方，这使得 GC 在可接受的时间范围内完成工作变得非常 "difficult"。
我的问题是：如何进一步分析这个问题，并缩小可能的原因？有什么值得推荐的工具可以帮助解决此类问题吗？我本质上是在寻找一种比天真地关闭和打开部分代码更有效的方法，这非常麻烦和耗时。
顺便说一句，我将非常感谢任何解释 GC 调试输出中使用的 terms/messages（例如 "promotion limit reached"）以及其中列出的数字的文档的链接。我对 V8 GC 的工作原理有非常基本的了解（this 帮助很大），但大部分输出仍然超出我的理解范围。
以防万一：这是 运行 Node.js v0.10.33 Ubuntu 14.04 服务器上的 运行。
编辑： 不久前，我们转到 io.js，这个问题不再发生（可能是由于更新的 V8 版本）。不过，我从未在 Node v0.10 中找到此问题的原因，更不用说修复了。
这个答案可能不像您希望的那样具体，但我建议您查看 good package that's part of Walmart's hapi.js 框架。它在将日志记录扩展到 --trace-gc 之外做得很好。它是一个进程监视器，用于侦听以下一个或多个事件：
ops- 系统和进程性能 - CPU、内存、磁盘和其他指标。response- 有关传入请求和响应的信息。这映射到从 hapi 服务器发出的 "response" 或 "tail" 事件。log- 未绑定到特定请求的日志信息，例如系统错误、后台处理、配置错误等。映射到从 hapi 服务器发出的 "log" 事件。error- 请求状态代码为 500 的响应。这映射到 "request-error" hapi 事件。request- 请求日志信息。这映射到通过request.log(). 发出的 hapi 'request' 事件
你必须引入 Hapi 库才能工作，但为了调试的目的暂时这样做可能是值得的。总的来说，我强烈推荐 Hapi 来扩展 Node.js 应用程序，沃尔玛的员工在过去一年里用它做了很多令人惊奇的事情。
您能否在单个节点上重现该问题？我想如果我处于这种情况，我可能会混合执行以下操作：
- 编写一个加载程序，让我在本地实例上进行复制
- 如果没有，将一个实例放入将接收一部分流量的 prod 中，并修改它以执行以下操作
- 将 node-heapdump 添加到您的源中，每隔一段时间调用一次，然后每隔 N 分钟将结果导出到 json 文件。
- 如果您 运行 在本地，您可能还可以利用 memwatch.
- 等待慢速 GC 启动。
- 在您知道缓慢的 GC 开始发生时抓取一些堆转储。
- 将它们加载到 chrome 并使用 three snap shot technique 分析它们（我想你可以在我们的案例中称其为 N 快照技术）
基本上，您将加载堆并开始查看它们以尝试了解正在堆积的东西的类型，持有它的是什么，因此您将了解为什么 GC 花费这么长时间.
Available memory never runs out, and the RSS does not even come close to the 1000mb old space limit, so it does not seem to be a leak. It looks to me like there might be something rather unusual within the code, making it very "difficult" for the GC to do its job in acceptable time frames.
在这里您可能正在寻找长而圆形的保留树。但归根结底，即使是这种情况，您也应该能够确定那棵树的根是什么，里面有什么，并尝试减少移除的方法。
我也同意@dandavis 并怀疑关闭。