util100%怪異問題分析

蘭春發表於2017-06-09
原文網址 : https://flycode.co/archives/186788

環境

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. 最後非常感謝姜承堯和宋武斌的幫助，才能夠最終徹底發現這樣的問題


相關文章