NodeJS 在生产环境3:一次 CPU 概率性满负荷运行问题的排查
项目某个版本经过开发环境、测试环境检验,经过测试上线之后正常运行,突然在某个时间点出现页面访问超级慢。以下是这个问题的主要排查过程。
问题来源
是否页面脚本执行错误
通过 Chrome 控制台可以发现,页面的请求被挂起,显示pending
状态,直到超时结束。可以确定这不是页面脚本错误,而是后端服务出现问题。
是不是 Node 进程出现内存泄露
登录 Node 服务器,使用 pm2 list
发现该项目进程也是正常,内存占用维持在 50MB 以下。
是不是服务器其他进程占用系统资源
使用 top
命令,发现该项目的 Node 进程的 CPU 使用率是 96% 以上。
依次通过以上三步,已经确定了问题来源是 Node 进程运行占用了大量的 CPU 资源,应该是执行了一个密集型计算,可能是死循环等。
问题根源
因为项目使用了两台服务器,使用负载均衡来分担访问压力。所以,我们紧急对第一台服务器进行了重启 Node 进程操作。
pm2 restart <ID>
执行 pm2 restart
之后,使用 top
命令发现,CPU 使用率依然是 96% 以上。使用 ps -ef | grep node
命令查看,发现了两个同样的 Node 进程在运行:
502 1277 21432 0 17:42 pts/2 00:00:00 grep node
502 1580 3613 0 Apr07 ? 02:10:54 node /some-project/app.js
502 2801 3613 0 Jun17 ? 00:03:54 node /some-project/app.js
其中一个进程占用了大量的 CPU 资源。
pm2 无法直接杀死旧进程,只能祭出kill -9 <PID>
命令了,杀死占用高的进程之后,CPU 使用率恢复正常。
然后,对第二台 Node 服务器进行问题排查。为了不影响生产环境,临时修改负载均衡,将所有的负载都指向第一台服务器,专心对第二台服务器进行问题排查。
CPU 性能分析
首先需要进行 CPU 性能分析:
稍等3分钟之后,查看分析报告:
这个结果有些意外,求助 alinode 官方人员,得到的结果是 CPU 占用 100% 的时候无法进行 CPU 性能分析。同时对方建议使用 gdb
命令来进行 CPU 性能分析。
输入bt
:
alinode 官方人员提示该情况无法进行调试,建议使用 node --debug
模式来启动。
访问日志
在进行 debug 模式之前,对现在的代码进行一次全面的检查,并未显式使用了循环,同时排除了一些第三方模块可能带来的 BUG。
因为问题的出现是一定概率的,所以打开了 Node 的访问日志。杀死 Node 进程,下载安装 node-inspector
模块,使用 node --debug
模式后台启动。
在 alinode 控制台添加报警通知,但是在下次出现问题的时候并未收到短信通知、邮件通知,这是他们的一个不足之处。
果然,在某个时间又出现问题了。通过查看 CPU 变化:
通过图表可以直接看到,在 14:27 分左右出现 CPU 突然上涨,因此重点查看下该段时间的访问日志。
在 14:25 分的时候,最后一次访问过后,就直接出现了重启日志,并且也没有报错日志。
通过该请求信息可以看出以下几个特殊点:
- 不是正常的浏览器访问,而是 google 蜘蛛
- 是一个活动详情页,并且有活动 ID
远程 debug
立马使用 node-inspector 开启调试,但是调试界面无法显示,可能原因应该还是 CPU 满负荷造成的。
本地模拟
在本地伪造请求头,使用同一个活动 ID。使用
node-debug app.js
启动。
访问该活动,在活动监视器里发现:
非常惊喜,这个 BUG 是可以在本地模拟出现的。使用 Chrome 控制台发现,只有在一个 xhr 接口上会阻塞页面,并且此时 CPU 占用率立马升高到 96% 以上。
本地 debug
发现在调试的时候,接口的请求和响应都是正常的,但是在响应内容的处理上卡住了。最后定位到一个文本处理上有问题,发现是这样一个正则表达式的执行卡住。
/<p>((\s* ?\s*)+|)<\/p>/g
正则本意是用来删除空白段落的。在控制台执行
v = '<p>' + new Array(2).join(' ');
n = v.match(/ /g).length + '个 +空格';
console.time(n);
v.match(/<p>((\s* ?\s*)+|)<\/p>/g);
console.timeEnd(n);
< 1个 +空格: 0.101ms
这个代码执行是没问题的,但是当
的长度增加到 20 个之后:
v = '<p>' + new Array(21).join(' ');
n = v.match(/ /g).length + '个 +空格';
console.time(n);
v.match(/<p>((\s* ?\s*)+|)<\/p>/g);
console.timeEnd(n);
< 20个 +空格: 52.562ms
25 个之后:
v = '<p>' + new Array(26).join(' ');
n = v.match(/ /g).length + '个 +空格';
console.time(n);
v.match(/<p>((\s* ?\s*)+|)<\/p>/g);
console.timeEnd(n);
< 25个 +空格: 1658.748ms
该正则性能问题的示意图:
确定了问题源头然后进行修复。