[[197701]]

主從復(fù)制作為 MySQL 的精髓，有兩大困難：主從數(shù)據(jù)的延時(shí)與數(shù)據(jù)的不一致性。針對(duì)數(shù)據(jù)不一致的排查處理，相信各位大佬們都有豐富的處理經(jīng)驗(yàn)，我就不多說(shuō)了。

本文主要是給大家分享一個(gè)工作中遇到的奇葩事例：由于一個(gè)極隱式的騷操作，導(dǎo)致從庫(kù)丟失數(shù)據(jù)(數(shù)據(jù)丟失量在每天將近萬(wàn)條記錄)!

環(huán)境描述

業(yè)務(wù)環(huán)境：短時(shí)間內(nèi)(幾個(gè)月的時(shí)間)，業(yè)務(wù)蓬勃發(fā)展，客戶量從一兩萬(wàn)一下增加到幾十萬(wàn)用戶。

數(shù)據(jù)庫(kù)環(huán)境，如下圖：

問(wèn)題描述

某天，主庫(kù) 10.0.0.1 的 CPU 使用率突然升高，均值達(dá)到 80%+，導(dǎo)致 Keepalived 的 VIP 漂移至從庫(kù) 10.0.0.2。

理論上丟失的是切換過(guò)程中的幾秒鐘數(shù)據(jù)，業(yè)務(wù)側(cè)對(duì)丟失的這幾秒數(shù)據(jù)表示沒(méi)關(guān)系，那么這個(gè)事件到此應(yīng)該就結(jié)束了。

然而當(dāng)天晚上，業(yè)務(wù)打電話過(guò)來(lái)說(shuō)：丟失了部分用戶信息，導(dǎo)致用戶登入不了，要求幫忙恢復(fù)數(shù)據(jù)并查找數(shù)據(jù)丟失的原因。

本文對(duì)數(shù)據(jù)恢復(fù)這塊就不具體展開了，稍微提一下，這邊因?yàn)樾轮?10.0.0.2 已經(jīng)有數(shù)據(jù)寫入，只能對(duì)比用戶表數(shù)據(jù)把新主少的數(shù)據(jù)導(dǎo)入進(jìn)去。

初步排查

對(duì)于主從復(fù)制丟失數(shù)據(jù)，解決方法沒(méi)有捷徑，只能老老實(shí)實(shí)地跟蹤數(shù)據(jù)復(fù)制過(guò)程，查看是哪里出了問(wèn)題。

選擇丟失數(shù)據(jù)中時(shí)間比較近的，時(shí)間為 2017-06-09 13:36:01，ID為 849791 這條數(shù)據(jù)，來(lái)跟蹤整個(gè)復(fù)制過(guò)程，因?yàn)槿罩局槐Ａ?14 天的。

分析主庫(kù) binlog 日志，binlog 日志中是有這條記錄的。

分析從庫(kù)日志：因?yàn)閿?shù)據(jù)庫(kù)配置了 relay_log_purge 與 log-slave-updates，所以中繼日志已經(jīng)找不到這個(gè)時(shí)間點(diǎn)了，只能查看從庫(kù) binlog 日志。

然而在從庫(kù)的 binlog 日志中并未找到這條記錄，說(shuō)明這條數(shù)據(jù)是未執(zhí)行，排除后期人為刪除的，那么數(shù)據(jù)為何不被執(zhí)行呢?或者說(shuō)數(shù)據(jù)是在執(zhí)行過(guò)程中丟失的?

數(shù)據(jù)分析

無(wú)可用的中繼日志怎么辦?難道沒(méi)辦法查了?于是我決定觀察和對(duì)比一下丟失的數(shù)據(jù)，看看其中是否含有什么規(guī)律，是不定時(shí)丟失數(shù)據(jù)，還是會(huì)在某些特定時(shí)刻丟失數(shù)據(jù)。

整理了一下某表丟失的數(shù)據(jù)，通過(guò)觀察、分析丟失數(shù)據(jù)的屬性(下圖是我截取的部分列，***一列的時(shí)間是創(chuàng)建時(shí)間，也就是寫表時(shí)間)：

從圖中可以看出，丟失的數(shù)據(jù)的插表時(shí)間都是在每分鐘的前 2 秒。這不由地讓人思考，為何丟失的數(shù)據(jù)是每分鐘前 2 秒的呢?

而且數(shù)據(jù)丟失的時(shí)間間隔也不是很長(zhǎng)，基本隔幾天就肯定有數(shù)據(jù)丟失。經(jīng)過(guò)這樣分析，事情似乎就變得簡(jiǎn)單了。

深入調(diào)查

首先，關(guān)閉 log-slave-updates、relay_log_purge 等一切影響判斷的額外參數(shù)設(shè)置，等待一段時(shí)間后，再來(lái)對(duì)比某表新數(shù)據(jù)丟失情況。

可以看到又有新數(shù)據(jù)丟失，根據(jù)這些丟失數(shù)據(jù)再來(lái)排查問(wèn)題。

首先先查主庫(kù)，查看主庫(kù)的 binlog 日志狀體信息狀態(tài)。

就以 2017-6-17 15:17:02 ***丟失的這條數(shù)據(jù)來(lái)跟蹤，查看主庫(kù) 10.0.0.2 上的 binlog 日志中是否存在這條數(shù)據(jù)：

 結(jié)果顯示主庫(kù)是存在這條數(shù)據(jù)的

在登入從庫(kù)查看 relay-log 日志情況，發(fā)現(xiàn) relay-log 日志生成太頻繁，每分鐘生成 1 個(gè) relay-log 日志，而且有些文件大小又不一致。

那么這套主從集群，業(yè)務(wù)肯定部署過(guò)分割 relay-log 日志的腳本，而且應(yīng)該是 flush 來(lái)強(qiáng)制刷新的。如圖：

 我們先來(lái)看從庫(kù) relay-log 日志中是否存在這條數(shù)據(jù)，查找17分生成的relay日志，提取前 2 秒能匹配的插入情況。

 發(fā)現(xiàn)并沒(méi)有這條 insert 操作，難道數(shù)據(jù)未寫入 relay 日志，刷新日志時(shí)導(dǎo)致事務(wù)丟失? 把查詢時(shí)間拉長(zhǎng)至 50 秒。

 發(fā)現(xiàn)也沒(méi)有這條數(shù)據(jù)，并且數(shù)據(jù)跟前面 2 秒的一致，那么其它數(shù)據(jù)呢?會(huì)不會(huì)在下一個(gè)日志中?

趕緊去 18 分生成的 relay 日志查看，發(fā)現(xiàn)這條數(shù)據(jù)在 15:18 分這個(gè) relay 日志中的***個(gè)事務(wù)的位置。

 那么是沒(méi)有執(zhí)行，還是執(zhí)行過(guò)程丟失?仔細(xì)觀察主庫(kù) binlog 與從 relay-log 日志的記錄，也沒(méi)能看出什么名堂，從事務(wù)開始到 commit，都一樣。

問(wèn)題定位

如果一條數(shù)據(jù)無(wú)法比較，那就再隨機(jī)拿出幾條丟失的數(shù)據(jù)來(lái)跟蹤。發(fā)現(xiàn)情況都一樣，數(shù)據(jù)都已經(jīng)復(fù)制到 relay 日志中，而且內(nèi)容根本看不出為何不能執(zhí)行。

唯一有疑點(diǎn)的是這些事務(wù)都在日志的***個(gè)事務(wù)中。頓時(shí)，我有種想法，會(huì)不會(huì)強(qiáng)制刷新 relay 日志，造成日志的***個(gè)事務(wù)有時(shí)不執(zhí)行，或執(zhí)行過(guò)程中丟失?

如果是腳本引起的，那么除去這些事務(wù)未執(zhí)行外，肯定還有其它事務(wù)也未執(zhí)行。那么，我就隨機(jī)選擇幾個(gè) relay-log 日志，找到***個(gè)事務(wù)。

具體分析如下：

 再登入從庫(kù)查詢結(jié)果：

 可以看出從庫(kù)數(shù)據(jù)并未更新。隨后，隨機(jī)分析了幾個(gè) relay 日志，發(fā)現(xiàn)***個(gè)事務(wù)都未被執(zhí)行。而且操作的表都是有不同的，操作也是有不同，有 insert、update 等等，頓時(shí)感覺(jué)事情大條了。

如果每個(gè)日志的***個(gè)事務(wù)都未執(zhí)行，那么從庫(kù)要缺少多少條數(shù)據(jù)?不敢想象，現(xiàn)在業(yè)務(wù)還在上升期，不久業(yè)務(wù)量會(huì)是現(xiàn)在的幾倍，甚至更多，到那時(shí)就不是用戶投訴那么簡(jiǎn)單了。

又抓取了部分 relay 日志情況，***個(gè)事務(wù)也都未被執(zhí)行。我可以肯定了，是所有 relay 日志的***個(gè)事務(wù)都未被執(zhí)行。

這個(gè)問(wèn)題也可以是由于分割 relay 日志的腳本造成的。一般強(qiáng)制刷新日志是用 flush 命令來(lái)操作的，flush 命令一般不會(huì)造成數(shù)據(jù)丟失，當(dāng)然像他們這樣頻繁的操作，我是不知道會(huì)不會(huì)造成 Bug，導(dǎo)致丟數(shù)據(jù)。

還有在 flush relay logs 的時(shí)候有沒(méi)有用到其他的什么操作呢?我決定抓一把數(shù)據(jù)庫(kù)中操作過(guò)的命令。

抓取命令，問(wèn)題解決

想到就做，登上從庫(kù)主機(jī)、登入數(shù)據(jù)庫(kù)，開啟 general_log 日志。坐等 5 分鐘，打開日志，尋找每分鐘前幾秒的記錄。

哇!哇!哇!

你們猜我看到了什么? 我從未見過(guò)如此騷的操作!上圖，以表我的震驚。

 為什么要跳過(guò)事務(wù)?你用 stop slave 與 Start slave 來(lái)刷新 relay 日志，已經(jīng)刷新了我的三觀，那，有必要跳過(guò)事務(wù)?這就解釋得通了，為何 relay 日志***個(gè)事務(wù)全都丟失。

至此!問(wèn)題已經(jīng)清晰，是由于開發(fā)設(shè)置的分割 relay 日志的腳本，使用了非常規(guī)命令及 sql_slave_skip_counter 跳過(guò)事務(wù)命令來(lái)分隔 relay-log 日志，導(dǎo)致事務(wù)大量丟失。

所以，創(chuàng)新是好事，但要打好基本功，別搞些騷操作。

[[197703]]

 洪凌

新炬網(wǎng)絡(luò)資深 MySQL 工程師

超過(guò) 7 年 MySQL 數(shù)據(jù)庫(kù)運(yùn)維經(jīng)驗(yàn)，擅長(zhǎng)數(shù)據(jù)庫(kù)運(yùn)維體系、集群架構(gòu)建設(shè)，熟悉 MySQL 性能優(yōu)化，對(duì)數(shù)據(jù)庫(kù)監(jiān)控系統(tǒng)也有著獨(dú)特的理解。