日均萬條資料丟失,一個隱式騷操作導致的奇葩事故!
資料庫環境,如下圖:
問題描述
某天,主庫10.0.0.1的CPU使用率突然升高,均值達到80%+,導致Keepalived的VIP漂移至從庫10.0.0.2。理論上丟失的是切換過程中的幾秒鐘資料,業務側對丟失的這幾秒資料表示沒關係,那麼這個事件到此應該就結束了。
然而當天晚上,業務打電話過來說:丟失了部分使用者資訊,導致使用者登入不了,要求幫忙恢復資料並查詢資料丟失的原因。本文對資料恢復這塊就不具體展開了,稍微提一下,這邊因為新主10.0.0.2已經有資料寫入,只能對比使用者表資料把新主少的資料匯入進去。
初步排查
對於主從複製丟失資料,解決方法沒有捷徑,只能老老實實地跟蹤資料複製過程,檢視是哪裡出了問題。
選擇丟失資料中時間比較近的,時間為2017-06-09 13:36:01,ID為849791這條資料,來跟蹤整個複製過程,因為日誌只保留14天的。
分析主庫binlog日誌,binlog日誌中是有這條記錄的。
分析從庫日誌:因為資料庫配置了relay_log_purge與log-slave-updates,所以中繼日誌已經找不到這個時間點了,只能檢視從庫binlog日誌。然而在從庫的binlog日誌中並未找到這條記錄,說明這條資料是未執行,排除後期人為刪除的,那麼資料為何不被執行呢?或者說資料是在執行過程中丟失的?
資料分析
無可用的中繼日誌怎麼辦?難道沒辦法查了?於是我決定觀察和對比一下丟失的資料,看看其中是否含有什麼規律,是不定時丟失資料,還是會在某些特定時刻丟失資料。
整理了一下某表丟失的資料,通過觀察、分析丟失資料的屬性(下圖是我擷取的部分列,最後一列的時間是建立時間,也就是寫表時間):
從圖中可以看出,丟失的資料的插表時間都是在每分鐘的前兩秒。這不由地讓人思考,為何丟失的資料是每分鐘前2秒的呢?而且資料丟失的時間間隔也不是很長,基本隔幾天就肯定有資料丟失。經過這樣分析,事情似乎就變得簡單了。
深入調查
首先,關閉log-slave-updates、relay_log_purge等一切影響判斷的額外引數設定,等待一段時間後,再來對比某表新資料丟失情況。
可以看到又有新資料丟失,根據這些丟失資料再來排查問題。
首先先查主庫,檢視主庫的binlog日誌狀體資訊狀態。
就以2017-6-17 15:17:02最新丟失的這條資料來跟蹤,檢視主庫10.0.0.2上的binlog日誌中是否存在這條資料:
結果顯示主庫是存在這條資料的。
在登入從庫檢視relay-log日誌情況,發現relay-log日誌生成太頻繁,每分鐘生成1個relay-log日誌,而且有些檔案大小又不一致。那麼這套主從叢集,業務肯定部署過分割relay-log日誌的指令碼,而且應該是flush來強制重新整理的。如圖:
我們先來看從庫relay-log日誌中是否存在這條資料,查詢17分生成的relay日誌,提取前兩秒能匹配的插入情況。
發現並沒有這條insert操作,難道資料未寫入relay日誌,重新整理日誌時導致事務丟失? 把查詢時間拉長至50秒。
發現也沒有這條資料,並且資料跟前面兩秒的一致,那麼其它資料呢?會不會在下一個日誌中?趕緊去18分生成的relay日誌檢視,發現這條資料在15:18分這個relay日誌中的第一個事務的位置。
那麼是沒有執行,還是執行過程丟失?仔細觀察主庫binlog與從relay-log日誌的記錄,也沒能看出什麼名堂,從事務開始到commit,都一樣。
問題定位
如果一條資料無法比較,那就再隨機拿出幾條丟失的資料來跟蹤。發現情況都一樣,資料都已經複製到relay日誌中,而且內容根本看不出為何不能執行。
唯一有疑點的是這些事務都在日誌的第一個事務中。頓時,我有種想法,會不會強制重新整理relay日誌,造成日誌的第一個事務有時不執行,或執行過程中丟失?如果是指令碼引起的,那麼除去這些事務未執行外,肯定還有其它事務也未執行。
那麼,我就隨機選擇幾個relay-log日誌,找到第一個事務。
具體分析如下:
再登入從庫查詢結果:
可以看出從庫資料並未更新。
隨後,隨機分析了幾個relay日誌,發現第一個事務都未被執行。而且操作的表都是有不同的,操作也是有不同,有insert、update等等。頓時感覺,事情大條了。如果每個日誌的第一個事務都未執行,那麼從庫要缺少多少條資料?不敢想象,現在業務還在上升期,不久業務量會是現在的幾倍,甚至更多,到那時就不是使用者投訴那麼簡單了。
又抓取了部分relay日誌情況,第一個事務也都未被執行。我可以肯定了,是所有relay日誌的第一個事務都未被執行。
這個問題也可以是由於分割relay日誌的指令碼造成的。一般強制重新整理日誌是用flush命令來操作的,flush命令一般不會造成資料丟失,當然像他們這樣頻繁的操作,我是不知道會不會造成Bug,導致丟資料。還有在flush relay logs的時候有沒有用到其他的什麼操作呢?
我決定抓一把資料庫中操作過的命令。
抓取命令,問題解決
想到就做,登上從庫主機、登入資料庫,開啟general_log日誌。
坐等5分鐘,開啟日誌,尋找每分鐘前幾秒的記錄。
哇!
哇!
哇!
你們猜我看到了什麼? 我從未見過如此騷的操作!
上圖,以表我的震驚。
為什麼要跳過事務?你用stop slave與Start slave來重新整理relay日誌,已經重新整理了我的三觀,那,有必要跳過事務?這就解釋得通了,為何relay日誌第一個事務全都丟失。
至此!問題已經清晰,是由於開發設定的分割relay日誌的指令碼,使用了非常規命令及sql_slave_skip_counter跳過事務命令來分隔relay-log日誌,導致事務大量丟失。
所以,創新是好事,但要打好基本功,別搞些騷操作。
文章來自微信公眾號:DBAplus社群