By 兰春

Updated:

Contents
  1. 1. 环境
  2. 2. 问题描述
  3. 3. 问题分析
  4. 4. 总结&改进
  5. 5. 最后

环境

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

问题描述

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

问题分析

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

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

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

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

  • 既然是io压力，那么很自然的查看iostat和iotop 
1
2
3
4
5
6
7
8
1. iostat 
经过一段时间的iostat（因为要问题复现必须要等待，因为通过监控得到，问题时间不规律）发现，磁盘io 100%  
的时候，基本上wio=2000，wMB/s 800M左右  
2. iotop
经过一段时间的观察，唯独了一个系统进程[flush-8:16] io占用特别高

到这里，是不是就基本锁定问题了呢？
去查了下，[flush-8:16] 就是OS内核再刷新数据
到这一步，基本上快接近真相了，但是剧情并没有按照想象的发展，那么问题来了，这个刷新是谁导致的呢？最后的凶手又是谁呢？

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

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

  • 分析下是否MySQL的脏页刷新导致
1
2
3
4
5
6
7
8
9
10
11
12
13
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的刷新问题
  • 分析下是否系统产生的脏页导致的问题
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
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
2
3
1） 这一次的iotop，由于目不转睛的人肉扫描，终于发现另一个可疑进程  cp  xx.err xx.err.bak
2)  然后查看了下这个xx.err文件，竟然有8G的大小  
3） 然后问题终于已经定位成功

总结&改进

  • 为什么MySQL error log 会这么大呢？ 
1
2
3
4
5
6
7
8
9
10
11
12
13
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
1) 由于cp的时间就几秒非常短，所以当我们看到的时候，已经是在flush 阶段了
  • 有什么先进的工具可以直接定位到文件，哪个文件所占用的io最大呢？ 
1
2
3
4
5
6
7
1） pt-ioprofile  
优点：可以分析出文件的io占比  
缺点：
	比较重，是用ptrace的方式来实现，可能会对mysql有影响  
	貌似只会对MySQL的文件才监控

最后

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

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

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

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

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

Contents
  1. 1. 环境
  2. 2. 问题描述
  3. 3. 问题分析
  4. 4. 总结&改进
  5. 5. 最后

幸福,不在于得到的多

而在于计较的少