阿里云rds数据库mysql版cpu占用100%排查问题过程

背景

• 某天去到公司，用户反馈说系统响应很慢，甚至有些功能基本用不了，严重影响工作效率。测试同事说阿里云RDS数据库的CPU占用了100%，我打开阿里云dms的监控页面，确实如此，接着开始排查问题。

问题排查过程

• 因为前段时间遇到过代码死循环查询数据库导致了CPU占用100%的问题，所以一开始就往这个方向排查。首先通过阿里云的dms控制台执行show processlist命令查询数据库正在执行的线程如下
  
  发现大量状态为sending data的线程，通过查询资料，这个状态的意思是读取和过滤数据，如果一个表数据量很大且没有索引的话，就容易出现sending data状态，官方解释是，线程正在读取和处理 SELECT 的行记录，发送给客户端，由于在这个状态下的操作会执行大量的磁盘访问（读），因此它通常是查询生命周期最长的状态。但具体为什么会占用大量CPU，还有待学习了解。
• 之前的死循环会出现在一些同步erp数据到业务系统的定时任务中，因为需要同步大量的数据而使用了循环。使用上面的sql语句（info字段）搜索代码，发现只有一个定时任务的方法使用了这个语句，因此接着登录服务器查询这个定时任务，但是没有找到相应的定时任务，后来了解到原来一直没有配置，但是同事在前一天手动执行过这个定时任务，通过如下监控信息 发现从前一天下午5点09分开始数据库的CPU就开始飙升到100%了。通过ps命令找不到相关的定时任务进程正在执行，但为什么那些语句一直存在呢？然后在运维同事的帮助下，使用lsof和ll /proc/pid命令以及上面show processlist结果的端口查询到发起那个语句请求的进程是php-fpm，工作目录是tp框架的public目录，印象中tp框架的php think命令运行的模式是cli，因此导致sending data状态有可能不是定时任务导致的。
• 因为当时没有及时排查出原因，所以采取了同事的建议将服务器重启。
  
  重启后数据库的CPU确实降下来了，但是过了一会又升上去了。确定了不是由于定时任务导致的，接着继续排查代码中调用这个定时任务方法的地方，后来确实发现还有一个接口调用了这个方法，通过查询nginx的access.log日志，发现当时一直有IP频繁地请求着这个接口，初步认定是由于这个接口调用了这个方法导致的问题。接着和同事一起去查看这个方法的代码，但是却没有发现这个方法的问题，逻辑上产生死循环的逻辑也没有被发现。
• 在测试环境模拟复现这个问题，发现在死循环中获取一个数据量为三万的表的同一条数据时（查询条件有加索引并命中）并不会导致CPU飙升，但是没有索引或没有命中索引的情况下，CPU就会一直飙升。
  
  从上面排查的过程中，没有发现死循环，考虑到有些单据数据行比较多，所以模拟了短时间内循环查询并修改大量不同单据的情景，在命中索引的情况下，CPU占用不高，但是没有命中索引的情况下，CPU占用升到百分之五十多。

• 接着看了生产环境相关的表，数据量大概是十万行，而且用于查询的entry_id字段并没有设置索引，因此同步数据时，如果数据量较大，循环插入或者更新数据时会导致数据库CPU占用持续升高。通过下面的监控图
  

  
  119.23.123.173 - - [21/Apr/2022:11:10:03 +0800] "OPTIONS /abc_admin/v2/sourceOrderPhoto/getODODetail?inquire_type=2&express_no=10111194500 HTTP/1.1" 200 5 "https://cadmin.hopo.com.cn/" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/77.0.3865.120 Safari/537.36 Core/1.77.103.400 QQBrowser/10.9.4624.400"
  119.23.123.176 - - [21/Apr/2022:11:10:07 +0800] "GET /abc_admin/v2/sourceOrderPhoto/getODODetail?inquire_type=2&express_no=10111194249 HTTP/1.1" 499 0 "https://cadmin.hopo.com.cn/" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/77.0.3865.120 Safari/537.36 Core/1.77.103.400 QQBrowser/10.9.4624.400"
  119.23.123.174 - - [21/Apr/2022:11:10:09 +0800] "OPTIONS /abc_admin/v2/sourceOrderPhoto/getODODetail?inquire_type=2&express_no=10111194045 HTTP/1.1" 200 5 "https://cadmin.hopo.com.cn/" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/77.0.3865.120 Safari/537.36 Core/1.77.103.400 QQBrowser/10.9.4624.400"
  119.23.123.179 - - [21/Apr/2022:11:10:09 +0800] "GET /abc_admin/v2/sourceOrderPhoto/getODODetail?inquire_type=2&express_no=10111194045 HTTP/1.1" 201 1003 "https://cadmin.hopo.com.cn/" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/77.0.3865.120 Safari/537.36 Core/1.77.103.400 QQBrowser/10.9.4624.400"
  119.23.123.174 - - [21/Apr/2022:11:10:14 +0800] "OPTIONS /abc_admin/v2/sourceOrderPhoto/getODODetail?inquire_type=2&express_no=10111194552 HTTP/1.1" 200 5 "https://cadmin.hopo.com.cn/" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/77.0.3865.120 Safari/537.36 Core/1.77.103.400 QQBrowser/10.9.4624.400"
  119.23.123.167 - - [21/Apr/2022:11:10:14 +0800] "GET /abc_admin/v2/sourceOrderPhoto/getODODetail?inquire_type=2&express_no=10111194552 HTTP/1.1" 201 1892 "https://cadmin.hopo.com.cn/" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/77.0.3865.120 Safari/537.36 Core/1.77.103.400 QQBrowser/10.9.4624.400"
  119.23.123.164 - - [21/Apr/2022:11:10:17 +0800] "OPTIONS /abc_admin/v2/sourceOrderPhoto/getODODetail?inquire_type=2&express_no=10111194613 HTTP/1.1" 200 5 "https://cadmin.hopo.com.cn/" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/77.0.3865.120 Safari/537.36 Core/1.77.103.400 QQBrowser/10.9.4624.400"
  119.23.123.154 - - [21/Apr/2022:11:10:26 +0800] "OPTIONS /abc_admin/v2/sourceOrderPhoto/getODODetail?inquire_type=2&express_no=10111194548 HTTP/1.1" 200 5 "https://cadmin.hopo.com.cn/" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/77.0.3865.120 Safari/537.36 Core/1.77.103.400 QQBrowser/10.9.4624.400"
  119.23.123.169 - - [21/Apr/2022:11:10:31 +0800] "OPTIONS /abc_admin/v2/sourceOrderPhoto/getODODetail?inquire_type=2&express_no=10111194229 HTTP/1.1" 200 5 "https://cadmin.hopo.com.cn/" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/77.0.3865.120 Safari/537.36 Core/1.77.103.400 QQBrowser/10.9.4624.400"
  47.112.84.217 - - [21/Apr/2022:11:10:31 +0800] "GET /abc_admin/v2/sourceOrderPhoto/getODODetail?inquire_type=2&express_no=10111194249 HTTP/1.1" 499 0 "https://cadmin.hopo.com.cn/" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/77.0.3865.120 Safari/537.36 Core/1.77.103.400 QQBrowser/10.9.4624.400"
  119.23.123.165 - - [21/Apr/2022:11:10:32 +0800] "GET /abc_admin/v2/sourceOrderPhoto/getODODetail?inquire_type=2&express_no=10111194264 HTTP/1.1" 499 0 "https://cadmin.hopo.com.cn/" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/77.0.3865.120 Safari/537.36 Core/1.77.103.400 QQBrowser/10.9.4624.400"
  119.23.123.178 - - [21/Apr/2022:11:10:35 +0800] "OPTIONS /abc_admin/v2/sourceOrderPhoto/getODODetail?inquire_type=2&express_no=10111194592 HTTP/1.1" 200 5 "https://cadmin.hopo.com.cn/" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/77.0.3865.120 Safari/537.36 Core/1.77.103.400 QQBrowser/10.9.4624.400"
  119.23.123.170 - - [21/Apr/2022:11:10:39 +0800] "GET /abc_admin/v2/sourceOrderPhoto/getODODetail?inquire_type=2&express_no=10111194500 HTTP/1.1" 499 0 "https://cadmin.hopo.com.cn/" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/77.0.3865.120 Safari/537.36 Core/1.77.103.400 QQBrowser/10.9.4624.400"
  119.23.123.159 - - [21/Apr/2022:11:10:41 +0800] "OPTIONS /abc_admin/v2/sourceOrderPhoto/getODODetail?inquire_type=2&express_no=10111194580 HTTP/1.1" 200 5 "https://cadmin.hopo.com.cn/" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/77.0.3865.120 Safari/537.36 Core/1.77.103.400 QQBrowser/10.9.4624.400"
  119.23.123.170 - - [21/Apr/2022:11:10:41 +0800] "GET /abc_admin/v2/sourceOrderPhoto/getODODetail?inquire_type=2&express_no=10111194580 HTTP/1.1" 201 1125 "https://cadmin.hopo.com.cn/" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/77.0.3865.120 Safari/537.36 Core/1.77.103.400 QQBrowser/10.9.4624.400"
  119.23.123.154 - - [21/Apr/2022:11:10:46 +0800] "OPTIONS /abc_admin/v2/sourceOrderPhoto/getODODetail?inquire_type=2&express_no=10111194576 HTTP/1.1" 200 5 "https://cadmin.hopo.com.cn/" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/77.0.3865.120 Safari/537.36 Core/1.77.103.400 QQBrowser/10.9.4624.400"
  119.23.123.170 - - [21/Apr/2022:11:10:46 +0800] "GET /abc_admin/v2/sourceOrderPhoto/getODODetail?inquire_type=2&express_no=10111194576 HTTP/1.1" 201 1296 "https://cadmin.hopo.com.cn/" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/77.0.3865.120 Safari/537.36 Core/1.77.103.400 QQBrowser/10.9.4624.400"
  119.23.123.154 - - [21/Apr/2022:11:10:51 +0800] "OPTIONS /abc_admin/v2/sourceOrderPhoto/getODODetail?inquire_type=2&express_no=10111194536 HTTP/1.1" 200 5 "https://cadmin.hopo.com.cn/" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/77.0.3865.120 Safari/537.36 Core/1.77.103.400 QQBrowser/10.9.4624.400"
  119.23.123.171 - - [21/Apr/2022:11:10:53 +0800] "GET /abc_admin/v2/sourceOrderPhoto/getODODetail?inquire_type=2&express_no=10111194613 HTTP/1.1" 499 0 "https://cadmin.hopo.com.cn/" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/77.0.3865.120 Safari/537.36 Core/1.77.103.400 QQBrowser/10.9.4624.400"
  47.112.84.213 - - [21/Apr/2022:11:10:56 +0800] "GET /abc_admin/v2/sourceOrderPhoto/getODODetail?inquire_type=2&express_no=10111194264 HTTP/1.1" 499 0 "https://cadmin.hopo.com.cn/" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/77.0.3865.120 Safari/537.36 Core/1.77.103.400 QQBrowser/10.9.4624.400"
  119.23.123.163 - - [21/Apr/2022:11:10:57 +0800] "OPTIONS /abc_admin/v2/sourceOrderPhoto/getODODetail?inquire_type=2&express_no=10111194524 HTTP/1.1" 200 5 "https://cadmin.hopo.com.cn/" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/77.0.3865.120 Safari/537.36 Core/1.77.103.400 QQBrowser/10.9.4624.400"
  119.23.123.172 - - [21/Apr/2022:11:11:02 +0800] "GET /abc_admin/v2/sourceOrderPhoto/getODODetail?inquire_type=2&express_no=10111194548 HTTP/1.1" 499 0 "https://cadmin.hopo.com.cn/" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/77.0.3865.120 Safari/537.36 Core/1.77.103.400 QQBrowser/10.9.4624.400"
  47.112.84.216 - - [21/Apr/2022:11:11:02 +0800] "GET /abc_admin/v2/sourceOrderPhoto/getODODetail?inquire_type=2&express_no=10111194500 HTTP/1.1" 499 0 "https://cadmin.hopo.com.cn/" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/77.0.3865.120 Safari/537.36 Core/1.77.103.400 QQBrowser/10.9.4624.400"
  119.23.123.166 - - [21/Apr/2022:11:11:06 +0800] "OPTIONS /abc_admin/v2/sourceOrderPhoto/getODODetail?inquire_type=2&express_no=10111194508 HTTP/1.1" 200 5 "https://cadmin.hopo.com.cn/" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/77.0.3865.120 Safari/537.36 Core/1.77.103.400 QQBrowser/10.9.4624.400"

结合同事在前一天手动执行了定时任务并且是全量获取数据以及nginx的access.log日志的情况，从前一天执行了定时任务开始一直到第二天11点08分的CPU都是占满的状态，然后重启了服务器，CPU降了下来，接着因为相关接口被频繁调用，所以又导致CPU重新占满。

问题原因

1. 数据量大的表且用于查询的字段没有设置索引，导致查询效率低。
2. 执行定时任务时没有传入增量获取的参数，采用了全量获取数据的方式进行同步数据，数据量较大，一直占用着数据库资源。

解决办法与预防措施

1. 需要给数据量较大的表频繁查询的字段添加索引
2. 同步大量数据时，采用增量的方式，如果是需要重新获取全量数据，则尽量在晚上执行，且要考虑同步的时长是否会影响白天系统的使用。
3. 优化同步数据的方法，尽量避免在循环中调用数据库，造成数据库资源占用过高，影响系统性能。