运维同事监测到生产环境数据库CPU占用过高，业务系统反应卡慢，记录一下排查过程。
最后检查结果：非SQL性能导致的，原因是业务代码的BUG，导致每秒发送几千条SQL到数据库，导致CPU占用搞
排查过程如下
第一步，开启慢查询日志
一般情况，数据库CPU占用过高一般是SQL执行太慢，如数据量大，没有索引，语句不合理等问题导致。
慢查询日志是mysql本身就支持的功能，可以将超过指定时间的查询请求记录下来，方便排查故障
-- 开启慢查询日志
set global slow_query_log ='ON';
-- 开启慢查询日志的时间阀值，超过此时间被记录，，0代表记录所有,0.1代表100毫秒
set global long_query_time = 0.1;
-- 输出日志到文件或，【TABLE】为表，【FILE】为文件，【FILE,TABLE】为同时输出表和文件
set GLOBAL log_output = 'TABLE';
-- 查看慢查询相关变量是否生效
show VARIABLES like '%slow%';
-- 查看慢查询时间的设置（set之后要重新连接才会看到值的变化）
show VARIABLES like '%long_query_time%';
运行一段时间后，查看慢查询日志
-- sql_text为sql语句，我这边的Navicat显示为 BLOB,所有使用CONVERT函数转换为字符串显示
select a.*,CONVERT(sql_text USING utf8) from `mysql`.slow_log a
此时查看慢查询日志结果，没有数据！说明sql的执行都低于100ms，没有异常的SQL
image.png
第二步，开启一般日志，尝试找出异常SQL
SET GLOBAL general_log = 'ON'; -- 开启一般日志
SET GLOBAL slow_query_log = 'OFF'; -- 关闭慢查询日志
-- （一般日志存放在`mysql`.general_log表中）
-- 未了方便分析本次的问题，先清空【一般日志表】
truncate mysql.general_log;
-- 运行一段时间后，在关闭一般日志，此时表中只有最近的一般日志
SET GLOBAL general_log = 'OFF'; -- 开启一般日志
-- 查询日志，argument 为sql语句
select a.*,CONVERT(argument USING utf8) from mysql.general_log a
image.png
可以看到日志非常多，且在11:25:02执行了很多的日志，怀疑同一秒执行大量SQL,并发量太高导致CPU过高
-- 按秒 分组查询一下数量
select left(event_time,19),count(1) from mysql.general_log
group by left(event_time,19)
image.png
每秒执行7千~9千多条SQL,确诊了，并发量导致的CUP过高！！！
一般情况来说，没有慢查询日志，只是并发量高，说明SQL语句本身没有什么问题，工作情况也是正常的，只是业务代码调用的问题。但我们业务量平时没那么大，肯定不正常，因此需要继续排查
第三步，找出发送SQL的主机、端口、程序
mysql.general_log表中user_host字段就是SQL执行用户和连接的IP地址，可以直接定位到机器
但本次我们还需要定位到程序，所以使用mysql.general_log表的thread_id字段定位到执行的mysql进程ID(mysql内部的进程，非操作系统的进程)，连接information_schema.PROCESSLIST表查询进程信息
select * from (
select thread_id,count(1) cnt from mysql.general_log
group by thread_id
) a
left join information_schema.`PROCESSLIST` b on a.ID=b.thread_id
order by `HOST` DESC
图5
HOST字段就是连接数据库的客户端IP和端口，（ID等字段为NULL的则是已经关闭的连接，不用理会）
linux 上执行netstat命令查看TCP连接，通过grep命令搜索，HOST字段的值
注意：netstat命令的执行机器的IP，需匹配HOST字段（如图5的第一条数据，HOST为192.168.1.51:38610，则在机器192.168.1.51上面执行netsta命令来搜索）
# grep 命令搜索HOST字段，注意在192.168.1.51机器上执行
# 使用\|分隔多个字符串,表示OR的关系，匹配到其中的任意字符串则输出
netstat -apn|grep "192.168.1.51:38610\|192.168.1.51:38474\|192.168.1.51:38470"
image.png
可以看出这几个连接，都是一个PID为6834点java进程
此进程的3个连接连接了数据库，其中192.168.1.51:38474这个连接发送了5214条SQL，根据图5，此连接的Mysql进程ID为15
执行jcmd |grep 6834查看java进程
image.png
此时已定位到程序级别，此为我们的业务应用，因此可以继续往下，定位到代码级别
第四步，定位到代码
根据刚才的排查结果，选择Mysql进程ID为15的连接，看一下他执行的什么SQL
然后将SQL拿到JAVA程序的日志中去查找SQL，定位到JAVA程序的执行线程
select a.*,CONVERT(argument USING utf8) from mysql.general_log a
where thread_id=15
limit 1000
image.png
可以看出，基本是同样的SQL,只是参数可能不一样，经过人工分析，发现此连接多次发送同一个SQL，参数都是一样的，显然是不正常的（同一连接，同一SQL，短时间内发送多次）
抓取SQL，然后查询JAVA程序的日志，找到线程名称: nioEventLoopGroup-5-1
image.png
使用jstack命令dump线程堆栈，搜索刚刚的线程名称
# dump线程情况到tdump.log文件，方便查询，其中6834为java进程ID
jstack -l 6834 > tdump.log
此时在tdump.log文件中搜索nioEventLoopGroup-5-1，即可定位到代码行
最后检查业务代码后，确定是一个代码BUG，修复之后，CPU变为正常情况
（下图是问题解决之后，后期补充的图片，故没有我们的业务代码行号）
image.png
清理排查问题时临时配置、文件等
mysql：关闭慢查询日志和一般日志，清空日志表数据
set global slow_query_log ='OFF;
set global general_log='OFF';
truncate mysql.slow_log;
truncate mysql.general_log;
linux: 删除临时文件
rm -f tdump.log
网友评论