压力测试过程中MySQL服务CPU占用率过高的问题排查思路

〇、经验总结：

• 在关注业务接口的TPS时，也要关注数据库服务器的QPS。如果一个业务流程里包含多条查询，那么业务接口TPS的上升对数据库服务器QPS的放大效应会很明显。
• 如果查询结果集不大，尽量使用一条查询语句，通过子查询返回多个结果集，避免将多个结果集拆分成多次数据库查询，否则会造成过多的数据库连接/查询操作，消耗IO资源，降低TPS，提高CPU占用率。
• 在业务代码中，尽量避免在循环语句里写数据库查询。
• 依据SQL语句的使用频率来建立索引，查询条件字段顺序按照联合索引的字段顺序来写（从左到右的匹配顺序）
• 关注慢查日志

一、背景说明

接着上一篇Grpc性能调优的文章继续写，我们这次压测的是一个查询用户群组列表信息的接口，该接口里需要查询某个用户的所有群组信息，包括每个群组的名称、成员数量等。
经过之前对业务机器的JVM参数等进行优化后，现在已经不存在业务机器的频繁GC、CPU占用率过高、TPS上不去等问题了。但是我们遇到了两个新问题：在业务接口并发50、TPS600左右时，压测接口出现了超时错误，而且数据库服务器CPU占用率超过了93%！

二、测试过程

数据准备：

• t_info_group群组表：
  

• t_info_group_member群组成员表：
  

数据约定：测试数据中，每个群组里面有3000个成员；每个成员有20个群组。

1、第一次压测

我们首先进行一次摸底测试，使用两台压测机器共同发起300个并发，持续压测2分钟。（如果只用一台压测机发起300个并发，会由于机器端口受限，TPS超过5W后不能发起新请求，压测机将报错）
（1）数据库连接池配置
c3p0.initialPoolSize=15
c3p0.minPoolSize=15
c3p0.acquireIncrement=10
c3p0.maxPoolSize=32
（2）数据库慢查日志、数据库服务器监控指标

top命令显示CPU使用率超过了91%，而且慢查日志一直在刷！
通过分析慢查日志里面的SQL语句，以及对应的数据库表，发现查询语句中有“where a=.. and b=.. and c=..”，但是有一个联合索引的字段是“a, c"。根据联合索引的匹配规则，这条sql用不了索引，导致慢查。经过将索引更换成"a, b, c"，单条sql查询效率提高一倍。

2、第二次压测

使用两台压测机器共同发起50个并发，持续压测2分钟。
（1）其他配置均不做改变。
（2）数据库慢查日志、数据库服务器监控指标
经过上述调整，慢查日志没有了，但是CPU使用率依然还是超过了90%。这是一个不能容忍的数据，如果并发继续提高，数据库服务器很快将被撑爆。

由于其他涉及到sql查询的接口在压测时都没有出现过CPU占用率这么高的情况，所以我们排除了数据库服务器安装配置的问题。
我们开始思考出现问题的可能原因：

• 数据库连接池等参数配置有缺陷，导致连接池不够用，一直在建立新的连接。
• 业务代码逻辑可能存在缺陷，导致查询语句消耗过多IO或内存资源。
• 并发数量高，数据库服务器CPU正常就需要占用这么多。（这是最无奈最不想接受的结局）
  我们先查看show processlist; 的结果，发现有很多连接其实是空闲的，也就是说目前的连接池已经够用了。
  而当我们把连接池尝试放大，配置改为：
  c3p0.initialPoolSize=20
  c3p0.minPoolSize=20
  c3p0.acquireIncrement=20
  c3p0.maxPoolSize=128
  在这个配置下，对CPU的占用率没有丝毫影响。那么排除连接池配置的问题。
  那有没有可能是在当前并发量条件下，就需要消耗这么多的CPU呢？
  我们对比了另一个涉及到SQL查询的接口，在60个并发下，那个接口的TPS达到了1100，而现在压测的接口，TPS只有600。那么在同等并发下，相同的查询语句复杂度和查询结果数据量条件下，现在压测的接口不仅TPS低，还占用了过多的CPU，可能就不是数据库的问题。这就排除了因并发量高而必然导致CPU占用率超过90%的假设。
  我们继续看数据库服务器的监控指标，使用阿里的orzdba脚本监控MySQL服务器。
  当前压测接口的MySQL服务器指标数据：
  

对照接口的指标数据：

从上述两个对比图可以看到，当前压测接口的数据库QPS高达3000。对比数据汇总一下，可以看出一些问题：
当前接口：
并发：60，TPS：600，数据库CPU：92%，数据库QPS：3000
对照接口：
并发60，TPS：1000，数据库CPU：20%，数据库QPS：1400
当前压测接口处理更耗时，可能原因是一次接口业务里涉及到了多次数据库操作。
那么接下来就是排查业务代码里的数据库操作了。进行code review！
核心业务伪代码：
//查询用户的群组列表
List<Dto> groupList = groupDao.selectGroups(userId);
for(Dto dto:groupList){
//查询每个群组的用户数，会循环20次！
int userNumber = groupDao.getGroupNumber(dto.getAsIong(groupId));
}

这段代码怎么这么别扭？第一个查询已经去查询群组信息了，还要用for循环去遍历20次统计每个群组用户数？？
这样操作的话，一次接口请求将操作很多次的数据库查询，并带来更多网络、IO操作。那么CPU占用率过高的问题很可能是这个情况导致的。
我们的优化措施是优化groupDao.selectGroups(userId)对应的查询语句，使用子查询返回用户的群组列表和每个群组的用户数，去掉for循环。

3、第三次压测

使用两台压测机器共同发起50个并发，持续压测2分钟。
（1）其他配置均不做改变。
（2）数据库慢查日志、数据库服务器监控指标
数据库慢查日志没有提示慢查SQL语句，数据库服务器CPU占用率稳定在80%以下，数据库QPS提高到了近7000！这个优化效果可以说是非常的明显了。

4、留给我的疑问

也许有人会问：代码优化后数据库的QPS比之前更高了，那CPU使用应该更多啊，但是为什么数据库的CPU占用率反而降下来了呢？这是为什么呢？[这个问题，其实我也没有想明白，有知道原因的朋友欢迎留言讨论。]
对于这个问题，我最近一直在思考，并查阅相关的资料，突然从接口优化前后的性能数据上可以看到：优化前，业务接口的TPS才600，数据库QPS才3000，而优化后的业务接口TPS达到了1100，几乎翻倍，同时数据库QPS达到了6000，也翻倍了，但数据库CPU使用率反而降低了。从这几个数据可以得到这样一条结论：接口TPS的增长，自然导致了数据库QPS的同级别增长，说明在优化前和优化后，数据库的压力瓶颈还远没有达到，那么数据库服务器CPU使用率的飙高，也不是由于SQL处理导致的！
数据库服务器的资源消耗，除了SQL执行、磁盘IO，其实还有网络连接。
优化前的代码里，一次TPS会进行多次数据库连接并提交SQL查询请求，这个操作带来的网络连接消耗也是非常可观的，优化后的代码里，一次TPS就进行一次数据库连接并提交SQL查询请求，资源消耗降低了很多。

• 接口优化前：
  并发：60，TPS：600，数据库CPU：92%，数据库QPS：3000
  
  

• 接口优化后：
  并发：60，TPS：1100，数据库CPU：低于80%，数据库QPS：6000