1. 问题现象:
某项目跑在 p01~02
2台ECS上,主要用途是聚合服务,给H5页面提供直接访问的接口。
最近版本新增加了接口 wechat/mp/qrcode
,用途是根据请求参数生成小程序二维码,以swoole+lumen方式对外服务
接口上线后,cpu使用率逐步上升,直至100%;同时请求响应时长也逐步攀升
上图是问题期间p01
cpu使用率,几个下降过程是因为上线(会重启服务进程)或者手动重启服务进程;后面发现p01 p02
cpu基本打满,临时加了 p03 p04
2台ecs以降低问题的影响。
2. 初步分析
对于cpu使用率居高不下的进程,通常做法是先大致看下系统调用,看cpu时间都耗在哪个上面:strace -p {pid} -c
位居第一的是 brk
系统调用,占用了接近90%的时间
搜索brk
的作用:
更通俗一点说,malloc
小于128k的内存,使用brk
分配内存,将_edata
往高地址推(只分配虚拟空间,不对应物理内存(因此没有初始化),第一次读/写数据时,引起内核缺页中断,内核才分配对应的物理内存,然后虚拟地址空间建立映射关系)
到这里,当时的第一反应是有资源未正确释放,导致内存泄漏,于是去捋了一遍接口代码,发现代码是这样的:
$curl = new Curl();
$curl->setHeader('Content-Type', 'application/json; charset=utf-8');
$curl->post('https://api.weixin.qq.com/wxa/getwxacodeunlimit?access_token=' . $accessToken, $params);
if ($curl->error) {
...
}
if (is_object($curl->response)) {
...
}
$img = base64_encode($curl->response);
发现 $curl
没有执行close操作,而服务本身以swoole方式对外提供服务,未正确close可能会导致内存泄漏,故简单的认为是这个原因导致;
在增加了 $curl->close()
后,上线,发现问题依旧,尴尬  ̄□ ̄||。。。
3. 深入分析
重新思考了下,既然$curl->close()
未能解决问题,说明很大概率问题不是出在代码,而是其他组件。
再次通过strace
命令观察了进程的系统调用,这次没有使用-c
统计参数,而是直接输出,发现个有意思的事:
如上图,Line 988
在读取了 /etc/pki/tls/certs/ca-bundle.crt
文件后,就产生了大量的brk
系统调用,截图下方还有成百上千个;ca-bundle.crt
是服务器上存储的所有根证书文件,4700行左右
仔细观察 brk
的参数,发现在有规律的周期重复,到这里,初步怀疑是这个阶段不停的在分配内存,然后释放;而且很可能是每请求一次,就会多一组相同变量的分配、释放操作,所以才会导致brk地址周期性的重复。
通过系统调用,可以发现问题出在TLS握手阶段;既然如此,那不验证证书信息,是不是就可以绕过这些来源不明的brk
系统调用?遂再次尝试修复bug,在代码层面增加了一行
$curl->setOpt(CURLOPT_SSL_VERIFYPEER, false);
上线后,问题消失。
4. 查找root cause
经过上面的处理,问题已经修复,但并没有找到root cause,只是一个绕过的方式,而且关闭验证证书的话,也存在中间人攻击的风险,不是长久之策,还是得找到 root cause.
再次回到问题,我写了一个临时脚本,以死循环的方式用同样的代码去请求美篇的一个https接口,然后观察cpu以及系统调用。
在这期间,通过搜索,发现通过gdb
可以打印线程具体执行的方法:
遂在poster04
上安装了gdb
通过以下命令查看:
gdb -q --batch -ex "thread apply all bt” -p `pidof tmem`
很可惜的是,当时的结果没有截图,用一个正常的截图来看看大致效果:
当时的现象是,在握手阶段,发现有 PL11_CreateManagedGenericObject()
方法调用,该方法属于nss
库
nss
是一个底层密码学库,包括 TLS 实现
到这里,已经怀疑是nss
库的问题,于是和运维同学沟通,将curl
的NSS
库替换为OpenSSL
库
再次运行临时脚本,发现问题消失。
由于临时脚本非swoole方式运行,为了排除swoole的问题,通过将p04
ECS上的代码手动修改,重启,恢复到问题发生时的状态,观察了一段时间后,发现问题没有出现。
至此,问题根因找到,属于nss
库的bug导致
在后续的搜索中,https://bugzilla.redhat.com/show_bug.cgi?id=1659108 这里可以看到有相同的问题现象,也确认了是nss
库在读取ca文件时,某个版本中,原本固定长度的数组变成了无限增长的数组,导致内存泄漏,进而导致分配、释放内存消耗了大量cpu。
5. 后记
在整个排查过程中,其实不是如文中所说这么顺畅,期间也遇到了一团乱麻的时候,不知道问题出在哪。
前期花了大量时间排查、验证代码,没有特别敢怀疑基础库的问题
幸运的是,后面搜索到了几篇非常有帮助的文章,对排查问题提供了很大帮助,也进一步理清了思路,一步一步逼近真相:)
参考:
- 一种内存泄露检查和定位的方法 https://blog.51cto.com/xiamachao/1929118
- 频繁分配释放内存导致的性能问题的分析 https://cloud.tencent.com/developer/article/1420726
- Linux内存分配小结--malloc、brk、mmap https://blog.csdn.net/gfgdsg/article/details/42709943