MySQL的binlog相信大家都有所耳聞，但是可能沒有真正日常使用過。

因此，本文結(jié)合一個(gè)otter小坑的排查案例，來分享下binlog的日常使用方式。

重點(diǎn)了解下：

• binlog的導(dǎo)出方式
• binlog的解析方式
• 結(jié)合案例分享下開源項(xiàng)目otter的一個(gè)小坑

1.案例背景

某個(gè)周末突然收到報(bào)警，發(fā)現(xiàn)線上多云數(shù)據(jù)庫的數(shù)據(jù)同步任務(wù)掛起，顯示日志寫入數(shù)據(jù)失敗。

錯(cuò)誤原因非常明顯：

唯一索引沖突。

查看了一下源庫的數(shù)據(jù)內(nèi)容，確實(shí)已經(jīng)update完畢。而目標(biāo)庫的數(shù)據(jù)內(nèi)容，確實(shí)存在沖突導(dǎo)致無法update。

2.排查過程

這個(gè)數(shù)據(jù)同步任務(wù)，使用了阿里開源的數(shù)據(jù)庫同步項(xiàng)目otter。難道遇到了什么bug?

otter項(xiàng)目是阿里巴巴開源的數(shù)據(jù)庫同步系統(tǒng)。

基于數(shù)據(jù)庫增量日志解析，準(zhǔn)實(shí)時(shí)同步到本機(jī)房或異地機(jī)房的mysql/oracle數(shù)據(jù)庫的一個(gè)分布式數(shù)據(jù)庫同步系統(tǒng)。

直接開始排查問題。

2.1 表結(jié)構(gòu)是否一致

為什么源庫沒有沖突，目標(biāo)庫會(huì)有沖突呢?是不是表結(jié)構(gòu)不一致?或者是源庫發(fā)生了表結(jié)構(gòu)變更沒有同步到目標(biāo)庫?

確認(rèn)了下源庫的表結(jié)構(gòu)和目標(biāo)庫表結(jié)構(gòu)是一致的，且都有對應(yīng)的唯一索引udx_position。

2.2 排查源庫binlog

那源庫到底是怎么更新成功的?只能撈一下binlog了。

首先導(dǎo)出線上正在使用的binlog文件。

在數(shù)據(jù)庫上執(zhí)行

flush logs 

這個(gè)命令會(huì)關(guān)閉當(dāng)前正在寫入的binlog文件，然后生成一個(gè)序號加1的新的binlog文件讓mysql server繼續(xù)使用。

等待幾分鐘，讓當(dāng)前的binlog落盤為日志文件，本案例中為xxxx_binlog_mysqlbin.000005。

然后下載到本地。

通過mysqlbinlog命令解析，輸出為指定文件xxx.binlog，如下：

mysqlbinlog  --start-datetime='2020-11-20 18:17:00' --stop-datetime='2020-11-20 18:21:01' --base64-output=decode-rows -v -d db xxxx_binlog_mysqlbin.000005 > xxx.binlog 

• binlog格式binlog_format采用row模式。僅保存記錄被修改細(xì)節(jié)，不記錄sql語句上下文相關(guān)信息優(yōu)點(diǎn)：能非常清晰的記錄下每行數(shù)據(jù)的修改細(xì)節(jié)，不需要記錄上下文相關(guān)信息，因此不會(huì)發(fā)生某些特定情況下的procedure、function、及trigger的調(diào)用觸發(fā)無法被正確復(fù)制的問題，任何情況都可以被復(fù)制，且能加快從庫重放日志的效率，保證從庫數(shù)據(jù)的一致性。
• 通過 --start-datatime和--stop-datetime指定解析的起止時(shí)間
• row模式生成的sql編碼需要解碼，不能用常規(guī)的辦法去生成，需要加上相應(yīng)的參數(shù)(--base64-output=decode-rows -v)才能顯示出sql語句

binlog的內(nèi)容解析后sql的過程如下(為了更好地看清過程，這里不展示binlog原文，而是一個(gè)邏輯過程)：

我們能清楚地看到，源庫通過一個(gè)事務(wù)中，交換position(唯一索引的列)的值，達(dá)到更新唯一索引而不造成沖突的目的。

那目標(biāo)庫為什么會(huì)沖突呢?

2.3 查看目標(biāo)庫的sql審計(jì)

由于數(shù)據(jù)同步失敗掛起，所以目標(biāo)庫的同步數(shù)據(jù)暫時(shí)不會(huì)寫入對應(yīng)的binlog記錄。

因此，我們需要通過sql審計(jì)來查看目標(biāo)庫的寫入情況。

這里同樣展示sql審計(jì)中撈出的相關(guān)過程：

Oh～ My～ God!

事務(wù)中間的update交換過程居然被合并了!!

所以造成了唯一索引沖突，更新失敗。

3.求證

重新去翻了一遍otter的wiki，看到了關(guān)于《otter數(shù)據(jù)入庫算法》說明。

https://github.com/alibaba/otter/wiki/Otter%E6%95%B0%E6%8D%AE%E5%85%A5%E5%BA%93%E7%AE%97%E6%B3%95

確實(shí)存在操作合并的情況。

這樣做許多好處：

• insert/行記錄update 執(zhí)行merge sql，解決重復(fù)數(shù)據(jù)執(zhí)行
• 合并算法執(zhí)行后，單pk主鍵只有一條記錄，減少并行l(wèi)oad算法的復(fù)雜性(比如batch合并，并行/串行等處理)
• 同步速度相比于mysql的復(fù)制，拋棄了強(qiáng)一致性，約有5倍左右的性能提升

找了下源碼，定位到DbLoadAction類

令人遺憾的是，我們發(fā)現(xiàn)竟然沒有開關(guān)可以控制。

4.解決方案。

到上面基本已經(jīng)水落石出，找到了問題的根本原因。由于otter對事務(wù)內(nèi)的update操作進(jìn)行了合并，導(dǎo)致了目標(biāo)庫唯一索引沖突。

那怎么解決呢?

看到文檔上有這么一句話

那么，對應(yīng)到這個(gè)案例，或者說其他唯一索引的變更，只能通過 先刪除，再插入，而不是通過update進(jìn)行交換。