天天看點

經典案例:磁盤I/O巨高排查全過程(1)

前言

是什麼原因導緻線上資料庫伺服器磁盤I/O的util和iowait持續飚高?

1. 問題描述

朋友小明的線上資料庫突發嚴重告警,業務方回報寫入資料一直堵住,很多鎖逾時復原了,不知道怎麼回事,就找到我了。

不管3721,先采集現場的必要資訊再說。

a. 系統負載,主要是磁盤I/O的負載資料

經典案例:磁盤I/O巨高排查全過程(1)

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

b. 活躍事務清單

經典案例:磁盤I/O巨高排查全過程(1)

可以看到,有幾個活躍的事務代價很高,鎖定了很多行。其中有兩個因為太久逾時被復原了。

經典案例:磁盤I/O巨高排查全過程(1)

再看一次活躍事務清單,發現有個事務鎖定的行更多了,說明活躍業務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     4705977
Old 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,降低加鎖代價

[[email protected]]> 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 |
+-------+--------+------+---------+----------+-------+----------+-----------------------+

[[email protected]]> 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 = 4G
innodb_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 選項對業務提供服務。