背景介紹 近來一套業務系統，從庫一直處於延遲狀態，無法追上主庫，導致業務風險較大。從資源上看，從庫的CPU、IO、網路使用率較低，不存在伺服器壓力過高導致回放慢的情況；從庫開啟了並行回放；在從庫上執行show processlist看到沒有回放線程阻塞，回放一直在持續；解析relay-log日誌文件 ...
背景介紹
近來一套業務系統，從庫一直處於延遲狀態，無法追上主庫，導致業務風險較大。從資源上看，從庫的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
上述信息的詳細解釋，可以參考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
上述第一條命令，是統計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
第二條命令統計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%
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
COMMIT_ORDER計算規則：如果兩個事務在主節點上是同時提交的，說明兩個事務的數據之間沒有衝突，那麼一定也是可以在從節點上並行執行的，理想中的典型案例如下麵的例子
| session-1 | session-2 |
|---|---|
| BEGIN | BEGIN |
| INSERT t1 values(1) | |
| INSERT t2 values(2) | |
| commit (group_commit) | commit (group_commit) |
但對於MySQL來說，group_commit是內部行為，只要session-1和session-2是同時執行commit，不管內部是否合併為group_commit，兩個事務的數據本質上都是沒有衝突的；再退一步來講，只要session-1執行commit之後，session-2沒有新的數據寫入，兩個事務依舊沒有數據衝突，依然可以並行複製。
| session-1 | session-2 |
|---|---|
| BEGIN | BEGIN |
| INSERT t1 values(1) | |
| INSERT t2 values(2) | |
| commit | |
| commit |
對於更多併發線程的場景，可能這些線程不能同時並行複製，但部分事務卻可以。以如下一個執行順序來說，在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個事務無法同時並行複製。
| session-1 | session-2 | session-3 |
|---|---|---|
| BEGIN | BEGIN | BEGIN |
| INSERT t1 values(1) | INSERT t2 values(1) | INSERT t3 values(1) |
| INSERT t1 values(2) | INSERT t2 values(2) | |
| commit | ||
| INSERT t1 values(3) | ||
| commit | ||
| commit |
WRITESET
實際上是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，由於特殊環境限制，該調整並未生效，不同的場景可能會有不同的表現。
Enjoy GreatSQL
