從庫延遲案例分析，你學到了什麼
2024.04.12
背景介紹
近來一套業務系統，從庫一直處於延遲狀態，無法追上主庫，導致業務風險較大。從資源來看，從庫的CPU、IO、網路使用率較低，不存在伺服器壓力過高導致回放慢的情況；從庫開啟了並行回放；在從庫上執行show processlist看到沒有回放線程阻塞，回放一直持續；解析relay-log日誌文件，發現其中並沒大事務回放。
過程分析
現象確認
收到維運同事的回饋，有一套從函式庫延遲的非常厲害，提供了show slave status延遲的截圖訊息
圖片
持續觀察了一陣show slave status的變化，發現pos點位資訊在不停的變化，Seconds_Behind_master也是不停的變化的，整體趨勢還在不停的變大。
資源使用
觀察了伺服器資源使用情況，可以看到佔用非常低
圖片
觀察從庫進程情況，基本上只能看到有一個執行緒在回放工作
圖片
並行回放參數說明
在主庫設定了binlog_transaction_dependency_tracking=WRITESET
在從庫中設定了slave_parallel_type=LOGICAL_CLOCK和slave_parallel_workers=64
error log日誌對比
從error log取並行回放的日誌進行分析
$ grep 010559 100werror3306.log | tail -n 3
2024-01-31T14:07:50.172007+08:00 6806 [Note] [MY-010559] [Repl] Multi-threaded slave statistics for channel 'cluster': seconds elapsed = 120; events assigned = 3318582273; worker queues filled over overrun level = 207029; waite
d due a Worker queue full = 238; waited due the total size = 0; waited at clock conflicts = 348754579743300 waited (count) when Workers occupied = 34529247 waited when Workers occupied = 76847369713200
2024-01-31T14:09:50.078829+08:00 6806 [Note] [MY-010559] [Repl] Multi-threaded slave statistics for channel 'cluster': seconds elapsed = 120; events assigned = 3319256065; worker queues filled over overrun level = 207029; waite
d due a Worker queue full = 238; waited due the total size = 0; waited at clock conflicts = 348851330164000 waited (count) when Workers occupied = 34535857 waited when Workers occupied = 76866419841900
2024-01-31T14:11:50.060510+08:00 6806 [Note] [MY-010559] [Repl] Multi-threaded slave statistics for channel 'cluster': seconds elapsed = 120; events assigned = 3319894017; worker queues filled over overrun level = 207029; waite
d due a Worker queue full = 238; waited due the total size = 0; waited at clock conflicts = 348943740455400 waited (count) when Workers occupied = 34542790 waited when Workers occupied = 76890229805500- 1.
- 2.
- 3.
- 4.
- 5.
- 6.
- 7.
- 8.
- 9.
上述資訊的詳細解釋，可以參考 MTS效能監控你知道多少
去掉了發生次數比較少的統計，顯示了一些關鍵數據的對比
圖片
可以發現自然時間120，回放的協調線程有90多秒由於無法並行回放而進入等待，有近20秒是由於沒有空閒的work線程進入等待，折算下來協調線程工作的時間只有10秒左右。
平行度統計
眾所周知，mysql從庫並行回放主要依賴於binlog中的last_commmitted來做判斷，如果事務的last_committed相同，則基本上可以認為這些事務可以並行回放，下面從環境中獲取一個relay log進行並行回放的大概統計
$ mysqlsqlbinlog --no-defaults 046638 |grep -o 'last_committed.*' | sed 's/=/ /g' | awk '{print $2}' |sort -n | uniq -c |awk 'BEGIN {print "last_commited group_count Percentage"} {count[$2]=$1
; sum+=$1} END {for (i in count) printf "%d %d %.2f%%\n", i, count[i], (count[i]/sum)*100|"sort -k 1,1n"}' | awk '{if($2>=1 && $2 <11){sum+=$2}} END {print sum}'
235703
$ mysqlsqlbinlog --no-defaults 046638 |grep -o 'last_committed.*' | sed 's/=/ /g' | awk '{print $2}' |sort -n | uniq -c |awk 'BEGIN {print "last_commited group_count Percentage"} {count[$2]=$1
; sum+=$1} END {for (i in count) printf "%d %d %.2f%%\n", i, count[i], (count[i]/sum)*100|"sort -k 1,1n"}' | awk '{if($2>10){sum+=$2}} END {print sum}'
314694- 1.
- 2.
- 3.
- 4.
- 5.
- 6.
上述第一條指令，是統計last_committed相同的交易數量在1-10個，即並行回放程度較低或是無法並行回放，這些交易總數量為235703，佔43%，詳細解析並行回放度比較低的事務分佈，可以看出這部分last_committed基本上都是單條的，都需要等待先序事務回放完成後，自己才能進行回放，這就會造成前面日誌中觀察到的協調線程等待無法並行回放而進入等待的時間比較長的情況
$ mysqlbinlog --no-defaults 046638 |grep -o 'last_committed.*' | sed 's/=/ /g' | awk '{print $2}' |sort -n | uniq -c |awk 'BEGIN {print "last_commited group_count Percentage"} {count[$2]=$1; sum+=$1} END {for (i in count) printf "%d %d %.2f%%\n", i, count[i], (count[i]/sum)*100|"sort -k 1,1n"}' | awk '{if($2>=1 && $2 <11) {print $2}}' | sort | uniq -c
200863 1
17236 2
98 3
13 4
3 5
1 7- 1.
- 2.
- 3.
- 4.
- 5.
- 6.
- 7.
第二條指令統計last_committed相同的交易數量超過10個的總事務數，其數量為314694，佔57%，詳細解析了這些並行回放度比較高的事務，可以看到每一組是在6500~9000個事務數間
$ mysqlsqlbinlog --no-defaults 046638 |grep -o 'last_committed.*' | sed 's/=/ /g' | awk '{print $2}' |sort -n | uniq -c |awk 'BEGIN {print "last_commited group_count Percentage"} {count[$2]=$1
; sum+=$1} END {for (i in count) printf "%d %d %.2f%%\n", i, count[i], (count[i]/sum)*100|"sort -k 1,1n"}' | awk '{if($2>11){print $0}}' | column -t
last_commited group_count Percentage
1 7340 1.33%
11938 7226 1.31%
23558 7249 1.32%
35248 6848 1.24%
46421 7720 1.40%
59128 7481 1.36%
70789 7598 1.38%
82474 6538 1.19%
93366 6988 1.27%
104628 7968 1.45%
116890 7190 1.31%
128034 6750 1.23%
138849 7513 1.37%
150522 6966 1.27%
161989 7972 1.45%
175599 8315 1.51%
189320 8235 1.50%
202845 8415 1.53%
218077 8690 1.58%
234248 8623 1.57%
249647 8551 1.55%
264860 8958 1.63%
280962 8900 1.62%
297724 8768 1.59%
313092 8620 1.57%
327972 9179 1.67%
344435 8416 1.53%
359580 8924 1.62%
375314 8160 1.48%
390564 9333 1.70%
407106 8637 1.57%
422777 8493 1.54%
438500 8046 1.46%
453607 8948 1.63%
470939 8553 1.55%
486706 8339 1.52%
503562 8385 1.52%
520179 8313 1.51%
535929 7546 1.37%- 1.
- 2.
- 3.
- 4.
- 5.
- 6.
- 7.
- 8.
- 9.
- 10.
- 11.
- 12.
- 13.
- 14.
- 15.
- 16.
- 17.
- 18.
- 19.
- 20.
- 21.
- 22.
- 23.
- 24.
- 25.
- 26.
- 27.
- 28.
- 29.
- 30.
- 31.
- 32.
- 33.
- 34.
- 35.
- 36.
- 37.
- 38.
- 39.
- 40.
- 41.
- 42.
last_committed機制介紹
主庫的參數binlog_transaction_dependency_tracking用於指定如何產生其寫入二進位日誌的依賴訊息，以幫助從庫確定哪些事務可以並行執行，即透過該參數控制last_committed的生成機制，參數可選值有COMMIT_ORDER、WRITESET、SESSION_WRITESET 。從下面這段程式碼，很容易看出來三種參數關係：
- 基礎演算法為COMMIT_ORDER
- WRITESET演算法是在COMMIT_ORDER基礎上再計算一次
- SESSION_WRITESET演算法是在WRITESET基礎上再計算一次
圖片
由於我的實例設定的是WRITESET，因此關注COMMIT_ORDER演算法和的WRITESET演算法即可。
提交訂單
COMMIT_ORDER計算規則：如果兩個事務在主節點上是同時提交的，說明兩個事務的資料之間沒有衝突，那麼一定也是可以在從節點上並行執行的，理想中的典型案例例如下面的例子
會話-1 | 會話2 |
開始 | 開始 |
插入 t1 值(1) | |
插入 t2 值(2) | |
提交（組提交） | 提交（組提交） |
但對MySQL來說，group_commit是內部行為，只要session-1和session-2是同時執行commit，不管內部是否合併為group_commit，兩個事務的資料本質上都是沒有衝突的；再退一步來講，只要session-1執行commit之後，session-2沒有新的資料寫入，兩個事務依舊沒有資料衝突，依然可以並行複製。
會話-1 | 會話2 |
開始 | 開始 |
插入 t1 值(1) | |
插入 t2 值(2) | |
犯罪 | |
犯罪 |
對於更多並發執行緒的場景，可能這些執行緒不能同時並行複製，但部分事務卻可以。以如下一個執行順序來說，在session-3提交之後，session-2沒有新的寫入，那麼這兩個事務是可以並行複製的；而session-3提交後，session-1又插入了一條新的數據，此時無法判定資料衝突，所以session-3和session-1的事務無法並行複製；但session-2提交後，session-1之後沒有新資料寫入，所以session-2和session-1又可以並行複製。因此，在這個場景中，session-2分別可以和session-1，session-3並行複製，但3個交易無法同時並行複製。
會話-1 | 會話2 | 會話-3 |
開始 | 開始 | 開始 |
插入 t1 值(1) | 插入 t2 值(1) | 插入 t3 值(1) |
插入 t1 值(2) | 插入 t2 值(2) | |
犯罪 | ||
插入 t1 值(3) | ||
犯罪 | ||
犯罪 |
寫集
其實是commit_order+writeset的組合，會先透過commit_order計算一個last_committed值，然後再透過writeset計算一個新值，最後取兩者間的小值作為最終交易gtid的last_committed。
在MySQL中，writeset本質上是對schema_name + table_name + primary_key/unique_key 計算的hash值，在DML執行語句過程中，透過binlog_log_row產生row_event之前，會將DML語句中所有的主鍵/唯一鍵都單獨計算hash值，並加入到交易本身的writeset清單中。而如果存在無主鍵/唯一索引的表，也會對事務設定has_missing_keys=true。
參數設定為WRITESET，但是不一定就能使用上，其限制如下
- 非DDL語句或表具有主鍵或唯一鍵或空事務
- 目前session使用的hash演算法與hash map中的一致
- 未使用外鍵
- hash map的容量未超過binlog_transaction_dependency_history_size的設定以上4個條件皆滿足時，則可使用WRITESET演算法，若有任一條件不滿足，則會退化為COMMIT_ORDER計算方式
圖片
具體WRITESET演算法如下，事務提交時：
- last_committed設定為m_writeset_history_start，此值為m_writeset_history清單中最小的sequence_number
- 遍歷交易的writeset列表a 如果某個writeset在全域m_writeset_history中不存在，建構一個pair<writeset, 當前交易的sequence_number>對象，插入到全域m_writeset_history列表中b. 如果存在，那麼last_committed=max(last_committed, 歷史writeset的sequence_number值)，並同時更新m_writeset_history中該writeset對應的sequence_number為目前交易值
- 如果has_missing_keys=false，即事務所有資料表均包含主鍵或唯一索引，則最後取commit_order和writeset兩種方式計算的最小值作為最終的last_committed值
圖片
TIPS：基於上面WRITESET規則，就會出現後提交的事務的last_committed比先提交的事務還小的情況
結論分析
結論描述
根據WRITESET的使用限制，對relay-log及事務中涉及到的表結構進行了對比，分析單last_committed的事務組成發現如下兩種情況：
- 單last_committed的交易中所涉及的資料和sequence_number有資料衝突
- 單last_committed的事務中涉及到的表存在無主鍵的情況，而且這種事務特別多
從上面的分析可以得出結論：無主鍵表的事務太多，導致WRITESET退化為COMMIT_ORDER，而由於資料庫為TP應用，事務都快速提交，多個事務提交無法保證在一個commit週期內，導致COMMIT_ORDER機制產生的last_committed重複讀取很低。從函式庫也就只能串列回放這些事務，造成回放延遲。
優化措施
- 從業務側對錶做改造，在允許的情況下為相關表都加上上主鍵。
- 嘗試調大參數binlog_group_commit_sync_delay、binlog_group_commit_sync_no_delay_count從0修改為10000，由於特殊環境限制，該調整並未生效，不同的場景可能會有不同的表現。