util 100% 怪异问题分析

内容简介：util 100% 怪异问题分析

环境

1. DB: Server version: 5.7.18-log MySQL Community Server (GPL)  
2. OS: CentOS release 6.6 (Final)

问题描述

• 问题要害

1. 不定时的磁盘util 100%  
2. 每次持续时间就几秒钟

问题分析

• 第一反应

1. 看到这个问题，我的第一反应就是去看看mysql slow query  
2. 结果通过omega系统里面的智能slow query系统得到的答案是：无明显slow

问题到这，基本上根据经验已经无法快速得到答案，然后继续思考

• 看各项监控

1. cpu 正常，历史曲线一致  
2. load 正常， 历史曲线一致  
3. InnoDB 核心监控正常，历史曲线一致  
4. 网络正常，历史曲线一致

看下来都很正常，唯独磁盘io不正常

• 既然是io压力，那么很自然的查看iostat和iotop

1. iostat 

经过一段时间的iostat（因为要问题复现必须要等待，因为通过监控得到，问题时间不规律）发现，磁盘io 100%  
的时候，基本上wio=2000，wMB/s 800M左右  

2. iotop

经过一段时间的观察，唯独了一个系统进程[flush-8:16] io占用特别高

到这里，是不是就基本锁定问题了呢？

去查了下，[flush-8:16] 就是OS内核再刷新数据

到这一步，基本上快接近真相了，但是剧情并没有按照想象的发展，那么问题来了，这个刷新是谁导致的呢？最后的凶手又是谁呢？

• 回顾问题

1. 基本确定是内核刷新数据导致，排除掉硬件故障  
2. 是系统自己刷新？还是 MySQL 再刷新？  
3. io 100% 为什么以前没有发生这样的现象，唯独最近一周发生，这一周我们做了哪些改变  
 a）MySQL 从5.6 升级到 5.7 
 b）MySQL的参数从5.6，优化到 5.7，参数优化的变量因子还是挺多的，没办法一一去掉后排查 
 c）最近由于机器问题，切换了一次master

那就分析下是os自己的刷新，还是MySQL内核的刷新

• 分析下是否MySQL的脏页刷新导致

1. MySQL 刷新数据，io占用比较高的地方有哪些
    a）binlog： binlog 并不在出问题的分区上，所以binlog 可以排除  
    b）redo log ： 
				b.1) redo log 是顺序写，checkpoint的age在800M左右，大小上来看非常温和，但是要记住，这仅仅是age，并不是一次性要刷新这么多  
				b.2) redo log 是没有o_direct的，所以可能导致操作系统刷新数据  
				b.3) redo log的刷新条件和触发时机有一个是：每秒钟都刷新，每一次commit都刷新，所以更加可以排除掉redo造成的问题，因为一个commit在一秒内不可能有这么大的日志量  
    c）data file ： 
        		c.1) data file 如果要刷新800M，那至少要刷新好几万个page吧，如果要刷新那么多页，MySQL估计就已经hung住了  
			    c.2) data file 我们设置的是： flush_method=O_Direct, 这表示InnoDB自己管理内存刷新  
                c.2) checkpoint的触发时机：当checkpoint_age达到75%的redo 总大小时触发,然而远远没有达到  
				c.3)  查看modified pages 的频率，并没有明显的异常

所以，排除掉是MySQL的刷新问题

• 分析下是否系统产生的脏页导致的问题

while true; do cat /proc/vmstat  |grep nr_dir; date; sleep 1; done

Wed Jun  7 15:59:18 CST 2017
nr_dirty 182832
Wed Jun  7 15:59:19 CST 2017
nr_dirty 494958
Wed Jun  7 15:59:20 CST 2017
nr_dirty 815964
Wed Jun  7 15:59:21 CST 2017
nr_dirty 1140783
Wed Jun  7 15:59:22 CST 2017
nr_dirty 1474413
Wed Jun  7 15:59:23 CST 2017
nr_dirty 1382764
Wed Jun  7 15:59:24 CST 2017


当脏页非常多的时候，过几秒，io 100%就必现

基本可以断定，是操作系统的刷新导致的问题

• 再次iotop

1） 这一次的iotop，由于目不转睛的人肉扫描，终于发现另一个可疑进程  cp  xx.err xx.err.bak
2)  然后查看了下这个xx.err文件，竟然有8G的大小  
3） 然后问题终于已经定位成功

总结&改进

• 为什么MySQL error log 会这么大呢？

1) 5.7新增参数innodb print dead locks=1，这样可以打印出详细的死锁日志  
2) 然后线上一堆死锁  
3) 导致error log日志非常大  
4) 然后我们自己的监控回去定期cp error log  
5) 然后问题就发生了  

至于为什么有那么的死锁信息，这个后面有MySQL锁的专题文章专门介绍  

改进方案：

1）去掉这个参数  ，没必要打印出所有的死锁信息，当有死锁的时候，实时查看也可以的  
2）error log的日志监控  
3）cp的方式优化掉

• 为什么iotop 一开始没有发现到这个cp 进程呢？

1) 由于cp的时间就几秒非常短，所以当我们看到的时候，已经是在flush 阶段了

• 有什么先进的 工具 可以直接定位到文件，哪个文件所占用的io最大呢？

1） pt-ioprofile  

优点：可以分析出文件的io占比  

缺点：
	比较重，是用ptrace的方式来实现，可能会对mysql有影响  
	貌似只会对MySQL的文件才监控

最后

1. 问题的难点：问题出现时间短，无规律

2. 这个问题的解决，其实也非常简单，可是为什么没能一开始就找到答案呢，说明自己水平还是有限的，还需要多总结增加经验和不断学习

3. 这次的收获也非常多，经过这次的问题，分析问题的过程中对MySQL的体系结构又再次深入了解学习了下

4. 要把这种细小的问题分析透彻，是需要一定的坚持和固执的，因为就偶尔几秒钟的io100%，很可能不会引起大家的关注

5. 最后非常感谢姜承尧和宋武斌的帮助，才能够最终彻底发现这样的问题

以上所述就是小编给大家介绍的《util 100% 怪异问题分析》，希望对大家有所帮助，如果大家有任何疑问请给我留言，小编会及时回复大家的。在此也非常感谢大家对 码农网 的支持！

查看所有标签

猜你喜欢:

• 低概率问题分析解决
• 事物分析和问题解决(200421)
• 问题分析和解决逻辑(200701)
• 技术问题分析(9.17)
• 技术问题分析(9.29)
• HDFS Decommission问题分析

本站部分资源来源于网络，本站转载出于传递更多信息之目的，版权归原作者或者来源机构所有，如转载稿涉及版权问题，请联系我们。