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.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%，很可能不會引起大家的關注
最後非常感謝薑承堯和宋武斌的幫助，才能夠最終徹底發現這樣的問題

最後更新：2017-06-09 16:31:33

util 100% 怪異問題分析

環境

問題描述

問題分析

總結&改進

最後

上一篇： H5響應式網站你需要做到以下3點

下一篇： spring cloud學習填坑筆記

相關內容

熱門內容

最新內容