MySQL运维系列 之 CPU瓶颈故障案例分析

很久没发布文章了，并不是春哥不爱学习了，而是最近我们碰到了一些瓶颈没有解决，心有不甘的苦苦探索着

现在容我给大家分析一起新鲜出炉热乎乎滚烫烫的故障案例

在分析案例前，据我们故障报告得到的数据分析显示，最近2年出现的故障

• 80%来自硬件，20%来自压力瓶颈（因为瓶颈分析和解除瓶颈做的及时）

• 压力瓶颈中：80%来自disk（IO压力、磁盘空间）、20%来自CPU

今天主要聊聊cpu相关的问题

一、背景

• 环境

1.系统：Centos 6
2.内核：2.6.32-504.23.4.el6.x86_64
3.MySQL： 5.7.22

• 案发经过

凌晨做了一次数据库升级，读写从old master 切到了 new master，一切顺利

然后，到早高峰的时候，接到告警，紧张刺激的一天开始了

告警内容如下：

1. slow query 上涨至 10000/s , 平时 5/s
2. thread running 上涨至 169/s , 平时 10/s
3. too many connection 频繁
4. cpu 使用率上涨至 99% ， 平时 20-30%
5. 服务器响应变慢

二、故障降级

根据以上报警信息，第一时间查看slow query

1. 没有发现特殊的慢查询（扫描行数多、执行特别慢等），其余基本都是在100ms ~ 500ms
2. java每次读写的时候，有带有大量的 select @@session.tx_read_only。
3. 正常情况下，这样的查询是不会慢的，但是为了先解决链接数多的问题，我们让业务调整了链接参数：useLocalSessionState=true

可是剧情并没有像我们想的那样发展，虽然有所好转（TMC从持续告警降低到间歇性告警），也就是问题并没有彻底解决

接下来，我们能做的就是用DCT（数据库配置管理系统）将master上的查询分流一部分（60%）到slave上来

好消息是： Master 压力降低，slow 降低，各种指标恢复正常

坏消息是： Slave 压力瞬间就起来了，然后表现的症状跟之前的Master一模一样

再接下来，我们就继续分流，再分60%的量到另外一台slave

最终，Master和slave 系统各指标稳定了下来

好了，现在我们可以有时间来回顾和分析下刚刚发生的一连串事件

• 案件名称：cpu暴走事件

cpu的sys 使用率非常高

1. 线索1： 数据库升级
2. 线索2： 高峰期流量大
3. 线索3： 数据没有预热

• 临时控制：流量迁移

• 后续方案：

1. 继续追踪，找到根本原因

   1.1 保留现场，寻找蛛丝马迹

   1.2 模拟案发，重现问题

2. 回退版本

   数据库降级方案：并不太好做，可能存在的问题更多，不到万不得已，我们不愿意这样尝试。

三、寻找真相

• 当cpu飙高的时候，究竟发生了什么

使用perf top 去看看哪些函数调用非常多，结果又遇到了另外一个坑，机器直接hang住，不久就挂了

直接上图

对呀，正所谓祸不单行就是这么个道理哈

所以，接下来，我们的解题思路变成了这样

1. 解决perf 导致linux挂掉的情况
2. 解决cpu高的瓶颈
   2.1 线下场景还原： 保留了案发当时的slow sql ， 使用mysqlslap模拟并发sql，将压力打在测试库上
   2.2 线上场景还原： 使用tcpcopy，在线引流将真实压力打在测试库上

四、测试

4.1 测试用例一

先解决perf的问题，因为有了它，才可能知道坑在哪里

• 模拟问题，跑perf的时候让linux挂掉的场景复现

1.没有mysql进程，perf没问题
2.有mysql进程，只有查询，perf没问题
3.有mysql进程，模拟写入，perf没问题
4.有mysql进程，复制同步，有查询，但是master模拟单一sql写入，perf没问题
5.有mysql进程，复制同步，有查询，复制的sql来自生产环境，perf每次执行，必定crash


结论：perf + MySQL replicate  = crash  ， 此场景每次必定复现

• perf为什么会挂

google了一圈后，发现一丢丢可操作的点，大致的意思是说： perf在centos 2.6.32的内核中有bug

链接如下：

1. https://access.redhat.com/solutions/1310693

2. https://access.redhat.com/solutions/1992703

内核版本跟我们的版本一样

于是，我们也没想要去看是什么因素导致perf在linux 2.6.32 中触发了bug，我们所幸直接将系统升级到 centos 7来看看问题是否可以重现

再次经过上述的测试发现：perf + MySQL replicate 没问题了，现在基本断定是perf + kernel 2.6.32 遇到相关bug了

不过，既然centos 7上的perf可以用，那么我们所幸在centos 7上复现 cpu高的问题

4.2 线下场景还原： 保留了案发当时的slow sql ， 使用mysqlslap模拟并发sql，将压力打在测试库上

• 单一 slow sql 测试 + 多条 slow sql 混合测试

SQL语句：

1. SELECT loupan_page_use,last_update FROM mp_loupan_tags WHERE id=233598838
2. SELECT loupan_page_use,last_update FROM mp_loupan_tags WHERE loupan_page_use = '1' AND mp_type = '1' AND loupan_id in ('431819','417907','431337','413800','431650','215981','435463','429181','240518','411871') ORDER BY display_seq ASC,last_update DESC LIMIT 500 OFFSET 0
3. SELECT loupan_id,last_update_time FROM grade WHERE loupan_id = '257809' AND status = '2' ORDER BY last_update_time DESC
4. SELECT loupan_page_use,last_update FROM mp_loupan_tags WHERE loupan_page_use = '1' AND mp_type = '1' AND loupan_id in ('263126','426580','263275','263298','411670') ORDER BY display_seq ASC,last_update DESC LIMIT 500 OFFSET 0
5. SELECT loupan_page_use,last_update FROM mp_loupan_tags WHERE loupan_page_use = '1' AND mp_type = '1' AND loupan_id in ('215981','411875','418474','416128','298380','411083','418262','412631','237083','415427','411644','437897','415833','434643','400752','432261','416437','438013','436612','400947','431337','418277','413800','435463','250211','240518','417907','439605','435269','430827','430420','418785','417828','416877','416624','416376','416241') ORDER BY display_seq ASC,last_update DESC LIMIT 500 OFFSET 0
6. SELECT house_type_id,last_update FROM loupan_images WHERE ((loupan_id=261547) AND (house_type_id="161236") AND (category=10)) ORDER BY rank DESC,last_update DESC,category ASC,id DESC LIMIT 100 OFFSET 0
7. SELECT loupan_id,last_update FROM loupan_images WHERE category = '7' AND loupan_id = '260933' AND ((flag in (0,1) and 1)) ORDER BY rank DESC,last_update DESC,id DESC LIMIT 200 OFFSET 0
8. SELECT loupan_id,last_update FROM loupan_images WHERE ((loupan_id=425002) AND (category=8)) ORDER BY rank DESC,last_update DESC,category ASC,id DESC LIMIT 500 OFFSET 0
9. SELECT loupan_page_use,last_update FROM mp_loupan_tags WHERE loupan_page_use = '1' AND mp_type = '1' AND loupan_id in ('431994','251016','425992','383237','252069','435523','414367','438602','418001','411606','242004','435999','414054','437995','415811','414771','439970','251996','411782','416632','417611','247610','298398','251870','436767','417374','241933','241801','250763','432331') ORDER BY display_seq ASC,last_update DESC LIMIT 500 OFFSET 0 
10. SELECT loupan_page_use,last_update FROM mp_loupan_tags WHERE loupan_page_use = '1' AND mp_type = '1' AND loupan_id in ('414321','401273','414409','256987','239486','399951','411857','431038','418800','409145','419135','418756','438468') ORDER BY display_seq ASC,last_update DESC LIMIT 500 OFFSET 0
11. SELECT loupan_page_use,last_update FROM mp_loupan_tags WHERE loupan_page_use = '1' AND mp_type = '1' AND loupan_id in ('413112','413151','410298','410283','439916','245708','241716','241812','242072','241877','241890','241797','245710','242082','418996','413118','257403','413216','401112','412289') ORDER BY display_seq ASC,last_update DESC LIMIT 500 OFFSET 0
12. SELECT loupan_page_use,last_update FROM mp_loupan_tags WHERE loupan_page_use = '1' AND mp_type = '1' AND loupan_id in ('439605','429377','252408','400752','248666','401202','401143','249507','250236','415528','247559','244521','394528','435679','264022','383196','246045','241059','414997','250767','251984','411968','247811','414493','409271','240435','401207','417573','411913','400886','251003','240528','249072','253033','249420','240837','249433','428320','389816','416080','249171','414844','410203','240028','416743','416048','417677','416666','249162','264101') ORDER BY display_seq ASC,last_update DESC LIMIT 500 OFFSET 0
13. SELECT loupan_page_use,last_update FROM mp_loupan_tags WHERE loupan_page_use = '1' AND mp_type = '1' AND loupan_id in ('415666','416121','417661','431364','419055','257898','417384','424463','417831','429187','416745','417962','257940','258046','414746','416471','435536','431355','257873','414545','417836','257845','438835','417947','437315','433201','432220','432046','432027','427731','423631','423298','420072') ORDER BY display_seq ASC,last_update DESC LIMIT 500 OFFSET 0
14. SELECT loupan_page_use,last_update FROM mp_loupan_tags WHERE loupan_page_use = '1' AND mp_type = '1' AND loupan_id in ('437148','258865','417140','416114','432010','258825','258829','426077','258805','258813','405587','405958','258774','426808') ORDER BY display_seq ASC,last_update DESC LIMIT 500 OFFSET 0
15. SELECT loupan_page_use,last_update FROM mp_loupan_tags WHERE loupan_page_use = '1' AND mp_type = '1' AND loupan_id in ('438956','436725','409405','428214','438718','439063','439199','439619','432314','415807','437725','418984','439932','432333','439773','429497','439609','415674','428729','434976','237609','438566','416101','426292','426251','427909','432703','435501','418548','438644') ORDER BY display_seq ASC,last_update DESC LIMIT 500 OFFSET 0
16. SELECT loupan_page_use,last_update FROM mp_loupan_tags WHERE loupan_page_use = '1' AND mp_type = '1' AND loupan_id in ('416298','252892','253165','436887','428371','251816','229854','432686','418173','411578','416559','253142','298034','240938','240864','409266','431641','426850','432043','435222','428298','229366','430458','237272','298020','410783','431129','249778','240946','251629') ORDER BY display_seq ASC,last_update DESC LIMIT 500 OFFSET 0
17. SELECT loupan_page_use,last_update FROM mp_loupan_tags WHERE loupan_page_use = '1' AND mp_type = '1' AND loupan_id in ('237961','246760','245148','400531','411079','426430','252039','238153','239570','237975','414382','415405','430961','430002','250845','416659','237984','438604','416113','437075','418631','431147','245171','416380','246418','411336','400697','418718','239952','238007','238017','417838','238031','252181','250326','240911','414506','246970','248340','241266','241018','251248','241011','238054','240459','251286','239843','251255','438525','237986') ORDER BY display_seq ASC,last_update DESC LIMIT 500 OFFSET 0
18. SELECT loupan_id,last_update FROM loupan_images WHERE ((loupan_id=414637) AND (house_type_id="238264") AND (category=3)) ORDER BY rank DESC,last_update DESC,category ASC,id DESC LIMIT 100 OFFSET 0
19. SELECT loupan_id,last_update FROM loupan_images WHERE ((loupan_id=417843) AND (category=4)) ORDER BY rank DESC,last_update DESC,category ASC,id DESC LIMIT 500 OFFSET 0
20. SELECT loupan_id,last_update FROM mp_loupan_tags WHERE loupan_page_use = '1' AND mp_type = '1' AND loupan_id in ('417138','416488','417434','417118','414536','431886','410367','399936','414636','435391') ORDER BY display_seq ASC,last_update DESC LIMIT 500 OFFSET 0
21. SELECT category,last_update FROM loupan_images WHERE ((loupan_id="402011") AND (category=3)) ORDER BY rank DESC,last_update DESC,category ASC,id DESC LIMIT 5 OFFSET 0

结果cpu压力果然上涨了，且sys cpu非常高，跟我们的故障场景类似

SQL序号 dstat结果 1. usr:18 sys:3 idle:78 2. usr:8 sys:87 idle:5 4. usr:8 sys:86 idle:6 n. … … 20. usr:7 sys:88 idle:5

然后用perf top -g 追踪统计下发生了啥

看到的确是内核态的函数比较多啊，但是这些是干啥的，并不知道哇，只知道自旋锁是瓶颈哇

如果这个没法统计，那我只能用pstack去碰碰运气，追踪下当时压力大的时候的点发生了什么？

 1 ib_wqueue_timedwait(ib_wqueue_t*,
 1 lock_wait_timeout_thread
 1 timer_notify_thread_func
 6 os_event::timed_wait(timespec
 6 os_event::wait_time_low(unsigned
 6 pthread_cond_timedwait@@GLIBC_2.3.2
55 Field_timestampf::get_date_internal(st_mysql_time*)
55 Time_zone_system::gmt_sec_to_TIME(st_mysql_time*,

似乎发现了什么，没错，就是时区转换函数，从google得之，在有timestamp的场景下，如果MySQL的time_zone=system,会调用linux的时区函数，从而内核态的cpu使用率高

timestamp的场景包括很多，什么情况下会导致sys cpu飙高呢，我们不妨测试一把：

• 链接并发数小于cpu总核数 , sql语句综合
• 链接并发数大于cpu总核数 , sql语句综合

得到的最后结论是：

• sys cpu高，只跟结果集包含timestamp有关系,跟查询条件是否有timestamp无关
• 使用time_zone=’+8:00’ 来替换 time_zone=’system’ ，可以大大降低sys cpu的使用率

最后，我们再针对一开始的21种语句使用 time_zone=’+8:00’ 来模拟一遍

SQL序号 time_zone=system time_zone=’+8:00’ 1. usr:18 sys:3 idle:78 usr:19 sys:3 idle:77 2. usr:8 sys:87 idle:5 usr:92 sys:1 idle:6 4. usr:8 sys:86 idle:6 usr:93 sys:2 idle:4 n. … … 20. usr:7 sys:88 idle:5 usr:90 sys:2 idle:7

很明显，问题得到解决

4.3 线下场景还原：使用TCPCOPY的方式在线引入真实的流量测试

• 简单介绍下tcpcopy

在搭建和测试tcpcopy的时候也遇到一些坑，其中在路由上卡壳了很久，数据包一直被reset， 最终排查下来 1. 由于腾讯机房的交换机上设置了arp自动应答 2. test serve和assistant server必须在同一网段

反正过程蛮曲折的，这不是我们今天的重点，先忽略。

详细的tcpcopy文章，请参考同事整理的 ： tcpcopy介绍

• 继续问题追踪

好了，根据4.1的测试，我们认为问题是时区转换导致的，但是为了严谨，我们在对生产环境的真实引流做一次测试，如果引流的时候出问题，然后设置时区可以解决问题，才能正在确定问题的所在

好消息是： 当qps达到早高峰的量时，cpu sys压力高的场景复现了

坏消息是： 设置了time_zone=’+8:00’ 之后，并没有得到好转，还是自旋锁的问题

pstack的跟踪并没有Time_zone_system::gmt_sec_to_TIME(st_mysql_time* ， 所以跟时区转换没有多大关系

 33 alloc_root
 38 dispatch_command
 38 mysql_parse
 50 my_raw_malloc
 55 _L_lock_12685
 56 malloc
 66 fil_aio_wait
 66 __io_getevents_0_4
 66 io_handler_thread
 66 LinuxAIOHandler::collect
 66 LinuxAIOHandler::poll
 66 os_aio_linux_handler
 71 __lll_lock_wait_private
 80 acl_authenticate
 80 check_connection
 80 do_auth_once
 80 login_connection
 80 native_password_authenticate
 80 server_mpvio_read_packet
128 <Per_thread_connection_handler::LOCK_thread_cache>,
128 that=0x1e7db20
130 native_cond_wait
142 pthread_cond_wait@@GLIBC_2.3.2
212 at
264 Protocol_classic::get_command
302 do_command
328 vio_io_wait
328 vio_read
328 vio_socket_io_wait
329 poll
330 Protocol_classic::read_packet
331 my_net_read
331 net_read_packet_header
331 net_read_raw_loop
527 handle_connection
532 pfs_spawn_thread
618 clone
618 start_thread

继续从分析结果中寻找猫腻，以上很多函数都见过，那么我们就去寻找下平常不起眼的一些的函数名一个个排查。

经过排查后，脑海中对alloc，malloc，my_raw_mallo 有点敏感，意识中就突然想到了tcmalloc，而tcmalloc我的印象中就是解决内存溢出和高并发场景的

然后，死马当活马医，抱着试一试的心跳来安装测试下

4.4 tcmalloc 安装和部署

以上是同事整理的 tcmalloc原理&安装&部署&运维经验 相关文档，我这边简单摘要下  

1. 下载gperftools：  

git clone https://github.com/gperftools/gperftools.git  


2. 编译安装：  

sh autogen.sh  
yum install libunwind libunwind-devel  
./configure --prefix=/usr/local/gperftools  
make all  
make install  
ln -s /usr/local/gperftools/lib/libtcmalloc.so /usr/lib/  
ln -s /usr/local/gperftools/lib/libtcmalloc.so /usr/lib64/  


3. 编辑/etc/my.cnf, 在mysqld_safe节中加入：  

malloc-lib = tcmalloc  


4. 启动时执行命令：  

mysqld_safe --user=mysql &  


5. 查看tcmalloc是否已经被加载到mysqld进程中：  

lsof -n | grep tcmalloc  

如果输出结果不为空，则说明已经被加载，否则是未加载的状态。

4.4 malloc vs tcmalloc

malloc

tcmolloc

以上测试经过了10次以上，通过以上测试看：

1. 使用glibc自带的malloc，在同样的sql模型下，当MySQL QPS 达到16000的时候，CPU使用率已经高达92%，而sys cpu明显比较高
2. 使用google的tcmalloc，在同样的sql模型下，当MySQL QPS达到21000的时候，CPU使用率才39%，而sys cpu明显比较低

至此，告一段落，接下来我们还有一系列要做的事情

总结

1. SQL模型 决定了 QPS的极限 ， 我们需要一套相对靠谱的模型来探测机器的极限, 给后期扩容给出相对靠谱的理论依据

2. 简单的SQL模型意味着更高的QPS，SQL越简单越好，复杂的业务逻辑可以放在程序端处理

3. time_zone = ‘+8:00’ 来代替 time_zone=’system’ , 用以获得更好的性能

4. tcmalloc 来替换 malloc ， 用以获得更好的并发，tcmalloc 在小内存分配管理上更加优秀

5. 透明大页需要关闭 : 在之前的N次测试中，perf偶尔会看到compact_zone的出现，而这个可能跟透明大页相关，此问题我没能复现出来，但仍引起我们的关心

6. 如何快速、高效的做读迁移

7. perf不要随便乱用，尽量升级Linux的内核到高版本，来降低系统bug的可能,当然也许会引进新的bug —需测试

8. 如何用tcpcopy将master的读压力引流到test server , 毕竟master的操作需要非常谨慎