深度分析 | MGR相同GTID產生不一樣transaction故障分析

問題現象

這是在生產環境中一組MGR集羣，單主架構，咱們能夠看到在相同的GTID86afb16f-1b8c-11e8-812f-0050568912a4:57305280下，本應執行相同的事務，但binlog日誌顯示不一樣事務信息。

 

• Primary節點binlog：

SET @@SESSION.GTID_NEXT= '86afb16f-1b8c-11e8-812f-0050568912a4:57305280'/*!*/;
# at 637087357
#190125 15:02:55 server id 3136842491 end_log_pos 637087441 Query
thread_id=19132957 exec_time=0 error_code=0
SET TIMESTAMP=1548399775/*!*/;
BEGIN
/*!*/;
# at 637087441
#190125 15:02:55 server id 3136842491 end_log_pos 637087514 Table_map:
`world`.`IC_WB_RELEASE` mapped to number 398
# at 637087514
#190125 15:02:55 server id 3136842491 end_log_pos 637087597 Write_rows: table id 398
flags: STMT_END_F
BINLOG '
n7RKXBP7avi6SQAAABov+SUAAI4BAAAAAAEAB2ljZW50ZXIAFUlDX1FVRVJZX1VTRVJDQVJEX0xP
'/*!*/;
### INSERT INTO `world`.`IC_WB_RELEASE`
### SET

• Secondary節點binlog：

SET @@SESSION.GTID_NEXT= '86afb16f-1b8c-11e8-812f-0050568912a4:57305280'/*!*/;
# at 543772830
#190125 15:02:52 server id 3136842491 end_log_pos 543772894 Query
thread_id=19162514 exec_time=318 error_code=0
SET TIMESTAMP=1548399772/*!*/;
BEGIN
/*!*/;
# at 543772894
#190125 15:02:52 server id 3136842491 end_log_pos 543772979 Table_map:
`world`.`IC_QUERY_USERCARD_LOG` mapped to number 113
# at 543772979
#190125 15:02:52 server id 3136842491 end_log_pos 543773612 Delete_rows: table id
113 flags: STMT_END_F
BINLOG '
nLRKXBP7avi6VQAAADNRaSAAAHEAAAAAAAEAB2ljZW50ZXIADUlDX1dCX1JFTEVBU0UACw8PEg8
'/*!*/;
### DELETE FROM `world`.`IC_QUERY_USERCARD_LOG`
### WHERE

從以上信息能夠推測，primary節點在這個GTID下對world.IC_WB_RELEASE表執行了insert操做事件沒有同步到secondary節點，secondary節點收到主節點的其餘事件，形成了數據是不一致的。當在表IC_WB_RELEASE發生delete操做時，引起了下面的故障，致使從節點脫離集羣。

2019-01-28T11:59:30.919880Z 6 [ERROR] Slave SQL for channel 'group_replication_applier': Could not execute Delete_rows event on table `world`.`IC_WB_RELEASE`; Can't find record in 'IC_WB_RELEASE', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND, Error_code: 1032
2019-01-28T11:59:30.919926Z 6 [Warning] Slave: Can't find record in 'IC_WB_RELEASE' Error_code: 1032
2019-01-28T11:59:30.920095Z 6 [ERROR] Plugin group_replication reported: 'The applier thread execution was aborted. Unable to process more transactions, this member will now leave the group.'
2019-01-28T11:59:30.920165Z 6 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'FIRST' position 271.
2019-01-28T11:59:30.920220Z 3 [ERROR] Plugin group_replication reported: 'Fatal error during execution on the Applier process of Group Replication. The server will now leave the group.'
2019-01-28T11:59:30.920298Z 3 [ERROR] Plugin group_replication reported: 'The server was automatically set into read only mode after an error was detected.'

問題分析

• 1. 主節點在向從節點同步事務時，至少有一個GTID爲86afb16f-1b8c-11e8-812f-0050568912a4:57305280（執行的是insert操做）的事務沒有同步到從節點，此時從實例還不存在這個GTID；因而主實例GTID高於從實例。數據就已經不一致了。

  
  

• 2. 集羣業務正常進行，GTID持續上漲，新上漲的GTID同步到了從實例，佔用了86afb16f-1b8c-11e8-812f-0050568912a4:57305280這個GTID，因此從實例沒有執行insert操做，少了一部分數據。

  
  

• 3. 主節點對GTID爲86afb16f-1b8c-11e8-812f-0050568912a4:57305280執行的insert數據進行delete，而從節點因爲沒有同步到本來的insert操做；沒有這部分數據就不能delete，因而脫離了集羣。

對於該故障的分析，咱們要從主從實例GTID相同，可是事務不一樣的緣由入手，該問題猜想與bug（https://bugs.mysql.com/bug.php?id=92690）相關，咱們針對MGR同步事務的時序作以下分析。

相關知識背景

MGR全組同步數據的Xcom組件是基於paxos算法的實現；每當提交新生事務時，主實例會將新生事務發送到從實例進行協商，組內協商經過後全組成員一塊兒提交該事務；每個節點都以一樣的順序，接收到了一樣的事務日誌，因此每個節點以一樣的順序回放了這些事務，最終組內保持了一致的狀態。

paxos包括兩個角色：

• 提議者（Proposer）：主動發起投票選主，容許發起提議。

• 接受者（Acceptor）：被動接收提議者（Proposer）的提議，並記錄和反饋，或學習達成共識的提議。

paxos達成共識的過程包括兩個階段：

• 第一階段（prepare）

• a：提議者（Proposer）發送prepare請求，附帶本身的提案標識（ballot，由數值編號加節點編號組成）以及value值。組成員接收prepare請求；

• b：若是自身已經有了確認的值，則將該值以ack_prepare形式反饋；在這個階段中，Proposer收到ack回覆後會對比ballot值，數值大的ballot會取代數值小的ballot。若是收到大多數應答以後進入下一個階段。

• 第二階段（accept）

• a：提議者（Proposer）發送accept請求

• b：接收者（Acceptor）收到請求後對比自身以前的bollat是否相同以及是否接收過value值。若是未接受過value值 以及ballot相同，則返回ack_accept，若是接收過value值，則選取最大的ballot返回ack_accept。

• c：以後接受相同value值的Proposer節點發送learn_op，收到learn_op節點的實例表示確認了數據修改，傳遞給上層應用。

針對本文案例咱們須要強調幾個關鍵點：

• 1. 該案例最根本的異常對比發生在第二次提案的prepare階段。

• 2. prepare階段的提案標識由數值編號和節點編號兩部分組成；其中數值編號相似自增加數值，而節點編號不變。

 

分析過程

結合paxos時序，咱們對案例過程進行推測：

Tips：如下分析過程請結合時序圖操做步驟觀看

建議點開放大，效果更清晰 ^ ^

1. 【step1】primary節點要執行對錶world.IC_WB_RELEASE的insert操做，向組內發送假設將ballot設置爲（0.0）以及將value值world.IC_WB_RELEASE的prepare請求，並收到大多數成員的ack_prepare返回，因而開始發送accept請求。primary節點將ballot（0.0）的提案信息發送至組內，仍收到了大多數成員ack_accept（ballot=0.0value=world.IC_WB_RELEASE）返回。而後發送learn_op信息【step3】。

2. 同時其餘從節點因爲網絡緣由沒有收到主實例的的learn_op信息【step3】，而其中一臺從實例開始新的prepare請求【step2】，請求value值爲no_op（空操做）ballot=1.1（此編號中節點編號是關鍵，該secondary節點編號大於primary節點編號，致使了後續的問題，數值編號不管誰大誰小都要被初始化）。

其餘的從實例因爲收到過主節點的value值；因此將主節點的（ballot=0.0，value=world.IC_WB_RELEASE）返回；而收到的ack_prepare的ballot值的數值符號全組內被初始化爲0，整個ballot的大小徹底由節點編號決定，因而從節點選取了ballot較大的該實例value值做爲新的提案，覆蓋了主實例的value值並收到大多數成員的ack_accept【step2】。並在組成員之間發送了learn_op信息【step3】，跳過了主實例提議的事務。

從源碼中能夠看到關於handle_ack_prepare的邏輯。

handle_ack_prepare has the following code:
    if (gt_ballot(m->proposal,p->proposer.msg->proposal))
        {
            replace_pax_msg(&p->proposer.msg, m);
            ...
            }

3. 此時，主節點在accept階段收到了組內大多數成員的ack_accept並收到了 本身所發送的learn_op信息，因而把本身的提案（也就是binlog中對錶的insert操做）提交【step3】，該事務GTID爲86afb16f-1b8c-11e8-812f-0050568912a4:57305280。而其餘節點的提案爲no_op【step3】，因此不會提交任何事務。此時主實例GTID大於其餘從實例的。

4. 主節點新生GTID繼續上漲；同步到從實例，佔用了從實例的86afb16f-1b8c-11e8-812f-0050568912a4:57305280這個GTID，因而產生了主節點與從節點binlog中GTID相同可是事務不一樣的現象。

5. 當業務執行到對錶world.IC_WB_RELEASE的delete操做時，主實例能進行操做，而其餘實例因爲沒有insert過數據，不能操做，就脫離了集羣。

▽過程總結：

• 1. 舊主發送prepare請求，收到大多數ack，進入accept階段，收到大多數ack。

• 2. 從實例因爲網絡緣由沒有收到learn_op信息。

• 3. 其中一臺從實例發送新的prepare請求，value爲no_op。

• 4. 新一輪的prepare請求中，提案標識的數值編號被初始化，新的提案者大於主實例，從實例選取新提案，執行空操做，不寫入relay-log。代替了主實例的事務，使主實例GTID大於從實例。

• 5. 集羣網絡狀態恢復，新生事物正常同步到從實例，佔用了本該正常同步的GTID，使集羣中主節點與從節點相同GTID對應的事務時不一樣的。

  

結論

針對此問題咱們也向官方提交SR，官方已經反饋社區版MySQL 5.7.26和MySQL 8.0.16 中會修復，若是是企業版客戶能夠申請最新的hotfix版本。

在未升級 MySQL 版本前，若再發生此類故障，在修復時須要人工檢查，檢查切換時binlog中 GTID 信息與新主節點對應 GTID 的信息是否一致。若是不一致須要人工修復至一致狀態，若是一致才能夠將被踢出的原主節點加回集羣。