經典案例：磁盤I/O巨高排查全過程

做者：葉金榮，知數堂聯合創始人，3306pai社區聯合創始人

前言

是什麼緣由致使線上數據庫服務器磁盤I/O的util和iowait持續飈高？

1. 問題描述

朋友小明的線上數據庫突發嚴重告警，業務方反饋寫入數據一直堵住，不少鎖超時回滾了，不知道怎麼回事，就找到我了。

無論3721，先採集現場的必要信息再說。

a. 系統負載，主要是磁盤I/O的負載數據

該服務器的磁盤是由6塊2T SSD硬盤組成的RAID-5陣列。從上面的截圖來看，I/O %util已經基本跑滿了，iowait也很是高，很明顯磁盤I/O壓力太大了。那就再查查什麼緣由致使的這麼高壓力。

b. 活躍事務列表

能夠看到，有幾個活躍的事務代價很高，鎖定了不少行。其中有兩個由於過久超時被回滾了。

再看一次活躍事務列表，發現有個事務鎖定的行更多了，說明活躍業務SQL的效率不太好，須要進行優化。這個算是緣由之一，先記下。

c. 查看InnoDB狀態
執行 SHOW ENGINE INNODB STATUS\G 查看InnoDB狀態，這裏只展現了幾個比較關鍵的地方：

...
0x7f8f700e9700 INNODB MONITOR OUTPUT
...
LATEST DETECTED DEADLOCK
------------------------
...
*** (2) TRANSACTION:
TRANSACTION 52970892097, ACTIVE 1 sec starting index read
mysql tables in use 2, locked 2
80249 lock struct(s), heap size 9691344, 351414 row lock(s),
 undo log entries 30005
 ### 這裏很明顯，發生死鎖的事務之一持有不少行鎖，須要優化SQL
 ...
 update a inner join b on a.uid=b.uid set a.kid=if(b.okid=0,b.kid,b.okid),a.aid=b.aid where a.date='2020-02-10'
 ...
 TRANSACTIONS
 ------------
 Trx id counter 52971738624
 Purge done for trx's n:o < 52971738461 undo n:o < 0
 state: running but idle
 History list length 81
 ...
 ---TRANSACTION 52971738602, ACTIVE 0 sec inserting
 mysql tables in use 1, locked 1
 1 lock struct(s), heap size 1136, 0 row lock(s), 
 undo log entries 348
 ### 一樣滴，也是有不少行鎖
 ...
 LOG
 ---
 Log sequence number 565123876918590
 Log flushed up to   565123858946703
 Pages flushed up to 565121518602442
 Last checkpoint at  565121518602442
 ...
 ### 注意到Last checkpoint和LSN之間的差距很是大，約爲2249MB
 ### 說明redo log的checkpoint有延遲比較厲害，有多是由於磁盤I/O太慢，
 ### 也有多是由於產生的髒頁太多太快，來不及刷新
 ----------------------
 BUFFER POOL AND MEMORY
 ----------------------
 Total large memory allocated 201200762880
 Dictionary memory allocated 130361859
 Internal hash tables (constant factor + variable factor)        Adaptive hash index 3930999872      (3059599552 + 871400320)    
     Page hash           23903912 (buffer pool 0 only)    
     Dictionary cache    895261747       (764899888 + 130361859)    
     File system         16261960        (812272 + 15449688)   
     Lock system         478143288       (478120568 + 22720)    
     Recovery system     0       (0 + 0)
Buffer pool size   11795040
Buffer pool size, bytes 193249935360
Free buffers       7035886
Database pages     4705977O
ld database pages 1737005
Modified db pages  238613
### 髒頁比例約爲2%，看着還好嘛，並且還有挺多free page的
...

d. 查看MySQL的線程狀態*

+---------+------+--------------+---------------------
| Command | Time | State        | Info                                                                                                 |
+---------+------+--------------+---------------------
| Query   |    1 | update       | insert xxx
| Query   |    0 | updating     | update xxx
| Query   |    0 | updating     | update xxx
| Query   |    0 | updating     | update xxx
| Query   |    0 | updating     | update xxx
+---------+------+--------------+---------------------

能夠看到幾個事務都處於updating狀態。意思是正在掃描數據並準備更新，肉眼可見這些事務狀態時，通常是由於系統負載比較高，因此事務執行起來慢；或者該事務正等待行鎖釋放。

2. 問題分析及優化工做

分析上面的各類現場信息，咱們能夠獲得如下幾點結論：

a. 磁盤I/O壓力很大。先把陣列卡的cache策略改爲WB，不過因爲已是SSD盤，這個做用並不大，只能申請更換成RAID-10陣列的新機器了，還需等待資源調配。

b. 須要優化活躍SQL，下降加鎖代價

[root@yejr.me]> desc  select * from a inner join b on a.uid=b.uid where a.date='2020-02-10';
+-------+--------+------+---------+----------+-------+----------+-----------------------+
| table | type   | key  | key_len | ref      | rows  | filtered | Extra                 |
+-------+--------+------+---------+----------+-------+----------+-----------------------+
| a     | ref    | date | 3       | const    | 95890 |   100.00 | NULL                  |
| b     | eq_ref | uid  | 4       | db.a.uid |     1 |   100.00 | Using index condition |
+-------+--------+------+---------+----------+-------+----------+-----------------------+
[root@yejr.me]> select count(*) from a inner join b on a.uid=b.uid where a.date='2020-02-10';
+----------+
| count(*) |
+----------+
|    40435 |
+----------+
1 row in set (0.22 sec)

執行計劃看起來雖然能用到索引，但效率仍是不高。檢查了下，發現a表的uid列居然沒加索引，我汗。。。

c. InnoDB的redo log checkpoint延遲比較大，有2249MB之巨。先檢查redo log的設置：

innodb_log_file_size = 2G
innodb_log_files_in_group = 2

這個問題就大了，redo log明顯過小，等待被checkpoint的redo都超過2G了，那確定要瘋狂刷髒頁，因此磁盤I/O的寫入才那麼高，I/O %util和iowait也很高。

建議把redo log size調整成4G、3組。

innodb_log_file_size = 4Ginnodb_log_files_in_group = 2

此外，也順便檢查了InnoDB其餘幾個重要選項

innodb_thread_concurrency = 0
# 建議維持設置0不變
innodb_max_dirty_pages_pct = 50
# 因爲這個實例每秒寫入量較大，建議先調整到75，下降刷髒頁的頻率，
# 順便緩解redo log checkpoint的壓力。
# 在本案例，最後咱們把這個值調整到了90。

特別提醒
從MySQL 5.6版本起，修改redo log設置後，實例重啓時會自動完成redo log的再次初始化，不過前提是要先乾淨關閉實例。所以建議在第一次關閉時，修改如下兩個選項：

innodb_max_dirty_pages_pct = 0
innodb_fast_shutdown = 0

而且，再加上一個新選項，防止實例啓動後，會有外部應用鏈接進來繼續寫數據：

skip-networking

在確保全部髒頁（上面看到的Modified db pages爲0）都刷盤完畢後，而且redo log也都checkpoint完畢（上面看到的Log sequence number和Last checkpoint at**值相等），此時才能放心的修改 innodb_log_file_size 選項配置並重啓。確認生效後再關閉 skip-networking 選項對業務提供服務。

通過一番優化調整後，再來看下服務器和數據庫的負載。

能夠看到，服務器的磁盤I/O壓力不再會那麼大了，數據庫中也不會頻繁出現大量行鎖等待或回滾的事務了。

[root@yejr.me]> SHOW ENGINE INNODB STATUS\g
Log sequence number 565749866400449
Log flushed up to   565749866400449
Pages flushed up to 565749866318224
Last checkpoint at  565749866315740
[root@yejr.me]> SHOW ENGINE INNODB STATUS\g
Log sequence number 565749866414660
Log flushed up to   565749866400449
Pages flushed up to 565749866320827
Last checkpoint at  565749866315740
[root@yejr.me]> SHOW ENGINE INNODB STATUS\g
Log sequence number 565749866414660
Log flushed up to   565749866414660
Pages flushed up to 565749866322135
Last checkpoint at  565749866315740
[root@yejr.me]> select (565749866400449-565749866315740)/1024;
+----------------------------------------+
| (565749866400449-565749866315740)/1024 |
+----------------------------------------+
|                                82.7236 |
+----------------------------------------+
1 row in set (0.00 sec)
[root@yejr.me]> select (565749866414660-565749866315740)/1024;
+----------------------------------------+
| (565749866414660-565749866315740)/1024 |
+----------------------------------------+
|                                96.6016 |
+----------------------------------------+

很明顯，redo log checkpoint lag幾乎沒有了。

完美搞定！

寫在最後

遇到數據庫性能瓶頸，負載飈高這類問題，咱們只須要根據一套完整的方法論 優化系列：實例解析MySQL性能瓶頸排查定位，根據現場的各類蛛絲馬跡，逐一進行分析，基本上都是能找出來問題的緣由的。本案其實並不難，就是按照這套方法來作的，最後連perf top都沒用上就很快能大體肯定問題緣由了。

延伸閱讀

• 是什麼致使MySQL數據庫服務器磁盤I/O高
• 實例解析MySQL性能瓶頸排查定位
• 重要的MySQL開發規範都在這了
• MySQL全面快速優化參考
• 實例解析MySQL性能瓶頸排查定位