如何在Node.js / V8中debugging/分析非常长的GC暂停

我正在尝试在相对复杂的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 )输出可以在这里find。

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

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

运行时间越长,停顿时间越长(通常几分钟),直到最终在几个小时后才完全locking。 可用的内存永远不会用完,RSS甚至不会接近1000mb旧的空间限制,所以它似乎不是泄漏。 在我看来,代码中可能有些不寻常的东西,使GC在可接受的时间框架内完成工作非常“困难”。

我的问题是:如何进一步分析这个问题,并缩小可能的原因? 任何推荐的工具来帮助像这样的问题? 我本质上是寻找一个更有效的方法比天真的closures和部分的代码,这是非常繁琐和费时。

另外,我非常感谢解释GCdebugging输出中使用的术语/消息(例如“达到的升级限制”)的任何文档的链接,以及那里列出的数字。 我对V8 GC的工作原理有了一个非常基本的了解( 这有很大的帮助),但是大部分的输出仍然超出了我的想象。

万一它很重要:这是在Ubuntu 14.04服务器上的Node.js v0.10.33上运行。

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

你能够在单个节点上重现问题吗? 我想如果我处于这种情况,我可能会混合使用以下内容:

  • 写一个加载器,让我复制本地实例
  • 如果没有的话,把一个实例放在收到stream量子集的地方,然后修改它来做下面的事情
  • 将node-heapdump添加到源代码中,每隔一段时间调用一次,并以N分钟为间隔将结果导出到json文件。
  • 如果你在本地运行,你可能也可以利用memwatch 。
  • 等待缓慢的GC启动。
  • 当你知道缓慢的GC开始发生的时候,抓取一些堆转储。
  • 将它们加载到chrome中并使用三次快照技术进行分析(我们假设您可以在我们的例子中将其称为N快照技术)

基本上,你会加载堆,并开始通过他们来试图了解是什么types的东西叠加起来,什么是持有它,因此,你会理解为什么GC是这么长时间。

可用的内存永远不会用完,RSS甚至不会接近1000mb旧的空间限制,所以它似乎不是泄漏。 在我看来,代码中可能有些不寻常的东西,使GC在可接受的时间框架内完成工作非常“困难”。

在这里,您可能正在寻找长而圆的保留树。 但是在一天结束的时候,即使是这样,你也应该能够确定那棵树的根源是什么,它里面是什么,并且试着用减less去除的方法。

我也同意@dandavis和可疑的closures。

这个答案可能不是你想要的,但是我build议你看一下沃尔玛hapi.js框架的一部分。 它在扩展日志logging方面做得很好--trace-gc 。 它是一个进程监视器,用于监听以下一个或多个事件:

  • ops – 系统和进程性能–CPU,内存,磁盘和其他指标。
  • response – 关于传入请求和响应的信息。 这映射到hapi服务器发出的“响应”或“尾巴”事件。
  • loglogging信息没有绑定到特定的请求,如系统错误,后台处理,configuration错误等。映射到从hapi服务器发出的“日志”事件。
  • error – 具有状态码500的请求响应。这映射到“请求错误”hapi事件。
  • request – 请求logging信息。 这映射到通过request.log()发送的hapi'request'事件。

为了达到这个目的,你必须拉入Hapi库,但是为了debugging的目的,暂时还是值得的。 总的来说,我强烈build议Hapi扩展Node.js应用程序,沃尔玛的这些人在过去的一年里一直在做着令人惊叹的事情。