某接口cpu使用率异常排查记录

1. 问题现象：

某项目跑在 p01~02 2台ECS上，主要用途是聚合服务，给H5页面提供直接访问的接口。
最近版本新增加了接口 wechat/mp/qrcode，用途是根据请求参数生成小程序二维码，以swoole+lumen方式对外服务
接口上线后，cpu使用率逐步上升，直至100%；同时请求响应时长也逐步攀升

case_cpu

上图是问题期间p01cpu使用率，几个下降过程是因为上线（会重启服务进程）或者手动重启服务进程；后面发现p01 p02cpu基本打满，临时加了 p03 p04 2台ecs以降低问题的影响。

2. 初步分析

对于cpu使用率居高不下的进程，通常做法是先大致看下系统调用，看cpu时间都耗在哪个上面：
strace -p {pid} -c

case_strace-c

位居第一的是 brk 系统调用，占用了接近90%的时间

搜索brk的作用：

case_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统计参数，而是直接输出，发现个有意思的事：

case_strace

如上图，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`

很可惜的是，当时的结果没有截图，用一个正常的截图来看看大致效果：

case_gdb

当时的现象是，在握手阶段，发现有 PL11_CreateManagedGenericObject()方法调用，该方法属于nss库

case_nss

nss是一个底层密码学库，包括 TLS 实现
到这里，已经怀疑是nss库的问题，于是和运维同学沟通，将curl的NSS库替换为OpenSSL库
再次运行临时脚本，发现问题消失。
由于临时脚本非swoole方式运行，为了排除swoole的问题，通过将p04ECS上的代码手动修改，重启，恢复到问题发生时的状态，观察了一段时间后，发现问题没有出现。
至此，问题根因找到，属于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

1. 问题现象：

2. 初步分析

3. 深入分析

4. 查找root cause

5. 后记

Leave a Reply Cancel reply