在Storify,我们用Node.js驱动后台。
对于大多数生产环境上的问题(像未捕获的异常),我们使用日志来调试。然后我们看到了一些其他的BUG,像内存泄漏和无限循环,这些漏洞无法通过debugging工具来调试。
注* 关于在Node.JS中添加错误日志,可参考: 守护node.js
过去,当我们的服务变得很慢时,我们使用Monit 去重启他们。当我们上线了Livefyre之后,我们决定不要重启,尝试去修复这些缺陷。经过几个月的尝试,我们在Node.JS的调试技巧方面学到了很多。
内存泄漏
几个月以前,我们已经知道程序有内存泄漏,这会引起我们的服务器强制自动重启。因为我们使用了大约60个npm 模块 ,这个BUG也有可能是从这些模块里产生的,因此找到泄漏点是不太可能的。
我们的同事@devongovett决定去修这个BUG,但是他不知道从何开始。
Devon创建了一台服务器去记录Node.JS的内存使用情况。他的第一个发现是在一条查询query执行后,几个对象被遗留了下来。下一步是将大量的Mongoose注释掉去寻找泄漏点。最终他找到了罪魁祸首。
“我认为这纯碎是运气”
这个调试经验让我们坚信我们需要使用更好的调试工具。
CPU占用率
我们的服务会偶尔当机几分钟。@tjfontaine Node.js项目的主管开始解决调试工具的问题,他建议我们试试MDB 。在阅读了这篇文章之后,我们开始玩这个工具了。
首次尝试
我使用gcare去获取核心转储(core dump),上传到Mana并开始分析。我的第一个分析很全面,但是我无法理解这个进程在干什么。
[ 00007fffe4967160 0x7f7a24ced619() ]
00007fffe496a1d0 uv__io_poll+0x148()
00007fffe496a230 uv_run+0xd8()
00007fffe496a2b0 _ZN4node5StartEiPPc+0x150()
0000000000000000 0x7f7a24c1e76d()
我在进程没有干什么任何事情的时侯捕获到了。
Node.js在等待事件发生时就会干这个。
最扯蛋的是gcare在你的程序崩溃的时侯进程了转储捕获(capture the dump)。这里有几个选项可以获取有用的跟踪。
在一段特定的代码处引导核心
process.abort()
在未捕获异常时引导核心
node --abort-on-uncaught-exception app.js
当CPU楔入(wedging)时杀死进程
kill -ABRT $pid
我们第一个有用的跟踪
通过使用 kill -ABRT method,我最终可以获取到一个好的跟踪栈。
我会只关注最重要的部分,但是你可以在这里看到整个栈。
> 00007ffffd09c0c0::jsstack
[...]
7ffffd09c7c0 0x3bdddc420285 inlineContent (e8477f4cc01)
7ffffd09c810 0x3bddc784e83d juice (e8477f4c9b9)
[...]
7ffffd09c948 0x3bddc4fb80f0 renderWrapper (270dfadc0769)
[...]
7ffffd09cdb8 0x3bddc7f2858b forEach (28a6e1015579)
[...]
7ffffd0a0ac0 node::Start+0x172
通过这个跟踪,我们开始注意Juice, 这是我们用来为RSS订阅源生成内联CSS的一个库(注* 邮件一般无法外联CSS样式)。我们只在Webapp代码里使用了一次。像下面这样:
async.forEach(stories, function(story, cb) {
res.render(‘story/_minimal’, {
//…
}, function(e, html) {
if (e) return cb(e);
var description = juice(html, someCss);
// …
});
}, callback);
通过这个,我现在可以在本地重现这个挂起了。最终的研究我们发现问题出现在了Jsdom ,这个库在处理大量HTML文档时会非常慢。相比修复Jsdom,我们开始寻找快一点的模块。通过使用 Cheerio 和 Styliner 我们现在可以将处理过程压缩到3秒以内,但是Juice需要大概5分钟。
结论
我希望用这个工具找到mongoose的泄漏。现在我们可以直接找到bug,不需要猜了。
有些漏洞无法在非生产环境发现。找到一种可以在生产环境检测程序工作的工具非常重要。
现在我们在重启前都会使用Monit去自动检测核心转储:
stop program = “/bin/bash -c ‘/bin/kill -ABRT `/bin/cat <%= processpidfile %>`’”
然后我们将Manit的日志跟Hipchat连在一起。现在我们明白重启时什么发生什么。
希望这篇文章对你有所帮助。
翻译得不是很好。
@夏乎设 #0
欢迎指出改进意见。
嘎嘎嘎嘎嘎呢