一次神奇的 Nodejs Debug 经历

中秋之后,服务器上老是出现 cpu 爆满的情况,难道服务器也闹情绪想休假。当然这种情况是很紧急的,所以马上就着手排查。

还没找出问题,又有同学报测试机上也有这种情况,但是应用进程不同。想到有可能这两件事是有关联的,所以先从测试机开始排查。

问题一, setTimeout 的 bug

测试机上的问题很好排查,每次进程重启后立刻飙升到 100%,通过万能的 log 大法,很快就定位到问题。应用中使用了 axon 模块作为消息中间件,在连接不成功时会用 setTimeout 尝试重连,间隔由最初的 100ms 开始每次乘以 1.5,这样在三次之后间隔就变成了 337.5ms,nodejs 有一个 bug,Timer 函数中出现小数时会导致死循环,我们用的是 0.10.30 版本,这个 bug 依然可以重现。所以解决办法也很简单了,直接 round 一下就可以了。以后在使用 Timer 类函数时也需要注意不要出现小数哦。

问题二,正则表达式的效率问题

由于 axon 在生产环境中也有使用,我们就将所有的版本都进行了升级,以为万事大吉。结果却不遂人愿,生产环境中的几个进程在启动后,时不时会出现负载 100% 的情况,这种可能性分析起来就很复杂了。我们依次尝试了 node-inspector,node-heapdump 等工具,都没有找到原因(实话说,以前用这些 debug 内存问题时也是一无所获,nodejs 的 debug 工具实在鸡肋)。也没有重现线上的问题。

一个有趣的现象是,我发现每次进程重启之后,飙升到 100% 的时间不定,但是每次都是瞬间从 0 到 100%。这种现象说明导致问题的原因可能不是程序内部产生,而是由外力产生,这个外力是什么呢,其实就是请求。再一次借助万能 log 大法,express 的 log 只能记录有响应的请求,如果一个请求在中途陷入了死循环,那么就得不到 express 的 log,所以我们自己写了一个中间件,在 express 的最前部引入,只打印出请求的链接。

接下来问题就很明显了(其实也破费一番周折),每当出现某一请求时,程序就陷入了死循环,屡试不爽。一步步排查下来,发现问题出现在 xss 模块中,其中的一个正则表达式,在匹配某些字符串时出现了问题:

  • 表达式:/<!--(.|\s)*?-->/gm
  • 测试字符串:<!--

当表达式未找到匹配内容时,效率指数级的下降,特别是在多个重复空格和子表达式时。这个原因解释起来就比较复杂了。大神的一篇文章很好的解释了这个问题,有时间我要翻译一下,一定又有很多收获。

解决的方法很简单,在这个 Pull Request中可以找到。看来以后使用正则表达式的时候得过留个心眼了。

Comments