MySQL · 案例分析 · RDS MySQL線上執行個體insert慢常見原因分析

概述

insert慢是經常被問到的問題，筆者嘗試在本文中對這個問題做一個分類梳理，列舉的線上例子會做簡化，希望對讀者有所啟發。

注意：因為阿裡雲MySQL線上執行個體還是以RDS 5.6為主體，本文的分析也是以5.6 innodb 引擎為主，其他版本的rds的執行個體可能略有差别。

insert幾個可能的性能瓶頸點

有關MySQL insert源碼分析的文章，可以參看阿裡雲雲栖社群的文章，例如：

1. 一條簡單insert語句的調用棧
2. 一條insert語句的執行過程

基于insert源碼分析，和MySQL事務的一般過程，可以看出insert語句執行過程中幾個可能的瓶頸點，包括加鎖，io和網絡幾個方面，

1. MDL鎖， insert語句需要拿IX MDL 鎖
2. 外鍵檢查對主表加S行鎖
3. insert轉update操作需要的對老記錄index entry的行鎖
4. iops限制
5. 寫binlog
6. semi-sync消息延遲

下面我們來看幾個實際的例子，每個例子都會盡量和讀者一起來分享一下根因定位方法和問題規避建議，

insert語句慢示例分析

MDL鎖等待

MDL鎖等待阻塞DML語句的問題比較常見，一般都是因為表上有運作時間比較長的DDL語句在運作，比如Optimize， Truncate table，Alter table等，診斷方法也很簡單，

通過運作show processlist，就會看到被阻塞的語句的狀态是

Waiting for table metadata lock

，如果權限足夠的話，還可以看到blocker thread，

規避的方法是避免在業務高峰運作DDL語句，特别是耗時很長的對大表的DDL。

外鍵檢查等待對主表記錄的S鎖

如果是insert的目标表有定義外鍵依賴，MySQL需要做參照完整性（RI）檢查，會對主表的對應記錄加S鎖。如果主表記錄上正好有沒有送出的修改，就會帶來insert事務的鎖等待。

在筆者寫這篇文章的時候，RDS的慢日志項目裡面的lock time字段并沒有清晰的反映這種因為RI帶來的鎖等待時間消耗。

在問題出現的當場，運作下面的query檢視I_S表，找出阻塞關系。這種方法有其局限性，隻能抓現行，如果阻塞已經消除了，後期就看不到了。

SELECT
r.trx_id waiting_trx_id,
r.trx_mysql_thread_id waiting_thread,
r.trx_query waiting_query,
b.trx_id blocking_trx_id,
b.trx_mysql_thread_id blocking_thread,
b.trx_query blocking_query,
(Unix_timestamp() - Unix_timestamp(r.trx_started)) blocked_time
from information_schema.innodb_lock_waits w
inner join information_schema.innodb_trx b
on b.trx_id = w.blocking_trx_id
inner join information_schema.innodb_trx r
on r.trx_id = w.requesting_trx_id
           

阿裡雲MySQL RDS有計劃會改進慢SQL lock time的記錄，記錄外鍵檢查對主表記錄S鎖的等待時間； 另外，還會将所有發生過阻塞的thread的資訊記錄在記憶體表裡，供後期問題排查使用。

外鍵檢查對主表記錄加鎖慢的規避方法是加速釋放主表的X行鎖，避免長事務；或者是通過業務而不是MySQL資料庫來保證參照完整性。

insert轉update操作需要拿老記錄index entry上的S/X鎖

如果新插入的記錄項已經存在，但已經被标記為已删除，或者是使用了INSERT ON DUPLICATE KEY UPDATE, MySQL會将insert操作轉成update操作。就會對老的index 項目加上X鎖(如果是cluster

index對應的記錄則加S鎖)，來確定原有記錄的删除/修改事務已經送出。

------------------------
LATEST DETECTED DEADLOCK
------------------------
...
*** (1) TRANSACTION:
TRANSACTION 82234303407, ACTIVE 0.000 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1184, 2 row lock(s), undo log entries 1
LOCK BLOCKING MySQL thread id: 1275826132 block 1242176372
MySQL thread id 1242176372, OS thread handle 0x2abbbf103700, query id 30359943998 ...  push_service update
INSERT INTO ... ON DUPLICATE KEY UPDATE ...
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 12214 page no 672677 n bits 264 index ... of table ... trx id 82234303407 lock_mode X waiting
Record lock, heap no 10 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
...

*** (2) TRANSACTION:
TRANSACTION 82234303405, ACTIVE 0.001 sec inserting
mysql tables in use 1, locked 1
4 lock struct(s), heap size 1184, 3 row lock(s), undo log entries 1
INSERT INTO ... ON DUPLICATE KEY UPDATE ...
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 12214 page no 672677 n bits 264 index `...` of table ... trrx id 82234303405 lock_mode X
Record lock, heap no 10 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
...

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 12214 page no 672677 n bits 264 index `...` of table ...  trx id 82234303405 lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 10 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
...

*** WE ROLL BACK TRANSACTION (1)
           

上面是多條INSERT ON DUPLICATE KEY UPDATE并發執行導緻的死鎖，在master error log裡面可以觀測到。

這種問題的診斷可以通過檢視慢日志的lock time字段來判斷；如果發生了死鎖，還可以檢視master error log，也可類似MDL鎖等待，從I_S表檢視目前的阻塞關系。

筆者曾經遇到過insert作業時不時會變慢，但前端業務并沒有什麼高峰尖刺。背景分析可以看到使用者binlog使用很重，大概每2分鐘就會産生将近600M的binglog檔案，依賴rds的系統診斷工具上也能觀察到iops

打滿的問題。

因為慢insert有明顯的時間規律，懷疑有定期批處理。和客戶溝通後，确認客戶有設定event scheduler，每分鐘會進行全表的資料歸集操作，io壓力比較大。後期讓客戶調整他們的資料歸集邏輯後，insert慢的問題消失。

寫binlog延遲

筆者還遇到一條insert語句一直沒有成功傳回,

show processlist

顯示該條insert語句的狀态是

query end

。筆者列印了當時的pstack資訊，發現了如下的調用棧

#0  0x0000003c00eab91d in nanosleep () from /lib64/libc.so.6
#1  0x0000003c00eab790 in sleep () from /lib64/libc.so.6
#2  0x00000000009967c6 in wait_for_free_space ()
#3  0x00000000009b29d9 in my_write ()
#4  0x000000000099a547 in my_b_flush_io_cache ()
#5  0x0000000000958892 in MYSQL_BIN_LOG::ordered_commit(THD*, bool, bool) ()
#6  0x0000000000959214 in MYSQL_BIN_LOG::commit(THD*, bool) ()
#7  0x000000000062c870 in ha_commit_trans(THD*, bool, bool) ()
#8  0x00000000008200e9 in trans_commit_stmt(THD*) ()
#9  0x000000000078aba1 in mysql_execute_command(THD*) ()
#10 0x00000000007910b0 in mysql_parse(THD*, char*, unsigned int, Parser_state*) ()
#11 0x0000000000792805 in dispatch_command(enum_server_command, THD*, char*, unsigned int) ()
#12 0x0000000000754535 in do_handle_one_connection(THD*) ()
#13 0x0000000000754589 in handle_one_connection ()
#14 0x0000003c01207851 in start_thread () from /lib64/libpthread.so.0
#15 0x0000003c00ee767d in clone () from /lib64/libc.so.6
           

這個調用棧很明顯的說明了問題所在，就是binlog的磁盤沒有剩餘空間了，導緻insert hang住。清理出足夠的磁盤空間後，insert執行結束。

需要指出的是，MySQL 8.0增加了新的thread stage

WAITING FOR DISK

來提示等待磁盤空間，來輔助診斷，對應的commit id是’6de594adf488add4514884d18c337745b1d227fb’。

在有主備複制環境下，semi-sync消息延遲也可能導緻insert變慢。筆者遇到一個慢insert，杜康慢日志顯示此insert的執行時間正好是1秒。

檢視master error log，發現在insert出現的時間點正好有這種資訊

...[Warning] Timeout waiting for reply of binlog (file: mysql-bin.000903, pos: 2519326), semi-sync up to file mysql-bin.000903, position 2519003.
           

而系統參數rpl_semi_sync_master_timeout也正好是1秒。是以，可以判定是因為網絡抖動，semi-sync消息延遲導緻的insert變慢。

總結

mysql insert語句執行慢的可能原因比較多，涵蓋cpu，io，網絡，鎖等，在本文中分析了MySQL執行個體負載大，唯一鍵update、外鍵檢查加鎖帶來的鎖等待，semi-sync的網絡開銷，磁盤io限制，binlog日志滿等導緻的insert慢的問題。具體的原因需要具體分析，分析方法包括檢視mysql已有的master-error log, slow log，另外，阿裡雲rds提供了強大的圖形化工具包括我們檢視系統負載曲線，慢日志詳情，系統卡慢歸總資訊等，rds mysql核心團隊有對定制系統診斷的能力，例如為慢日志添加更細的名額資訊，包括鎖等待時間等，并且也在一直加強對診斷問題缺失資訊的補全，這些資訊對于我們分析各種MySQL的性能問題都有很大的輔助。另外，保持MySQL版本的及時更新也是減少慢query或者是加快慢query診斷的推薦做法。