logo标签列表

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

javascriptnode.jsmemory-leaksgarbage-collectionv8
23

我正在尝试分析一个相对复杂的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) 输出可以在这里找到。

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

--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 Server上运行的Node.js v0.10.33。

编辑： 一段时间以前，我们转向了io.js，在那里这个问题根本没有出现（可能是由于更近期的V8版本）。我从未找到过Node v0.10中这个问题的原因，更不用说解决方法了。

RSS不是用了多少内存，至少不是按照描述的那样，heapUsed更接近于你想要查看的内容。似乎“old pointers”占用了大量的内存，因此我怀疑一个闭包被意外地缓存了，可能是通过过度宽松地传递req/res对象来实现的。在http://jayconrod.com/posts/55/a-tour-of-v8-garbage-collection 上可以了解有关该术语和整体情况的一些详细信息。 - dandavis
好的，堆使用量和总堆大小的图表在我的监控工具中完全遵循RSS曲线（据我所知没有交换）。感谢您提供“旧指针”的提示 - 我会更仔细地研究它。 - d0gb3r7
使用原型和面向对象编程，而不是无限嵌套闭包。 - Esailija
实际上，这段代码已经非常倾向于面向对象编程了。但首要的是，我真正想要的是找到更好的方法来理解和分析问题（而不是凭直觉进行复杂、深入的代码更改）。 - d0gb3r7
@d0gb3r7 我的意思是你可能通过嵌套函数（例如在构造函数内定义方法）来实现它。 - Esailija
显示剩余2条评论
2个回答
5

你能在单个节点上复现这个问题吗？如果我处于这种情况下，我可能会采取以下措施的混合方式：

  • 编写一个加载器，让我在本地实例上复制
  • 如果不行，在生产环境中放置一个将接收子集流量的实例，并修改它以执行以下操作
  • 在源代码中添加node-heapdump，按间隔调用它，并将结果导出到N分钟间隔的JSON文件中。
  • 如果您正在本地运行，可能还可以利用memwatch。
  • 等待缓慢的GC开始。
  • 在您知道发生缓慢GC时的时间周围获取多个堆转储。
  • 将它们加载到Chrome中，并使用three snap shot technique（我想我们在这种情况下可以称之为N快照技术）进行分析
基本上，您将加载堆并开始查看它们，以尝试了解正在堆积的类型，它是如何保持的，因此您将了解为什么GC需要这么长时间。
可用内存永远不会耗尽，RSS甚至没有接近1000mb的旧空间限制，因此它似乎不是泄漏。在我的看来，代码中可能有一些非常不寻常的东西，使得GC难以在可接受的时间范围内完成其工作。
在这里，您可能正在寻找长而循环的保留树。但归根结底，即使是这种情况，您也应该能够确定该树的根源是什么，其中包含什么，并尝试减少或删除的方法。
我也同意@dandavis并怀疑闭包。
1
感谢您提供详细的说明。正如我刚刚在问题中补充的那样，我们最终通过更新到io.js来解决了这个问题 :) 无论如何，我仍然会接受这个答案，因为据我所知，目前没有更方便的解决方法来调试这种问题，比较堆快照可能是唯一可行的方法。 - d0gb3r7
非常有趣。如果你能够聚焦于在Node中泄漏而不是在IO中泄漏的问题，我会非常好奇想知道。 - j03m
0

这个答案可能没有你想要的那么具体，但我建议看一下沃尔玛的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 应用程序，在过去的一年里，沃尔玛的团队已经用它做了很多惊人的事情。
谢谢您的回答。我之前不知道 good 包，看起来是一款很好用的通用监控库；我会在其他项目中记住它。但是我真的不明白它如何帮助解决这个问题（据我所知，除了 process.memoryUsage() 报告的内存 / GC 特定指标之外，并没有其他特定的指标）。 - d0gb3r7
网页内容由stack overflow 提供, 点击上面的
可以查看英文原文，
原文链接