轉載|線上IO問題跟蹤-剖析MySQL IO路徑

• 2019 年 10 月 5 日
• 筆記

提示：公眾號展示程式碼會自動折行，建議橫屏閱讀

一、問題描述

某業務CDB實例，每天在特地時間段內（ 00:07:00 - 00:08:00左右）機器對應IO監控出現寫入尖刺，且主從實例都有類似現象，從機器監控可以看到，問題確實存在。

不僅master，進行同步的slave上有相同的現象，業務方希望找到導致該IO尖刺問題穩定出現的原因。

二、問題分析

首先確定問題來源，上圖所示監控為機器級別，機器IO寫入負載是否來源於mysqld進程？如果來源於mysqld進程，是來自於mysqld進程的哪一部分寫入操作引起？

為了獲取IO來源，在slave機上部署mysqld實例監控，以及iotop採集監控，獲取對應時間段更詳細的相關資訊，抓取對應時間段進行IO寫入的進程（執行緒），同時觀察對應時間段mysql實例狀態。

這段時間內的較大IO寫入執行緒號為：（截取部分記錄）

通過slave上iotop採集到的統計資訊，可以看出較大寫入來源為145378這一執行緒，確實來自於mysql進程，該時間段內沒有抓到其他大量寫入的記錄，同時該實例slave mysql為單機獨佔，可以基本確定寫入來源為mysql中145378這個執行緒，那麼這個執行緒是哪一個執行緒呢？

145378這個執行緒號正是mysqld slave的執行緒，而且為單執行緒回放的sql執行緒。

Thread 85 (Thread 0x7f68c4c4c700 (LWP 145378)):  #0  0x00007fa2badd3945 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0  #4  exec_relay_log_event (rli=0x1771c43c8, thd=0x7f68b0000990)  #5  handle_slave_sql (arg=0x1771c3010)

通過進一步搜索監控記錄，可以發現，其實sql執行緒引入大量寫入IO不僅存在於這個時間段，在其他時間段也有較高寫入的記錄（超過100MB/s），在00:08:00左右持續時間相對較長。這個現象反應出該問題可能貫穿於整個執行過程，只是其他時間段沒有這麼明顯。

通過mysql實例的監控可，可以看到mysql主要進行的操作為insert，slave mysql主要在進行單執行緒回放，執行這些insert操作，操作數量會有一些增長，每秒操作數不穩定，峰值可能達到4000左右。

從對於slave實例的新增監控可以得到結論，這段時間的主要寫入來源確實為mysqld進程，且為mysqld的sql執行緒，那麼問題轉換為：

在該業務模型下，進行單執行緒回放的mysql slave sql thread， 為什麼會在一些時段產生較大的寫入IO？產生這個現象的時候，mysql在做什麼事情？

為了更好的分析問題，同時不影響線上業務，在另外一台實驗機器上單獨搭建mysql 5.7的slave，連到源實例的master作為slave，問題現象也可以復現，為了獲取更多資訊，打開mysql 5.7的performance_schema，在實驗機器的slave機監控上，依然能看到該問題存在。

現在我們需要分析一下，SQL執行緒回放，可能產生哪些IO寫（注意其他執行緒的IO不會記錄到SQL執行緒頭上，例如page cleaner flush），一條SQL語句回放過程中，可能經歷的路徑上有哪些操作會引發IO操作。

一個slave mysql讀取relay log進行日誌回放，首先想到回放執行語句，可能由此引發下列寫入IO：

• mysql server binlog日誌記錄，即回放過程中語句寫入的本地binlog。
• innodb redo undo日誌記錄。
• 用戶態page flush（free page吃緊，需要自行flush獲取可用free page）。
• relay log purge，刪除文件。默認每當slave回放完一個完整relay log，會將對應文件進行刪除。

那麼，為了找到真正引發寫入的來源，需要對於上述來源逐步進行分析、排除，對可能原因進行驗證。

首先在5.7 slave上配置log_slave_updates=OFF，使得回放過程不記錄binlog日誌，問題現象依舊，排除binlog寫入。

分鐘級監控顯示，master實例在對應時間段insert數量有一定幅度增加：

為了保證free page夠用，調大了buffer pool，確保free page足夠使用，另外關閉relay log purge功能，使得SQL執行緒不會觸發刪除relay log文件，問題現象依舊，排除清理relay以及用戶態page flush。

通過sys schema統計值發現，對於文件寫入，count write統計值較大的記錄主要來源於redo log（例如ib_logfile0寫入7439952次，且總量為57.47GB），但是innodb自身對於log寫入的單位時間統計值顯示卻不大。

/data1/mysql_root/log/20120/ib_logfile0 5       4.00 KiB        819 bytes       7439952   57.47 GiB       8.10 KiB        57.47 GiB       100.00  /data1/mysql_root/log/20120/ib_logfile1 2       64.50 KiB       32.25 KiB       3025254   23.39 GiB       8.11 KiB        23.39 GiB       100.00

為了進一步排除干擾，修改mysql實現關閉redo log寫入，替換mysql 5.7實驗版本，統計值顯示確實redo文件幾乎沒有寫入增長，問題依舊，排除redo寫入造成，再看ibdata相關記錄增長，也非常有限，也可以排除undo文件寫入。

到目前為止，通常能想到的用戶態寫入（例如sql執行緒回放執行一個事務），都可以排除掉，還有什麼原因可以sql執行緒造成大量寫入呢？需要重新整理一下思路。

再回到業務本身，看一下業務的庫表結構模型和數據規模，表結構大體如下：

FRFrom int(10) unsigned NOT NULL DEFAULT 『0』, FRtBody mediumblob NOT NULL, FPSQL varchar(20480) NOT NULL, FBody mediumblob NOT NULL, FResTime bigint(20) NOT NULL DEFAULT 『0』, FCime bigint(20) NOT NULL DEFAULT 『0』, FInt1 int(10) unsigned NOT NULL DEFAULT 『0』, FInt2 int(10) unsigned NOT NULL DEFAULT 『0』, FInt3 int(10) unsigned NOT NULL DEFAULT 『0』, FInt4 int(10) unsigned NOT NULL DEFAULT 『0』, FInt5 int(10) unsigned NOT NULL DEFAULT 『0』, FChar1 varchar(256) NOT NULL DEFAULT 『』, FChar2 varchar(256) NOT NULL DEFAULT 『』, FChar3 varchar(512) NOT NULL DEFAULT 『』, FChar4 varchar(1024) NOT NULL DEFAULT 『』, FChar5 varchar(1024) NOT NULL DEFAULT 『』, FExt blob, FGrp2EvtNo bigint(20) DEFAULT NULL, PRIMARY KEY (FEventNo)

• 表數量很多，超過1W張表，且單表數據量不大
• 表結構沒有其他索引，只有主鍵
• 包含blob欄位
• 從relay log分析插入語句，blob每次都有較大的數據量進行插入

表數量較多，插入操作，blob欄位，並發插入且插入操作分散到各個表，這幾點看起來有些關聯。在關掉了包括binlog，relay purge，redo log等多個寫入之後，再抓一下sql執行緒回放的堆棧，看一下寫入調用的來源：

#0  os_aio_func (type=..., mode=mode@entry=24,      name=0x7ee4493f97b8 "./DB_xxx/xxx_36.ibd", file=..., buf=buf@entry=0x7ee453ed4000, offset=offset@entry=122683392, n=n@entry=1048576, read_only=read_only@entry=false, m1=m1@entry=0x0, m2=m2@entry=0x0)  #1  0x0000000001187922 in fil_write_zeros (node=0x7ee4493f5338, node=0x7ee4493f5338, read_only_mode=<optimized out>,      len=4194304, start=121634816, page_size=<optimized out>)  #2  fil_space_extend (space=space@entry=0x7ee448d8dbd8, size=<optimized out>)  #3  0x00000000007701d1 in fsp_try_extend_data_file (space=space@entry=0x7ee448d8dbd8, header=header@entry=0x7ef4a4ff0026 "",  #4  0x000000000118f0df in fsp_reserve_free_extents (n_reserved=n_reserved@entry=0x7f20868f4fa0, space_id=9054, n_ext=3,      alloc_type=alloc_type@entry=FSP_NORMAL, mtr=mtr@entry=0x7f20868f5890, n_pages=n_pages@entry=2)  #5  0x00000000010e6394 in btr_cur_pessimistic_insert (flags=flags@entry=0, cursor=cursor@entry=0x7f20868f5150,      offsets=offsets@entry=0x7f20868f50b0, heap=heap@entry=0x7f20868f50a0, entry=entry@entry=0x7ee453143488,      rec=rec@entry=0x7f20868f5570, big_rec=big_rec@entry=0x7f20868f5090, n_ext=n_ext@entry=0, thr=thr@entry=0x7ee4544623f0,      mtr=mtr@entry=0x7f20868f5890)

回顧一下基於主鍵索引的插入操作，對於b+樹，如果插入的record的較大（例如很大的blob），可能會觸發分裂操作。類似

對於innodb而言，插入的過程中，首先嘗試樂觀插入索引，如果空間大小不夠，再嘗試悲觀插入，悲觀插入首先保證表空間大小足夠（ibd文件 innodb_file_per_table=ON，每個表對應一個文件），這裡用戶場景，正是每個表一個ibd文件，那麼16000張表總共有16000個ibd文件。如果空間不夠，嘗試對於ibd文件進行擴展，擴展邏輯如下：

每次擴展4個extent（每個extent包含 16kb*64 = 1MB大小供64個data page），即每次擴展形成4MB，業務場景包含16000多個表，且每次插入數據量相對固定，表結構相同，插入目標表隨機分散，所以很多表大小，和後續操作，非常均衡可以看作是齊頭並進。

從slave實例監控來看，insert在對應時間段超過1000個每秒，最多可以達到4000個每秒。假設相同數據量模型，其中500個表同時擴展大小，這一秒內，可能同時產生500*4MB = 2GB左右的寫入。為了印證這個寫入來源，繼續在innodb層添加日誌跟蹤，對於idb文件擴展加入以下邏輯進行日誌跟蹤：

每100MB擴展數據量，查看累計時間，如果累計時間在1秒以內，列印一條warning日誌，且sleep 0.5s。

查看對應時間段新增日誌（+8為北京時間），

對應時間擴展很頻繁，除去sleep時間，大約0.1-0.2秒能夠產生100MB的擴展寫入，IO尖刺數據量基本吻合，與iotop抓取到的大io寫入也基本吻合。至此我們基本可以得出問題結論。

三、問題結論

業務模型比較特殊，多個包含BLOB欄位的小表（超過16000），業務模型為insert，寫入目標表分散，在某些時間段會並發insert（平均2000個左右每秒，峰值4000個每秒），由於BLOB欄位佔用空間較大，各個表使用分散，導致頻繁同時觸發分裂，進而導致底層data page擴展，使得底層多個ibd文件同時並發extend，初始化data page產生某些時間段較大IO，反應到機器監控上為某些時間段IO尖刺

解決方法：

1. 業務層面，對於類似場景，考慮合併表數量，減少並發擴展帶來的寫入壓力，可以一定程度緩解IO尖刺。
2. MySQL層面，考慮更加智慧的數據文件擴展演算法，適配上述場景。減少擴展的並發性。
3. MySQL層面，考慮用戶指定初始化表空間大小，提前預分配和初始化，避免動態擴展。