标签搜索

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

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

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

问题原因
  1. 数据量大的表且用于查询的字段没有设置索引,导致查询效率低。
  2. 执行定时任务时没有传入增量获取的参数,采用了全量获取数据的方式进行同步数据,数据量较大,一直占用着数据库资源。
解决办法与预防措施
  1. 需要给数据量较大的表频繁查询的字段添加索引
  2. 同步大量数据时,采用增量的方式,如果是需要重新获取全量数据,则尽量在晚上执行,且要考虑同步的时长是否会影响白天系统的使用。
  3. 优化同步数据的方法,尽量避免在循环中调用数据库,造成数据库资源占用过高,影响系统性能。
3