在使用 MySQL 的过程中会遇到各种瓶颈问题,常见的是 IO 瓶颈,但是有时候会出现服务器 CPU 使用率超过 100%,应用页面访问慢,登录服务器负载很高。而导致这个问题竟然是 MySQL 进程,按理说如果 MySQL 运行稳定,服务器的 CPU 资源并不会跑满,如果出现这个问题,初步可以断定,是 MySQL 实例中出现了问题 SQL。
CPU 占用过高常见原因:
如果是业务高并发引起,可以理解为一种业务繁忙的状态,有可能业务猛增,有可能是定期或者临时的并发窗口:
SQL 问题导致 CPU 使用率过高是最常见的现象,比如 group by、order by、join 等,这些很大程度影响 SQL 执行效率,从而占用大量的系统资源。
说了这么多常见原因,其实总结一句话来说就是现有系统的现有配置下的现有环境提供不了所需要的数据查询、分析、执行能力,针对这个问题,首先我们要发现问题的所在,就是说我们要准确的定位问题,然后针对问题进行优化,再考虑其他升级改造的事情。
光说不练假把式,接下来我们比划比划。
首先,搭建一套模拟环境,这里我让我的得力助手 DBdeployer 来帮我搭建一套模拟环境。
DBdeployer 是用 Go 语言实现的一款非常强大与高效的部署数据库环境的开源工具,我们完全可以用它来部署开发、测试环境。如果你对这个助手感兴趣,可以看我的另外一篇 Chat。
MySQL 安装部署:我是如何“秒级”部署 MySQL 集群
使用 DBdeployer 来部署一个单点 5.7.27 版本的 MySQL,并配置一个模拟 CPU 占比高的测试环境。
[root@localhost ~]# dbdeployer deploy single 5.7.27
Database installed in /dbdata/sandboxes/msb_5_7_27
run 'dbdeployer usage single' for basic instructions'
.. sandbox server started
创建测试表:
[root@localhost ~]# cd /dbdata/sandboxes/msb_5_7_27/
[root@localhost msb_5_7_27]# ./use
mysql [localhost:5727] {msandbox} ((none)) > use test
Database changed
mysql [localhost:5727] {msandbox} (test) > create table t_cpu(id int primary key auto_increment);
Query OK, 0 rows affected (0.39 sec)
插入大量模拟测试数据:
mysql [localhost:5727] {msandbox} (test) > insert into t_cpu values(),(),(),(),();
Query OK, 5 rows affected (0.06 sec)
Records: 5 Duplicates: 0 Warnings: 0
mysql [localhost:5727] {msandbox} (test) > insert into t_cpu select id+(select count(*) from t_cpu) from t_cpu;
Query OK, 5 rows affected (0.05 sec)
Records: 5 Duplicates: 0 Warnings: 0
......
......
mysql [localhost:5727] {msandbox} (test) > insert into t_cpu select id+(select count(*) from t_cpu) from t_cpu;
Query OK, 5242880 rows affected (1 min 8.84 sec)
Records: 5242880 Duplicates: 0 Warnings: 0
mysql [localhost:5727] {msandbox} (test) > select count(*) from t_cpu;
+----------+
| count(*) |
+----------+
| 10485760 |
+----------+
1 row in set (2.22 sec)
至此我们已经造了 10485760 条数据。
有 1000W+ 的数据量了,我们模拟一个业务场景,让 CPU 嗨(high)起来。
执行一个慢查询:
mysql [localhost:5727] {msandbox} (test) > select * from t_cpu order by rand() limit 1;
另外开一个会话,top 看看进程:
top - 15:21:20 up 33 days, 23:10, 3 users, load average: 0.38, 0.19, 0.21
Tasks: 202 total, 2 running, 200 sleeping, 0 stopped, 0 zombie
%Cpu(s): 23.3 us, 3.6 sy, 0.0 ni, 73.1 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem : 8173716 total, 2867684 free, 1059276 used, 4246756 buff/cache
KiB Swap: 2097148 total, 2097140 free, 8 used. 6761912 avAIl Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
32232 root 20 0 1443252 356688 11748 S 107.0 4.4 2:03.82 mysqld
296 root 20 0 67044 15588 1440 S 0.7 0.2 325:32.46 plymouthd
600 root 20 0 162032 2360 1580 R 0.3 0.0 0:04.21 top
1901 gnome-i+ 20 0 714116 22436 9168 S 0.3 0.3 98:46.20 gsd-color
1 root 20 0 191264 4192 2632 S 0.0 0.1 18:39.97 systemd
2 root 20 0 0 0 0 S 0.0 0.0 0:01.28 kthreadd
4 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kworker/0:0H
6 root 20 0 0 0 0 S 0.0 0.0 0:00.95 ksoftirqd/0
7 root rt 0 0 0 0 S 0.0 0.0 0:02.08 migration/0
8 root 20 0 0 0 0 S 0.0 0.0 0:00.00 rcu_bh
通过 top 我们发现有一个 32232 的进程使得 CPU 使用率已经超过了 100%。
接下来我们具体分析分析,究竟是什么导致 CPU 使用率达到 100%以上的。
[root@localhost ~]# free -m
total used free shared buff/cache available
Mem: 7982 1033 2801 40 4147 6604
Swap: 2047 0 2047
内存使用率还可以,应该不是内存影响导致的问题。
方法一:
top -H -p <mysqld 进程 id>
先通过 top 找出占用 CPU 使用率 100% 的 MySQL 进程 32232,在具体查看该进程下的线程情况。
[root@localhost ~]# top -H -p 32232
top - 15:30:32 up 33 days, 23:20, 3 users, load average: 0.18, 0.15, 0.18
Threads: 28 total, 1 running, 27 sleeping, 0 stopped, 0 zombie
%Cpu(s): 24.4 us, 3.2 sy, 0.0 ni, 72.4 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem : 8173716 total, 2867420 free, 1059520 used, 4246776 buff/cache
KiB Swap: 2097148 total, 2097140 free, 8 used. 6761668 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
32272 root 20 0 1443252 356688 11748 R 99.7 4.4 2:25.74 mysqld
32244 root 0 -20 1443252 356688 11748 S 3.7 4.4 0:08.68 mysqld
32236 root 20 0 1443252 356688 11748 S 1.7 4.4 0:01.45 mysqld
32237 root 20 0 1443252 356688 11748 S 1.7 4.4 0:01.43 mysqld
32238 root 20 0 1443252 356688 11748 S 1.3 4.4 0:01.43 mysqld
32239 root 20 0 1443252 356688 11748 S 1.3 4.4 0:01.42 mysqld
32241 root 20 0 1443252 356688 11748 S 0.3 4.4 0:00.75 mysqld
32250 root 20 0 1443252 356688 11748 S 0.3 4.4 0:00.98 mysqld
32232 root 20 0 1443252 356688 11748 S 0.0 4.4 0:00.31 mysqld
32233 root 20 0 1443252 356688 11748 S 0.0 4.4 0:00.00 mysqld
32234 root 20 0 1443252 356688 11748 S 0.0 4.4 0:00.23 mysqld
32235 root 20 0 1443252 356688 11748 S 0.0 4.4 0:00.31 mysqld
32240 root 20 0 1443252 356688 11748 S 0.0 4.4 0:00.74 mysqld
32242 root 20 0 1443252 356688 11748 S 0.0 4.4 0:00.72 mysqld
32243 root 20 0 1443252 356688 11748 S 0.0 4.4 0:00.69 mysqld
32247 root 20 0 1443252 356688 11748 S 0.0 4.4 0:00.16 mysqld
32248 root 20 0 1443252 356688 11748 S 0.0 4.4 0:00.23 mysqld
32249 root 20 0 1443252 356688 11748 S 0.0 4.4 0:00.02 mysqld
32251 root 20 0 1443252 356688 11748 S 0.0 4.4 0:08.04 mysqld
32252 root 20 0 1443252 356688 11748 S 0.0 4.4 0:00.00 mysqld
32253 root 20 0 1443252 356688 11748 S 0.0 4.4 0:00.00 mysqld
32254 root 20 0 1443252 356688 11748 S 0.0 4.4 0:00.00 mysqld
32255 root 20 0 1443252 356688 11748 S 0.0 4.4 0:00.00 mysqld
32256 root 20 0 1443252 356688 11748 S 0.0 4.4 0:00.18 mysqld
32257 root 20 0 1443252 356688 11748 S 0.0 4.4 0:00.03 mysqld
32258 root 20 0 1443252 356688 11748 S 0.0 4.4 0:00.00 mysqld
32259 root 20 0 1443252 356688 11748 S 0.0 4.4 0:00.00 mysqld
32260 root 20 0 1443252 356688 11748 S 0.0 4.4 0:00.00 mysqld
结果可以明显的看到 32272 这个线程的 CPU 使用率异常。
方法二:
pidstat -t -p <mysqld 进程 id> 1 5
先通过 top 找出占用 CPU 使用率 100% 的 MySQL 进程 32232,使用 pidstat 工具在具体查看该进程下的线程情况。
pidstat -t -p 32232 1 5
Average: UID TGID TID %usr %system %guest %CPU CPU Command
Average: 0 32232 - 85.00 12.60 0.00 97.60 - mysqld
Average: 0 - 32232 0.00 0.00 0.00 0.00 - |__mysqld
Average: 0 - 32233 0.00 0.00 0.00 0.00 - |__mysqld
Average: 0 - 32234 0.00 0.00 0.00 0.00 - |__mysqld
Average: 0 - 32235 0.00 0.00 0.00 0.00 - |__mysqld
Average: 0 - 32236 1.00 0.40 0.00 1.40 - |__mysqld
Average: 0 - 32237 0.80 0.40 0.00 1.20 - |__mysqld
Average: 0 - 32238 0.80 0.40 0.00 1.20 - |__mysqld
Average: 0 - 32239 1.00 0.20 0.00 1.20 - |__mysqld
Average: 0 - 32240 0.20 0.00 0.00 0.20 - |__mysqld
Average: 0 - 32241 0.00 0.20 0.00 0.20 - |__mysqld
Average: 0 - 32242 0.00 0.00 0.00 0.00 - |__mysqld
Average: 0 - 32243 0.00 0.00 0.00 0.00 - |__mysqld
Average: 0 - 32244 1.20 1.80 0.00 3.00 - |__mysqld
Average: 0 - 32247 0.00 0.00 0.00 0.00 - |__mysqld
Average: 0 - 32248 0.00 0.00 0.00 0.00 - |__mysqld
Average: 0 - 32249 0.00 0.00 0.00 0.00 - |__mysqld
Average: 0 - 32250 0.00 0.00 0.00 0.00 - |__mysqld
Average: 0 - 32251 0.00 0.00 0.00 0.00 - |__mysqld
Average: 0 - 32252 0.00 0.00 0.00 0.00 - |__mysqld
Average: 0 - 32253 0.00 0.00 0.00 0.00 - |__mysqld
Average: 0 - 32254 0.00 0.00 0.00 0.00 - |__mysqld
Average: 0 - 32255 0.00 0.00 0.00 0.00 - |__mysqld
Average: 0 - 32256 0.00 0.00 0.00 0.00 - |__mysqld
Average: 0 - 32257 0.00 0.00 0.00 0.00 - |__mysqld
Average: 0 - 32258 0.00 0.00 0.00 0.00 - |__mysqld
Average: 0 - 32259 0.00 0.00 0.00 0.00 - |__mysqld
Average: 0 - 32260 0.00 0.00 0.00 0.00 - |__mysqld
Average: 0 - 32272 80.00 9.80 0.00 89.80 - |__mysqld
结果可以明显的看到 32272 这个线程的 CPU 使用率异常。
在 MySQL 中看看当前连接是否有什么异常。
方法一:
mysql [localhost:5727] {msandbox} ((none)) > show full processlist;
+----+----------+-----------+------+---------+------+---------------------+---------------------------------------------+
| Id | User | Host | db | Command | Time | State | Info |
+----+----------+-----------+------+---------+------+---------------------+---------------------------------------------+
| 3 | msandbox | localhost | test | Query | 7 | Creating sort index | select * from t_cpu order by rand() limit 1 |
| 4 | msandbox | localhost | NULL | Query | 0 | starting | show full processlist |
+----+----------+-----------+------+---------+------+---------------------+---------------------------------------------+
2 rows in set (0.00 sec)
方法二:
mysql [localhost:5727] {msandbox} ((none)) > select * from information_schema.processlist;
+----+----------+-----------+------+---------+------+--------------+----------------------------------------------+
| ID | USER | HOST | DB | COMMAND | TIME | STATE | INFO |
+----+----------+-----------+------+---------+------+--------------+----------------------------------------------+
| 5 | msandbox | localhost | test | Query | 2 | Sending data | select * from t_cpu order by rand() limit 1 |
| 6 | msandbox | localhost | NULL | Query | 0 | executing | select * from information_schema.processlist |
| 4 | msandbox | localhost | NULL | Sleep | 1401 | | NULL |
| 3 | msandbox | localhost | test | Sleep | 1405 | | NULL |
+----+----------+-----------+------+---------+------+--------------+----------------------------------------------+
4 rows in set (0.00 sec)
参数说明:
MySQL 5.7 官方参考MySQL 8.0 官方参考
状态 |
含义 |
After create |
当线程使用函数创建表(包括内部临时表)最后阶段会出现这个状态,即使由于某些错误未能创建成功,也会标识该状态 |
altering table |
服务端正在执行 ALTER TABLE |
Analyzing |
线程正在计算 MyISAM 引擎表键值分布(例如 ANALYZE TABLE) |
checking permissions |
线程正在检查服务端是否有执行语句所需要的的权限 |
Checking table |
线程正在执行表的检查工作 |
cleaning up |
线程已经处理了一个命令,并准备释放内存并重置某些状态 |
Closing tables |
线程正在将表中修改的数据刷新到磁盘,同时正在关闭已经用完的表。是一个能很快完成的动作,如果持续完不成,需要确认磁盘空间是否用满或者磁盘使用的负载很高 |
converting HEAP to ondisk |
线程正在将内部临时表从 MEMORY 表转换为磁盘表 |
copy to tmp table |
线程正在执行一个 ALTER TABLE 语句。在创建一个新表,然后将老表记录复制到新表之前将是此状态 |
Copying to group table |
如果语句具有不同的条件 ORDER BY 和 GROUP BY 标准,则按组对行进行排序并将其复制到临时表 |
Copying to tmp table |
服务端正在复制到内存中的临时表 |
Copying to tmp table on disk |
服务端正在复制到磁盘上的临时表,临时结果集变的太大(参考 8.4.4 节,MySQL 内部临时表的使用),线程正在将临时表从内存更改为基于磁盘的格式来节省内存 |
Creating index |
线程正在执行 MyISAM 表的 ALTER TABLE ... ENABLE KEYS |
Creating sort index |
线程正在处理 SELECT 使用内部临时表 |
creating table |
线程正在创建表,包括创建临时表 |
Creating tmp table |
线程正在内存中或者磁盘上创建临时表,如果临时表在内存中创建之后转换到磁盘,状态为 Copying to tmp table on disk |
committing alter table to storage engine |
服务端完成 ALTER TABLE 并提交结果 |
deleting from main table |
服务端正在执行多表删除的第一部分,仅删除第一个表,保存列和偏移量用于删除其他表 |
deleting from reference tables |
服务端正在执行多表删除的第二部分,在其他表中删除匹配的行 |
discard_or_import_tablespace |
线程正在执行 ALTER TABLE ... DISCARD TABLESPACE or ALTER TABLE ... IMPORT TABLESPACE 语句 |
end |
结束状态,结束之前需要清理 ALTER TABLE, CREATE VIEW, DELETE, INSERT, SELECT, or UPDATE |
executing |
线程正在执行语句 |
Execution of init_command |
线程正在执行变量 init_command system 中的语句 |
freeing items |
线程执行了一条命令,在此期间完成了一些项目的资源释放,涉及如查询缓存,这个状态之后通常为 cleaning up |
FULLTEXT initialization |
服务端正在准备执行 natural-language 的全文检索 |
init |
该状态在 ALTER TABLE, DELETE, INSERT, SELECT, or UPDATE 初始化之前,服务端在该状态下会刷新二进制日志和 InnoDB 日志,清理查询缓存 |
Killed |
有发送了一个 KILL 线程的请求,下次终止前会检查 kill 标志位。MySQL 会在每次主循环中检查 kill 标志位,有时该线程并不能立马杀掉会保留短暂时间,如果该线程被其他线程锁定,那么 kill 会在锁释放后生效 |
logging slow query |
线程正在往慢日志中写入语句 |
login |
连接线程的初始状态,直到客户端成功完成验证 |
manage keys |
服务端开启或者关闭表的索引 |
Opening tables |
线程正在打开表,这应该是一个很快的过程,除非有些事情组织了打开表。例如 ALTER TABLE or a LOCK TABLE 会在结束前阻止打开表操作。再就是有必要检查 table_open_cache 参数的值设置是否足够大。 |
optimizing |
服务端正在对查询进行初始化优化 |
preparing |
查询优化状态 |
Purging old relay logs |
线程正在删除不需要的中继日志 |
query end |
处理完查询,在 freeing items 之前的状态 |
Receiving from client |
服务端正在读取客户端的包,该状态在 5.7.8 叫 Reading from.NET |
Removing duplicates |
查询正在使用 SELECT DISTINCT,这个过程 MySQL 在早期阶段无法完成,因此需要一个额外的阶段在把结果返回给客户端前需要删除重复行 |
removing tmp table |
线程在执行完 SELECT 后删除中间临时表,如果没有使用临时表,无该状态 |
rename |
重命名表 |
rename result table |
线程正在执行 ALTER TABLE 语句,创建一个新表,重命名新表替换老表 |
Reopen tables |
线程给表加锁,但是发现在获取表后发现表结构发生了变化。当释放锁,关闭表之后尝试重新打开表 |
Repair by sorting |
使用排序创建索引修复代码 |
preparing for alter table |
服务端正准备就地执行 ALTER TABLE |
Repair done |
线程已完成对 MyISAM 表的多线程修复 |
Repair with keycache |
创建索引缓存修复代码,比 Repair by sorting 慢的多 |
Rolling back |
线程在回滚事务 |
Saving state |
对于 MyISAM 表的修复和分析操作,线程将新表保存到.MYI 文件头,状态包含行数,AUTO_INCREMENT 计数器,键值分布之类的信息 |
Searching rows for update |
线程正在执行第一阶段查询未更新的数据,如果更新了索引所在行就会执行有该状态 |
Sending data |
线程正在读取和处理 SELECT 的行记录,发送给客户端,由于在这个状态下的操作会执行大量的磁盘访问(读),因此它通常是查询生命周期最长的状态。 |
Sending to client |
服务端正在给客户端发送包,在 5.7.8 该状态叫 Writing to net |
setup |
线程开始执行 ALTER TABLE 操作 |
Sorting for group |
线程正在做排序来满足 GROUP BY |
Sorting for order |
线程正在做排序来满足 ORDER BY |
Sorting index |
线程正在做索引页优化来使得 MyISAM 表优化操作期间有更高效的访问 |
Sorting result |
对于一个 SELECT 语句,类似不使用临时表的 Creating sort index |
starting |
语句执行的第一个状态 |
statistics |
服务端正在计算统计信息对一个查询创建执行计划,如果持续很长时间,服务端可能正在执行其他的操作 |
System lock |
线程调用了 mysqllocktables(),并且一直未更新状态,这个状态非常常见,可能有很多原因造成。 |
update |
线程正准备执行更新操作 |
Updating |
线程正在检索要更新的行并且更新行 |
updating main table |
服务端正在执行多表更新的第一部分,仅更新第一个表,保存列和偏移量用于更新其他表 |
updating reference tables |
服务端正在执行多表更新的第二部分,在其他表中更新匹配的行 |
User lock |
线程正在使用 GET_LOCK()请求或等待一个意向锁,对于 SHOW PROFILE 这个状态意味着线程请求锁(但是不等锁) |
User sleep |
线程正在调用 SLEEP() |
Waiting for commit lock |
FLUSH TABLES WITH READ LOCK 正在等待一个提交锁 |
Waiting for global read lock |
FLUSH TABLES WITH READ LOCK 正在等待全局读锁或者设置系统全局变量 read_only |
Waiting for tables |
线程得到一个表结构变化的通知,需要重新打开表获取新的表结构,该线程需要等待其他线程关闭该表。这个通知发生在另外的线程执行了 FLUSH TABLES,ALTER TABLE,RENAME TABLE,REPAIR TABLE,ANALYZE TABLE or OPTIMIZE TABLE |
Waiting for table flush |
线程正在执行 FLUSH TABLES,正在等待其他线程关闭他们的表,或者是线程得到一个表结构变化的通知,需要重新打开表获取新的表结构,该线程需要等待其他线程关闭该表。这个通知发生在另外的线程执行了 FLUSH TABLES,ALTER TABLE,RENAME TABLE,REPAIR TABLE,ANALYZE TABLE or OPTIMIZE TABLE |
Waiting for lock_type lock |
服务端正在等待 THR_LOCK 锁,或者是元数据锁定子系统的锁,其中 lock_type 是锁的类型,等待 THR_LOCK 锁(Waiting for table level lock),等待元数据锁(Waiting for event metadata lock、Waiting for global read lock、Waiting for schema metadata lock、Waiting for stored function metadata lock、Waiting for stored procedure metadata lock、Waiting for table metadata lock、Waiting for trigger metadata lock) |
Waiting on cond |
线程正在等待条件变为 true 的状态,没有具体可用的状态信息 |
Writing to net |
服务端正在网络中写包,在 5.7.8 中该状态叫 Sending to client |
通过结果我们可以大致看看如下的情况:
我们模拟的这个环境,show 的结果只有两条,结果非常明显,但是真正的生产环境不止这两条结果,通过这个查询结果,可以大致分析一下,并不能准确定位,准确的定位问题,需要进行后续的操作。
根据问题线程 id 定位 MySQL 中的 SQL:
mysql [localhost:5727] {msandbox} ((none)) > select a.user,a.host,a.db,b.thread_os_id,b.thread_id,a.id processlist_id,a.command,a.time,a.state,a.info from information_schema.processlist a,performance_schema.threads b where a.id = b.processlist_id and b.thread_os_id=32272;
+----------+-----------+------+--------------+-----------+----------------+---------+------+--------------+---------------------------------------------+
| user | host | db | thread_os_id | thread_id | processlist_id | command | time | state | info |
+----------+-----------+------+--------------+-----------+----------------+---------+------+--------------+---------------------------------------------+
| msandbox | localhost | test | 32272 | 32 | 7 | Query | 2 | Sending data | select * from t_cpu order by rand() limit 1 |
+----------+-----------+------+--------------+-----------+----------------+---------+------+--------------+---------------------------------------------+
1 row in set (0.00 sec)
根据问题线程 id 查看其他监控指标:
mysql [localhost:5727] {msandbox} (performance_schema) > select * from performance_schema.events_statements_current where thread_id in (select thread_id from performance_schema.threads where thread_os_id = 32272)G;
*************************** 1. row ***************************
THREAD_ID: 32
EVENT_ID: 11
END_EVENT_ID: 11
EVENT_NAME: statement/sql/select
SOURCE:
TIMER_START: 93213362472684000
TIMER_END: 93221551162460000
TIMER_WAIT: 8188689776000
LOCK_TIME: 993000000
SQL_TEXT: select * from t_cpu order by rand() limit 1
DIGEST: 83dacab9df764f11291d0001e420012e
DIGEST_TEXT: SELECT * FROM `t_cpu` ORDER BY `rand` ( ) LIMIT ?
CURRENT_SCHEMA: test
OBJECT_TYPE: NULL
OBJECT_SCHEMA: NULL
OBJECT_NAME: NULL
OBJECT_INSTANCE_BEGIN: NULL
MYSQL_ERRNO: 0
RETURNED_SQLSTATE: NULL
MESSAGE_TEXT: NULL
ERRORS: 0
WARNINGS: 0
ROWS_AFFECTED: 0
ROWS_SENT: 1
ROWS_EXAMINED: 20971521
CREATED_TMP_DISK_TABLES: 1
CREATED_TMP_TABLES: 1
SELECT_FULL_JOIN: 0
SELECT_FULL_RANGE_JOIN: 0
SELECT_RANGE: 0
SELECT_RANGE_CHECK: 0
SELECT_SCAN: 1
SORT_MERGE_PASSES: 0
SORT_RANGE: 0
SORT_ROWS: 1
SORT_SCAN: 1
NO_INDEX_USED: 0
NO_GOOD_INDEX_USED: 0
NESTING_EVENT_ID: NULL
NESTING_EVENT_TYPE: NULL
NESTING_EVENT_LEVEL: 0
1 row in set (0.00 sec)
ERROR:
No query specified
通过这个结果我们可以查看具体的 SQL,看到有使用临时表、使用了排序等信息。
CREATED_TMP_DISK_TABLES: 1
CREATED_TMP_TABLES: 1
SORT_ROWS: 1
SORT_SCAN: 1
查询慢日志情况:
mysql [localhost:5727] {msandbox} ((none)) > show variables like 'slow_query_log%';
+---------------------+------------------------------------------------------+
| Variable_name | Value |
+---------------------+------------------------------------------------------+
| slow_query_log | ON |
| slow_query_log_file | /dbdata/sandboxes/msb_5_7_27/data/localhost-slow.log |
+---------------------+------------------------------------------------------+
2 rows in set (0.01 sec)
在慢日志中查看慢 SQL:
cat /dbdata/sandboxes/msb_5_7_27/data/localhost-slow.log
# Time: 2021-08-17T09:11:06.768816Z
# User@Host: msandbox[msandbox] @ localhost [] Id: 5
# Query_time: 7.984593 Lock_time: 0.000184 Rows_sent: 1 Rows_examined: 20971521
SET timestamp=1629191466;
select * from t_cpu order by rand() limit 1;
可以很清楚的查到慢 SQL:
select * from t_cpu order by rand() limit 1
执行了有 7.984593 秒,返回结果为 1 行。
开启排查日志功能:
更改排查日志为 TABLE 方式,默认为 FILE 方式
mysql [localhost:5727] {msandbox} ((none)) > set global log_output='TABLE';
Query OK, 0 rows affected (0.00 sec)
mysql [localhost:5727] {msandbox} ((none)) > set global general_log=ON;
Query OK, 0 rows affected (0.00 sec)
执行慢查询:
select * from t_cpu order by rand() limit 1
查询排查日志内容:
mysql [localhost:5727] {msandbox} ((none)) > SELECT * from mysql.general_log ORDER BY event_time DESC;
+----------------------------+-----------------------------------+-----------+-----------+--------------+----------------------------------------------------------+
| event_time | user_host | thread_id | server_id | command_type | argument |
+----------------------------+-----------------------------------+-----------+-----------+--------------+----------------------------------------------------------+
| 2021-08-17 17:19:19.863849 | msandbox[msandbox] @ localhost [] | 2 | 0 | Query | SELECT * from mysql.general_log ORDER BY event_time DESC |
| 2021-08-17 17:18:45.017615 | msandbox[msandbox] @ localhost [] | 5 | 0 | Query | select * from t_cpu order by rand() limit 1 |
+----------------------------+-----------------------------------+-----------+-----------+--------------+----------------------------------------------------------+
2 rows in set (0.00 sec)
结果显示了刚才的慢 SQL,还有我们查询排查日志结果的 SQL,其实慢日志会记录所有的 SQL,我们只能通过这个日志内容查看一些不太正常的 SQL,比如大量相同的 SQL;定期出现的 SQL;分析一个特定的事务等,排查日志模式非常影响 MySQL 性能,慎用。
关闭排查日志模式:
mysql [localhost:5727] {msandbox} ((none)) > set global general_log=OFF;
Query OK, 0 rows affected (0.05 sec)
mysql [localhost:5727] {msandbox} ((none)) > truncate table mysql.general_log;
Query OK, 0 rows affected (0.05 sec)
到目前为止,介绍了几种常用的 MySQL 占用 CPU 过高的定位方法,你是否掌握了。找到问题了,接下来,我们就需要看看如何优化这个问题了。
前面介绍了几种常用的排查 MySQL 占用 CPU 过高问题排查的方法,那么当我们遇到问题了,如何解决,如何优化呢?
首先,最暴力的方法,如果我们确定这个 SQL 可以被干掉,我们直接 kill id 即可。id 为 process 的 id。
其次,具体问题具体分析,如何排查问题是如何发生的,根据不同的问题作出相应的解决方法。
1. 优化 SQL,从逻辑上优化 SQL,降低 SQL 复杂度,降低 MySQL 执行成本。
2. 对 where、join、max()、min()、order by、group by 等子句用到的字段,创建相应的索引。
3. 二级索引的正确使用。
4. 参数优化:
1. 检查 MySQL 连接数当前使用是否超过限制
如果超出限制,而且之前的连接没有得到释放,那新的连接肯定会连接不到,造成连接延迟,影响效率。
2. MySQL 的 timeout 参数设置问题
这里介绍两个参数:
交互连接即在 mysql_real_connect() 函数中使用了 CLIENT_INTERACTIVE 选项。简单说,就是通过 MySQL 客户端连接数据库是交互式连接,通过 jdbc 连接数据库是非交互式连接。在 MySQL 默认设置下,当一个连接的空闲时间超过 8 小时后,当业务出现了高峰期,肯定会造成有太多的 TCP 连接没关闭,数据库连接数肯定会不够用。从而会产生 CPU 占用过高,服务器告警等问题。因 EPG 的一个访问一次对数据库操作量不大,查询完数据就完成 ok 了,wait_timeout 设置在 120s 内就可以了。
在 MySQL 的官网了解到修改以上两个参数必须修改 interactive_timeout。如果修改 interactive_timeout,则 wait_timeout 也发生变化,如果只修改 wait_timeout,不生效。
3. 老生常谈,规范的 SQL 也是非常必要的
好了,至此我们基本学习完本节内容了,内容比较多,当然也有不足之处,欢迎朋友们指正补充。