CPU、负载、磁盘同时飙升的问题分析
线上的一个问题分析过程
上周五下午的时候，线上的一个服务器出了一个报警，报警内容是CPU利用率大于80%，持续时间五分钟。
于是我上去看了一眼监控，监控中可以看到的数据如下：
从监控数据中心不难看出，15:30分左右出现了一个CPU利用率的激增，服务器的负载也飙升比较严重，除此之外，磁盘的使用率已经达到了100%，看起来服务器的状态已经相当危险了。
分析解决过程：
1、使用top -c命令看一下当前服务器的进程：
1top - 16:05:37 up 43 days, 23:47, 2 users, load average: 29.02, 27.31, 23.73
2Tasks: 245 total, 1 running, 244 sleeping, 0 stopped, 0 zombie
3Cpu0 : 16.7%us, 8.3%sy, 0.0%ni, 0.0%id, 75.0%wa, 0.0%hi, 0.0%si, 0.0%st
4Cpu1 : 50.0%us, 50.0%sy, 0.0%ni, 0.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
5Cpu2 : 10.0%us, 0.0%sy, 0.0%ni, 0.0%id, 90.0%wa, 0.0%hi, 0.0%si, 0.0%st
6Cpu3 : 18.2%us, 0.0%sy, 0.0%ni, 0.0%id, 81.8%wa, 0.0%hi, 0.0%si, 0.0%st
7Cpu4 : 45.5%us, 54.5%sy, 0.0%ni, 0.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
8Cpu5 : 8.3%us, 8.3%sy, 0.0%ni, 8.3%id, 75.0%wa, 0.0%hi, 0.0%si, 0.0%st
9Cpu6 : 8.3%us, 16.7%sy, 0.0%ni, 66.7%id, 8.3%wa, 0.0%hi, 0.0%si, 0.0%st
10Cpu7 : 46.2%us, 53.8%sy, 0.0%ni, 0.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
11Mem: 32883164k total, 29203540k used, 3679624k free, 350152k buffers
12Swap: 0k total, 0k used, 0k free, 14591920k cached
13
14 PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
1517123 mysql 20 0 1158m 909m 29m S 100.9 2.8 13430:24 /usr/local/mysql/bin/mysqld --defaults-file=/data/mysql_4323/my_4323.cnf --basedi
1622952 mysql 20 0 1254m 934m 29m S 100.9 2.9 10626:32 /usr/local/mysql/bin/mysqld --defaults-file=/data/mysql_4319/my_4319.cnf --basedi
1726715 mysql 20 0 814m 688m 29m S 100.9 2.1 2191:05 /usr/local/mysql/bin/mysqld --defaults-file=/data/mysql_4325/my_4325.cnf --basedi
1812827 mysql 20 0 1394m 1.0g 29m S 50.5 3.3 6889:10 /usr/local/mysql/bin/mysqld --defaults-file=/data/mysql_4402/my_4402.cnf --basedir
1929954 mysql 20 0 5740m 2.9g 29m S 42.0 9.2 5506:32 /usr/local/mysql/bin/mysqld --defaults-file=/data/mysql_4802/my_4802.cnf
2017349 root 20 0 15152 1460 1012 R 8.4 0.0 0:00.64 top -c
2117497 root 20 0 137m 7420 2320 S 8.4 0.0 0:01.81 python /usr/bin/dstat -cdlmrtn --disk-util --top-io --top-latency 1
22 1 root 20 0 19352 1624 1308 S 0.0 0.0 0:00.94 /sbin/init
23 2 root 20 0 0 0 0 S 0.0 0.0 0:00.00 [kthreadd]
24 3 root RT 0 0 0 0 S 0.0 0.0 2:20.51 [migration/0]
25 4 root 20 0 0 0 0 S 0.0 0.0 1:14.33 [ksoftirqd/0]
26 5 root RT 0 0 0 0 S 0.0 0.0 0:00.00 [stopper/0]
27 6 root RT 0 0 0 0 S 0.0 0.0 0:02.38 [watchdog/0] 从结果上看，应该是MySQL的进程占用了大量的CPU，然后当前的负载已经飙升到29倍了，服务器的压力相当大了。
2、询问业务方有没有进行相关操作
从上面的实例中，找到了几个实例使用方负责人，咨询了几个业务方当前是否有相关活动或者特殊操作，得到的结果是没有进行。
3、从磁盘的状态来看，磁盘的IO负载也是满的，是否产生了大量的慢日志，导致磁盘负载激增？
于是我查询了所有实例的慢日志文件增长情况，发现慢日志的几乎没有什么增长。这个问题就比较奇怪了。
4、使用iotop命令查看当前的使用IO的进程到底是哪些。得到的结果如下：
1Total DISK READ: 77.33 M/s | Total DISK WRITE: 3.18 M/s
2 TID PRIO USER DISK READ DISK WRITE SWAPIN IO> COMMAND
327988 be/4 mysql 1559.65 K/s 0.00 B/s 0.00 % 98.08 % mysqld --defaults-file=/data/mysql_4402/m~ata/mysql_4402/tmp/mysql.sock --port=4402
430074 be/4 mysql 2.90 M/s 0.00 B/s 0.00 % 95.61 % mysqld --defaults-file=/data/mysql_4802/my_4802.cnf
531599 be/4 mysql 2.72 M/s 0.00 B/s 0.00 % 95.16 % mysqld --defaults-file=/data/mysql_4802/my_4802.cnf
630060 be/4 mysql 3.05 M/s 0.00 B/s 0.00 % 95.14 % mysqld --defaults-file=/data/mysql_4802/my_4802.cnf
730088 be/4 mysql 2.91 M/s 0.00 B/s 0.00 % 95.14 % mysqld --defaults-file=/data/mysql_4802/my_4802.cnf
830061 be/4 mysql 3.54 M/s 0.00 B/s 0.00 % 95.12 % mysqld --defaults-file=/data/mysql_4802/my_4802.cnf
930071 be/4 mysql 3.43 M/s 0.00 B/s 0.00 % 95.06 % mysqld --defaults-file=/data/mysql_4802/my_4802.cnf
1031585 be/4 mysql 3.03 M/s 0.00 B/s 0.00 % 95.02 % mysqld --defaults-file=/data/mysql_4802/my_4802.cnf
1130084 be/4 mysql 3.69 M/s 0.00 B/s 0.00 % 95.00 % mysqld --defaults-file=/data/mysql_4802/my_4802.cnf
1230067 be/4 mysql 4.21 M/s 0.00 B/s 0.00 % 94.97 % mysqld --defaults-file=/data/mysql_4802/my_4802.cnf
1330068 be/4 mysql 3.91 M/s 0.00 B/s 0.00 % 94.91 % mysqld --defaults-file=/data/mysql_4802/my_4802.cnf
1430075 be/4 mysql 3.26 M/s 0.00 B/s 0.00 % 94.89 % mysqld --defaults-file=/data/mysql_4802/my_4802.cnf
1530065 be/4 mysql 3.61 M/s 0.00 B/s 0.00 % 94.89 % mysqld --defaults-file=/data/mysql_4802/my_4802.cnf
1631593 be/4 mysql 3.78 M/s 0.00 B/s 0.00 % 94.88 % mysqld --defaults-file=/data/mysql_4802/my_4802.cnf
1730087 be/4 mysql 3.90 M/s 0.00 B/s 0.00 % 94.85 % mysqld --defaults-file=/data/mysql_4802/my_4802.cnf
1830091 be/4 mysql 3.00 M/s 0.00 B/s 0.00 % 94.80 % mysqld --defaults-file=/data/mysql_4802/my_4802.cnf
1930081 be/4 mysql 3.48 M/s 0.00 B/s 0.00 % 94.76 % mysqld --defaults-file=/data/mysql_4802/my_4802.cnf
2031596 be/4 mysql 4.23 M/s 0.00 B/s 0.00 % 94.76 % mysqld --defaults-file=/data/mysql_4802/my_4802.cnf
2130077 be/4 mysql 4.36 M/s 0.00 B/s 0.00 % 94.71 % mysqld --defaults-file=/data/mysql_4802/my_4802.cnf
2231584 be/4 mysql 3.91 M/s 0.00 B/s 0.00 % 94.65 % mysqld --defaults-file=/data/mysql_4802/my_4802.cnf
2330085 be/4 mysql 3.76 M/s 0.00 B/s 0.00 % 94.64 % mysqld --defaults-file=/data/mysql_4802/my_4802.cnf
2430066 be/4 mysql 6.12 M/s 0.00 B/s 0.00 % 92.05 % mysqld --defaults-file=/data/mysql_4802/my_4802.cnf
2526943 be/4 mysql 30.58 K/s 7.65 K/s 0.00 % 6.64 % mysqld --defaults-file=/data/mysql_4801/m~ata/mysql_4801/tmp/mysql.sock --port=4801
26 977 be/3 root 0.00 B/s 0.00 B/s 0.00 % 5.06 % [jbd2/vdb1-8] 仿佛看到了想要的结果。我们可以看到，4802这个实例以几乎70M/s的读取速率在对磁盘进行访问，这个明显是不正常的，于是我立即联系相关业务方确认是否有正在进行的操作(其实，第2步中恰好一遗漏掉了这个实例)。得到的结果是他们正在对一个log库进行数据统计分析，所以将一个月的log进行了一下查询，同时反馈的信息还有，这个查询现在已经过了一个小时了，还没有得到结果。
5、连接到相关实例上，使用show processlist命令查看当前实例的连接情况。
1+---------+-------+--------------------------------------------------------+-
2| Command | Time | State |
3+---------+-------+--------------------------------------------------------+-
4| Connect | 22784 | Waiting for master to send event |
5| Connect | 1 | Slave has read all relay log; waiting for more updates |
6| Connect | 1 | Waiting for an event from Coordinator |
7| Connect | 2 | Waiting for an event from Coordinator |
8| Connect | 22 | Waiting for an event from Coordinator |
9| Connect | 13087 | Waiting for an event from Coordinator |
10| Connect | 22784 | Waiting for an event from Coordinator |
11| Connect | 22784 | Waiting for an event from Coordinator |
12| Connect | 22784 | Waiting for an event from Coordinator |
13| Connect | 22784 | Waiting for an event from Coordinator |
14| Sleep | 92 | |
15| Query | 2966 | Sending data |
16| Query | 2966 | Sending data |
17| Query | 2966 | Sending data |
18| Query | 2966 | Sending data |
19| Query | 2966 | Sending data |
20| Query | 2966 | Sending data |
21| Query | 2966 | Sending data |
22| Query | 2966 | Sending data |
23| Query | 2966 | Sending data |
24| Query | 2966 | Sending data |
25| Query | 2966 | Sending data |
26| Query | 2966 | Sending data |
27| Query | 2966 | Sending data |
28| Query | 2966 | Sending data |
29| Query | 2966 | Sending data |
30| Query | 2966 | Sending data |
31| Query | 2966 | Sending data |
32| Query | 2966 | Sending data |
33| Query | 2966 | Sending data |
34| Query | 2966 | Sending data |
35| Query | 2966 | Sending data |
36| Query | 0 | starting |
37| Sleep | 3 | |
38+---------+-------+--------------------------------------------------------+-可以看到，有很多个查询都卡在了sending data这一步，而且卡顿时间已经快一个小时了。
6、无情kill一些线程，尝试解决问题。
1mysql--root@localhost:mysql.sock:(none) 16:22:51>>kill 85228;
2Query OK, 0 rows affected (0.00 sec)
3
4mysql--root@localhost:mysql.sock:(none) 16:23:34>>kill 85229;
5Query OK, 0 rows affected (0.00 sec)
6
7mysql--root@localhost:mysql.sock:(none) 16:23:34>>kill 85230;
8Query OK, 0 rows affected (0.00 sec)
9
10mysql--root@localhost:mysql.sock:(none) 16:23:34>>kill 85231;
11Query OK, 0 rows affected (0.00 sec)
12
13mysql--root@localhost:mysql.sock:(none) 16:23:34>>kill 85232;
14Query OK, 0 rows affected (0.00 sec)
15
16mysql--root@localhost:mysql.sock:(none) 16:23:35>>system top -c
17top - 16:23:45 up 44 days, 5 min, 3 users, load average: 20.70, 24.41, 24.65
18Tasks: 250 total, 1 running, 249 sleeping, 0 stopped, 0 zombie
19Cpu(s): 20.1%us, 21.5%sy, 0.0%ni, 27.6%id, 30.8%wa, 0.0%hi, 0.0%si, 0.0%st
20Mem: 32883164k total, 28795988k used, 4087176k free, 350284k buffers
21Swap: 0k total, 0k used, 0k free, 14178684k cachedkill了几个MySQL的连接线程之后，可以看到，负载已经从29倍变成了20倍，收获还是比较明显的。
到这里，跟业务方明确反馈，现在服务器出现异常情况，需要对刚才的查询进行强制处理，业务方也表示理解，对不当操作表示了歉意。
然后使用kill线程的方法，对其他的链接线程进行了处理，最终得到的监控图如下。
7、处理结果
可以看到，CPU、负载和磁盘使用率发生了一个比较明显的下降。
一点反思：
0、本例子中，CPU的升高和负载的升高其实是由磁盘的IO打满导致其他系统任务出现等待。当解决了磁盘上的问题之后，CPU和负载问题会直接消失。
1、在解决问题的过程中需要全称记录现场日志。方便后续还原问题。
之所以能够写出这一篇文章，其实也是由于我有截取日志的习惯，所以提示大家在发现问题的时候，一定要保留现场，即使自己不能解决，也能够让其他人帮助自己进行分析和处理。
2、解决问题的过程中，需要不断和业务方保持联系，以免对业务产生影响而不自知，导致解决问题的过程中出现更大的问题。
3、kill MySQL的连接线程并不是一个最好的办法，只是笔者在当时处理该问题的一个办法，如果这个访问用户引入了连接池，当你kill掉连接的时候，又重新发起新的连接来请求数据库数据。那么kill是不能根除这个问题的。可能对防火墙设置相关的过滤策略会更好。
4、最后，不要怕遇到问题，出现不可控制的问题的时候，才是学习的最好素材。
本文参与 腾讯云自媒体同步曝光计划，分享自微信公众号。
原始发表：2019-12-09，如有侵权请联系 cloudcommunity@tencent.com 删除
评论
登录后参与评论
推荐阅读
相关产品与服务
云数据库 SQL Server
腾讯云数据库 SQL Server （TencentDB for SQL Server）是业界最常用的商用数据库之一，对基于 Windows 架构的应用程序具有完美的支持。TencentDB for SQL Server 拥有微软正版授权，可持续为用户提供最新的功能，避免未授权使用软件的风险。具有即开即用、稳定可靠、安全运行、弹性扩缩等特点。