從庫延遲案例分析，你學到了什么
背景介紹
近來一套業務系統，從庫一直處于延遲狀態，無法追上主庫，導致業務風險較大。從資源上看，從庫的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，由于特殊環境限制，該調整并未生效，不同的場景可能會有不同的表現。
