环境
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
d) 启动了压缩表功能 那就分析下是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.3) checkpoint的触发时机：当checkpoint_age达到75%的redo 总大小时触发,然而远远没有达到
c.4) 查看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的文件才监控
最后
- 问题的难点：问题出现时间短，无规律
- 这个问题的解决，其实也非常简单，可是为什么没能一开始就找到答案呢，说明自己水平还是有限的，还需要多总结增加经验和不断学习
- 这次的收获也非常多，经过这次的问题，分析问题的过程中对MySQL的体系结构又再次深入了解学习了下
- 要把这种细小的问题分析透彻，是需要一定的坚持和固执的，因为就偶尔几秒钟的io100%，很可能不会引起大家的关注
- 最后非常感谢姜承尧和宋武斌的帮助，才能够最终彻底发现这样的问题
