從庫(kù)延遲案例分析，你學(xué)到了什么
背景介紹
近來(lái)一套業(yè)務(wù)系統(tǒng)，從庫(kù)一直處于延遲狀態(tài)，無(wú)法追上主庫(kù)，導(dǎo)致業(yè)務(wù)風(fēng)險(xiǎn)較大。從資源上看，從庫(kù)的CPU、IO、網(wǎng)絡(luò)使用率較低，不存在服務(wù)器壓力過(guò)高導(dǎo)致回放慢的情況；從庫(kù)開(kāi)啟了并行回放；在從庫(kù)上執(zhí)行show processlist看到?jīng)]有回放線程阻塞，回放一直在持續(xù)；解析relay-log日志文件，發(fā)現(xiàn)其中并沒(méi)大事務(wù)回放。
過(guò)程分析
現(xiàn)象確認(rèn)
收到運(yùn)維同事的反饋，有一套從庫(kù)延遲的非常厲害，提供了show slave status延遲的截圖信息
圖片
持續(xù)觀察了一陣show slave status的變化，發(fā)現(xiàn)pos點(diǎn)位信息在不停的變化，Seconds_Behind_master也是不停的變化的，總體趨勢(shì)還在不停的變大。
資源使用
觀察了服務(wù)器資源使用情況，可以看到占用非常低
圖片
觀察從庫(kù)進(jìn)程情況，基本上只能看到有一個(gè)線程在回放工作
圖片
并行回放參數(shù)說(shuō)明
在主庫(kù)設(shè)置了binlog_transaction_dependency_tracking=WRITESET
在從庫(kù)設(shè)置了slave_parallel_type=LOGICAL_CLOCK和slave_parallel_workers=64
error log日志對(duì)比
從error log中取并行回放的日志進(jìn)行分析
$ 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上述信息的詳細(xì)解釋，可以參考 MTS性能監(jiān)控你知道多少
去掉了發(fā)生次數(shù)比較少的統(tǒng)計(jì)，顯示了一些關(guān)鍵數(shù)據(jù)的對(duì)比
圖片
可以發(fā)現(xiàn)自然時(shí)間120，回放的協(xié)調(diào)線程有90多秒由于無(wú)法并行回放而進(jìn)入等待，有近20秒是由于沒(méi)有空閑的work線程進(jìn)入等待，折算下來(lái)協(xié)調(diào)線程工作的時(shí)間只有10秒左右。
并行度統(tǒng)計(jì)
眾所周知，mysql從庫(kù)并行回放主要依賴于binlog中的last_commmitted來(lái)做判斷，如果事務(wù)的last_committed相同，則基本上可以認(rèn)為這些事務(wù)可以并行回放，下面從環(huán)境中獲取一個(gè)relay log進(jìn)行并行回放的大概統(tǒng)計(jì)
$ 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上述第一條命令，是統(tǒng)計(jì)last_committed相同的事務(wù)數(shù)量在1-10個(gè)，即并行回放程度較低或者是無(wú)法并行回放，這些事務(wù)總數(shù)量為235703，占43%，詳細(xì)解析并行回放度比較低的事務(wù)分布，可以看出這部分last_committed基本上都是單條的，都需要等待先序事務(wù)回放完成后，自己才能進(jìn)行回放，這就會(huì)造成前面日志中觀察到的協(xié)調(diào)線程等待無(wú)法并行回放而進(jìn)入等待的時(shí)間比較長(zhǎng)的情況
$ 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第二條命令統(tǒng)計(jì)last_committed相同的事務(wù)數(shù)量超過(guò)10個(gè)的總事務(wù)數(shù)，其數(shù)量為314694，占57%，詳細(xì)解析了這些并行回放度比較高的事務(wù)，可以看到每一組是在6500~9000個(gè)事務(wù)數(shù)間
$ 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機(jī)制介紹
主庫(kù)的參數(shù)binlog_transaction_dependency_tracking用于指定如何生成其寫(xiě)入二進(jìn)制日志的依賴信息，以幫助從庫(kù)確定哪些事務(wù)可以并行執(zhí)行，即通過(guò)該參數(shù)控制last_committed的生成機(jī)制，參數(shù)可選值有COMMIT_ORDER、WRITESET、SESSION_WRITESET。從下面這段代碼，很容易看出來(lái)三種參數(shù)關(guān)系：
- 基礎(chǔ)算法為COMMIT_ORDER
- WRITESET算法是在COMMIT_ORDER基礎(chǔ)上再計(jì)算一次
- SESSION_WRITESET算法是在WRITESET基礎(chǔ)上再計(jì)算一次
圖片
由于我的實(shí)例設(shè)置的是WRITESET，因此關(guān)注COMMIT_ORDER算法和的WRITESET算法即可。
COMMIT_ORDER
COMMIT_ORDER計(jì)算規(guī)則：如果兩個(gè)事務(wù)在主節(jié)點(diǎn)上是同時(shí)提交的，說(shuō)明兩個(gè)事務(wù)的數(shù)據(jù)之間沒(méi)有沖突，那么一定也是可以在從節(jié)點(diǎn)上并行執(zhí)行的，理想中的典型案例如下面的例子
session-1 | session-2 |
BEGIN | BEGIN |
INSERT t1 values(1) | |
INSERT t2 values(2) | |
commit (group_commit) | commit (group_commit) |
但對(duì)于MySQL來(lái)說(shuō)，group_commit是內(nèi)部行為，只要session-1和session-2是同時(shí)執(zhí)行commit，不管內(nèi)部是否合并為group_commit，兩個(gè)事務(wù)的數(shù)據(jù)本質(zhì)上都是沒(méi)有沖突的；再退一步來(lái)講，只要session-1執(zhí)行commit之后，session-2沒(méi)有新的數(shù)據(jù)寫(xiě)入，兩個(gè)事務(wù)依舊沒(méi)有數(shù)據(jù)沖突，依然可以并行復(fù)制。
session-1 | session-2 |
BEGIN | BEGIN |
INSERT t1 values(1) | |
INSERT t2 values(2) | |
commit | |
commit |
對(duì)于更多并發(fā)線程的場(chǎng)景，可能這些線程不能同時(shí)并行復(fù)制，但部分事務(wù)卻可以。以如下一個(gè)執(zhí)行順序來(lái)說(shuō)，在session-3提交之后，session-2沒(méi)有新的寫(xiě)入，那么這兩個(gè)事務(wù)是可以并行復(fù)制的；而session-3提交后，session-1又插入了一條新的數(shù)據(jù)，此時(shí)無(wú)法判定數(shù)據(jù)沖突，所以session-3和session-1的事務(wù)無(wú)法并行復(fù)制；但session-2提交后，session-1之后沒(méi)有新數(shù)據(jù)寫(xiě)入，所以session-2和session-1又可以并行復(fù)制。因此，這個(gè)場(chǎng)景中，session-2分別可以和session-1，session-3并行復(fù)制，但3個(gè)事務(wù)無(wú)法同時(shí)并行復(fù)制。
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
實(shí)際上是commit_order+writeset的組合，會(huì)先通過(guò)commit_order計(jì)算出一個(gè)last_committed值，然后再通過(guò)writeset計(jì)算一個(gè)新值，最后取兩者間的小值作為最終事務(wù)gtid的last_committed。
在MySQL中，writeset本質(zhì)上是對(duì) schema_name + table_name + primary_key/unique_key 計(jì)算的hash值，在DML執(zhí)行語(yǔ)句過(guò)程中，通過(guò)binlog_log_row生成row_event之前，會(huì)將DML語(yǔ)句中所有的主鍵/唯一鍵都單獨(dú)計(jì)算hash值，并加入到事務(wù)本身的writeset列表中。而如果存在無(wú)主鍵/唯一索引的表，還會(huì)對(duì)事務(wù)設(shè)置has_missing_keys=true。
參數(shù)設(shè)置為WRITESET，但是并不一定就能使用上，其限制如下
- 非DDL語(yǔ)句或者表具有主鍵或者唯一鍵或者空事務(wù)
- 當(dāng)前session使用的hash算法與hash map中的一致
- 未使用外鍵
- hash map的容量未超過(guò)binlog_transaction_dependency_history_size的設(shè)置 以上4個(gè)條件均滿足時(shí)，則可以使用WRITESET算法，如果有任意一個(gè)條件不滿足，則會(huì)退化為COMMIT_ORDER計(jì)算方式
圖片
具體WRITESET算法如下，事務(wù)提交時(shí)：
- last_committed設(shè)置為m_writeset_history_start，此值為m_writeset_history列表中最小的sequence_number
- 遍歷事務(wù)的writeset列表a 如果某個(gè)writeset在全局m_writeset_history中不存在，構(gòu)建一個(gè)pair<writeset, 當(dāng)前事務(wù)的sequence_number>對(duì)象，插入到全局m_writeset_history列表中b. 如果存在，那么last_committed=max(last_committed, 歷史writeset的sequence_number值)，并同時(shí)更新m_writeset_history中該writeset對(duì)應(yīng)的sequence_number為當(dāng)前事務(wù)值
- 如果has_missing_keys=false，即事務(wù)所有數(shù)據(jù)表均包含主鍵或者唯一索引，則最后取commit_order和writeset兩種方式計(jì)算的最小值作為最終的last_committed值
圖片
TIPS：基于上面WRITESET規(guī)則，就會(huì)出現(xiàn)后提交的事務(wù)的last_committed比先提交的事務(wù)還小的情況
結(jié)論分析
結(jié)論描述
根據(jù)WRITESET的使用限制，對(duì)relay-log及事務(wù)中涉及到的表結(jié)構(gòu)進(jìn)行了對(duì)比，分析單last_committed的事務(wù)組成發(fā)現(xiàn)如下兩種情況：
- 單last_committed的事務(wù)中涉及到的數(shù)據(jù)和sequence_number存在數(shù)據(jù)沖突
- 單last_committed的事務(wù)中涉及到的表存在無(wú)主鍵的情況，而且這種事務(wù)特別多
從上面的分析中可以得出結(jié)論：無(wú)主鍵表的事務(wù)太多，導(dǎo)致WRITESET退化為COMMIT_ORDER，而由于數(shù)據(jù)庫(kù)為TP應(yīng)用，事務(wù)都快速提交，多個(gè)事務(wù)提交無(wú)法保證在一個(gè)commit周期內(nèi)，導(dǎo)致COMMIT_ORDER機(jī)制產(chǎn)生的last_committed重復(fù)讀很低。從庫(kù)也就只能串行回放這些事務(wù)，引起回放延遲。
優(yōu)化措施
- 從業(yè)務(wù)側(cè)對(duì)表做改造，在允許的情況下給相關(guān)表都添加上主鍵。
- 嘗試調(diào)大參數(shù)binlog_group_commit_sync_delay、binlog_group_commit_sync_no_delay_count從0修改為10000，由于特殊環(huán)境限制，該調(diào)整并未生效，不同的場(chǎng)景可能會(huì)有不同的表現(xiàn)。
