背景介紹
近來一套業務系統，從庫一直處於延遲狀態，無法追上主庫，導致業務風險較大。從資源上看，從庫的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 😃
關於 GreatSQL
GreatSQL是適用於金融級應用的國內自主開源資料庫，具備高效能、高可靠、高易用性、高安全等多個核心特性，可以作為MySQL或Percona Server的可選替換，用於線上生產環境，且完全免費併相容MySQL或Percona Server。
相關連結： GreatSQL社群 Gitee GitHub Bilibili
GreatSQL社群：
社群部落格有獎徵稿詳情：https://greatsql.cn/thread-100-1-1.html
技術交流群：
微信：掃碼新增
GreatSQL社群助手微信好友，傳送驗證資訊加群。
