util 100% 怪异问题分析-阿里云开发者社区

开发者社区> 数据库> 正文

util 100% 怪异问题分析

简介: 环境 1. DB: Server version: 5.7.18-log MySQL Community Server (GPL) 2. OS: CentOS release 6.6 (Final) 问题描述 问题要害 1.

环境

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的文件才监控

最后

  1. 问题的难点:问题出现时间短,无规律
  2. 这个问题的解决,其实也非常简单,可是为什么没能一开始就找到答案呢,说明自己水平还是有限的,还需要多总结增加经验和不断学习
  3. 这次的收获也非常多,经过这次的问题,分析问题的过程中对MySQL的体系结构又再次深入了解学习了下
  4. 要把这种细小的问题分析透彻,是需要一定的坚持和固执的,因为就偶尔几秒钟的io100%,很可能不会引起大家的关注
  5. 最后非常感谢姜承尧和宋武斌的帮助,才能够最终彻底发现这样的问题

版权声明:本文内容由阿里云实名注册用户自发贡献,版权归原作者所有,阿里云开发者社区不拥有其著作权,亦不承担相应法律责任。具体规则请查看《阿里云开发者社区用户服务协议》和《阿里云开发者社区知识产权保护指引》。如果您发现本社区中有涉嫌抄袭的内容,填写侵权投诉表单进行举报,一经查实,本社区将立刻删除涉嫌侵权内容。

分享:
数据库
使用钉钉扫一扫加入圈子
+ 订阅

分享数据库前沿,解构实战干货,推动数据库技术变革

其他文章