项目某个版本经过开发环境、测试环境检验,经过测试上线之后正常运行,突然在某个时间点出现页面访问超级慢。以下是这个问题的主要排查过程。

问题来源

是否页面脚本执行错误

通过 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*&nbsp;?\s*)+|)<\/p>/g

正则本意是用来删除空白段落的。在控制台执行

v = '<p>' + new Array(2).join('&nbsp; ');
n = v.match(/&nbsp;/g).length + '个&nbsp;+空格';
console.time(n);
v.match(/<p>((\s*&nbsp;?\s*)+|)<\/p>/g);
console.timeEnd(n);

< 1个&nbsp;+空格: 0.101ms

这个代码执行是没问题的,但是当 &nbsp; 的长度增加到 20 个之后:

v = '<p>' + new Array(21).join('&nbsp; ');
n = v.match(/&nbsp;/g).length + '个&nbsp;+空格';
console.time(n);
v.match(/<p>((\s*&nbsp;?\s*)+|)<\/p>/g);
console.timeEnd(n);

< 20个&nbsp;+空格: 52.562ms

25 个之后:

v = '<p>' + new Array(26).join('&nbsp; ');
n = v.match(/&nbsp;/g).length + '个&nbsp;+空格';
console.time(n);
v.match(/<p>((\s*&nbsp;?\s*)+|)<\/p>/g);
console.timeEnd(n);

< 25个&nbsp;+空格: 1658.748ms

该正则性能问题的示意图:

确定了问题源头然后进行修复。