myrocks複製中斷問題排查

背景mysql

      mysql能夠支持多種不一樣的存儲引擎,innodb因爲其高效的讀寫性能,而且支持事務特性,使得它成爲mysql存儲引擎的代名詞,使用很是普遍。隨着SSD逐漸普及,硬件存儲成本愈來愈高,面向寫優化的rocksdb引擎逐漸流行起來,咱們也是看中了rocksdb引擎在寫放大和空間放大的優點,將其引入到mysql體系。兩種引擎的結構B-Tree(innodb引擎)和LSM-Tree(rocksdb引擎)很好地造成互補,咱們能夠根據業務類型來選擇合適的存儲。通常mysql默認是mysql+innodb引擎,而mysql+rocksdb引擎稱之爲myrocks。今天要討論的就是myrocks複製中斷問題,案例來源於真實的業務場景。git

問題現象github

 

複製過程當中,出現了1756錯誤,根據錯誤日誌和debug確認是slave-sql線程在更新slave_worker_info表時出錯致使,堆棧以下:sql

#7  0x0000000000a30104 in Rpl_info_table::do_flush_info (this=0x2b9999c9de00, force=<optimized out>) at /home/admin/95_20161208115448428_15352432_code/rpm_workspace/sql/rpl_info_table.cc:171
#8  0x0000000000a299b1 in flush_info (force=true, this=<optimized out>) at /home/admin/95_20161208115448428_15352432_code/rpm_workspace/sql/rpl_info_handler.h:92
#9  Slave_worker::flush_info (this=0x2b9999f80000, force=<optimized out>) at /home/admin/95_20161208115448428_15352432_code/rpm_workspace/sql/rpl_rli_pdb.cc:318
#10 0x0000000000a29d95 in Slave_worker::commit_positions (this=this@entry=0x2b9999f80000, ev=ev@entry=0x2b9999c9ab00, ptr_g=ptr_g@entry=0x2b9999daca00, force=<optimized out>)
    at /home/admin/95_20161208115448428_15352432_code/rpm_workspace/sql/rpl_rli_pdb.cc:582
#11 0x00000000009d61f0 in Xid_log_event::do_apply_event_worker (this=0x2b9999c9ab00, w=0x2b9999f80000) at /home/admin/95_20161208115448428_15352432_code/rpm_workspace/sql/log_event.cc:74

這裏簡單介紹下複製相關的位點表,在並行複製模式下,參與複製的主要有三個角色,slave_io線程負責將主庫的binlog拉取到本地;slave_sql線程讀取binlog並根據必定的規則分發給各個slave_worker;slave_worker線程回放主庫的操做,達到與主庫同步的目的。slave_io線程和slave_sql線程分別只有一個,而worker線程能夠有1個或多個,能夠依據參數slave_parallel_workers設置。若是將slave_parallel_workers設置爲0,則表示關閉並行複製,slave_sql線程承擔回放的工做。位點表主要有3張,包括slave_worker_info,slave_relay_log_info和slave_master_info表。slave_io線程更新slave_master_info表,更新拉取的最新位置;slave_sql線程更新slave_relay_log_info表,更新同步位點;而slave_worker線程更新slave_worker_info,每一個worker線程在該表中都對應一條記錄,每一個worker各自更新本身的位點。數組

Slave_worker的工做流程以下:bash

1) 讀取event,調用do_apply_event進行回放;
2) 遇到xid event(commit/rollback event),表示事務結束,調用commit_positions更新位點信息;
3) 調用do_commit提交事務。併發

從咱們抓的堆棧來看,是worker線程在執行執行第2步出錯,如今咱們獲得了初步的信息,更新位點表失敗直接致使了錯誤。app

問題定位與分析函數

接下來,咱們要看看最終是什麼致使了更新位點表失敗?根據最後的錯誤碼,咱們調試時設置了若干斷點,最終獲得了以下堆棧性能

#0  myrocks::Rdb_transaction::set_status_error (this=0x2b99b6c5b400, thd=0x2b99b6c51000, s=..., kd=std::shared_ptr (count 18, weak 0) 0x2b997fbd7910,
    tbl_def=0x2b9981bc95b0) at /home/admin/95_20161208115448428_15352432_code/rpm_workspace/storage/rocksdb/ha_rocksdb.cc:1460
#1  0x0000000000a6da28 in myrocks::ha_rocksdb::check_and_lock_unique_pk (this=this@entry=0x2b997fbb3010, key_id=key_id@entry=0, row_info=...,
    found=found@entry=0x2b9a58ca77ef, pk_changed=pk_changed@entry=0x2b9a58ca782f)
    at /home/admin/95_20161208115448428_15352432_code/rpm_workspace/storage/rocksdb/ha_rocksdb.cc:7092
#2  0x0000000000a6e8a8 in myrocks::ha_rocksdb::check_uniqueness_and_lock (this=this@entry=0x2b997fbb3010, row_info=..., pk_changed=pk_changed@entry=0x2b9a58ca782f)
    at /home/admin/95_20161208115448428_15352432_code/rpm_workspace/storage/rocksdb/ha_rocksdb.cc:7250
#3  0x0000000000a7386a in myrocks::ha_rocksdb::update_write_row (this=this@entry=0x2b997fbb3010, old_data=old_data@entry=0x0

經過代碼分析獲得了以下信息:

更新位點表之因此失敗是由於更新記錄時發現已經存在了一條記錄,這條記錄的sequnceNumber比當前快照獲取的sequnceNumber大,因此報錯。這裏簡單介紹下sequenceNumber,sequenceNumber是全局遞增的,內部存儲爲一個7字節的整數,Rocksdb依賴sequenceNumber實現MVCC。每條記錄有一個惟一的sequenceNumber,rocksdb利用sequenceNumber進行可見性判斷。事務在提交時,獲取當前最大的sequenceNumber,並按照前後順序爲事務中的每條記錄分配一個sequenceNumber,而後寫入memtable。同一個key的多個不一樣的sequenceNumber記錄按照逆序存放,即sequenceNumber最大的key放在最前面,最小的放在最後面。表1中key-n,key表示key值,n表示key對應sequenceNumber,假設key1<key2<key3<key4,則存儲順序以下:

Key1-100

Key1-50

Key2-120

Key2-80

Key3-70

Key4-150

ValueA

ValueB

ValueC

ValueD

ValueE

ValueF

進行讀取時,會利用sequenceNumber創建一個快照,讀取快照發生前的已經存在的記錄,系統以後的變動與本快照無關。假設快照的sequenceNumber是150,執行get(key2)時,會找到(key2-120,ValueC);而若是快照sequenceNumber是100,執行get(key2)時,則會找到(key2-80,ValueD)。

回到問題自己,看看與問題相關的更新流程:

1.嘗試對更新key加鎖,若是沒有併發更新,上鎖成功 //TryLock
2.利用當前最大的sequenceNumberA生成快照
3.檢查快照生成後,key是否被修改 // ValidateSnapshot
  1)再次獲取最大sequenceNumberB,構造key進行查找 // GetLatestSequenceForKey
  2)查找是否存在相同的key的記錄
4.若相同key的記錄存在,且key的sequnceNumber大於sequenceNumberA,則認爲有寫衝突,報錯。

咱們碰到的錯誤正好就是遇到了寫衝突報錯,那麼如今問題來了,明明這個key已經上鎖了,而且獲取了最新的sequencNumberA,爲何仍然會讀到相同的key,且對應的seqeunceNumber比sequencNumberA大?結合以前分析的slave_worker_info表,咱們能夠做出如下猜想

大膽猜想:

  1. 行級鎖併發沒有控制好,致使多個線程同時更新
  2. 某些路徑下,快照的sequenceNumber比較舊,不是最新
  3. slave_worker線程併發沒有控制好,多個worker同時更新一條記錄

當心求證:

現象看起來是這麼的不合理,全部的假設感受都是不攻自破,可是事實如此,惟有經過更多的信息來輔佐咱們進一步判斷。結合代碼,咱們對於上面懷疑的幾個點,在相關路徑下進行埋點驗證。埋點主要爲了獲得如下信息:

  1. 具體哪一個worker出錯了,出錯的是哪一個key,sequence是多少?
  2. worker與key的映射關係
  3. 這個key在出錯前被誰更新過?
  4. 每一個事務包含的記錄個數是多少?

得到日誌以下:

Resource busy: seq:38818368818, key_seq:38818368817, index number is 0-0-1-2, pk is 0-0-0-10, thread is 46983376549632

映射關係:
worker id is 10, thread is 46983367104256  //寫memtable線程
worker id is 9, thread is 46983376549632   //出錯線程
worker id is 11, thread is 46983359772416  //事務提交線程

寫memtable線程:
2016-12-19 16:42:06 53743 [ERROR] LibRocksDB:In Memtable, index_num is 0-0-1-2, pk is 0-0-0-10, seq is 38818368818, thread is 46983367104256

2016-12-19 16:42:06 53743 [ERROR] LibRocksDB:In Memtable, index_num is 0-0-1-2, pk is 0-0-0-4, seq is 38818368665, thread is 46983367104256

2016-12-19 16:42:06 53743 [ERROR] LibRocksDB:In Memtable, index_num is 0-0-1-2, pk is 0-0-0-3, seq is 38818368675, thread is 46983367104256

提交線程:
type is commit, write_start, thread is 46983359772416,   seq is 38818368817
type is commit, write_end, thread is 46983359772416,   seq is 38818368818, count is 1

報錯的直接緣由就是 已存在相同key的sequenceNumber 38818368818大於快照的squenceNumber 38818368817。這個衝突的key由worker 10寫入memtable,可是由worker 11提交,並非出錯的線程。總結下來, 咱們發現幾個奇怪的現象:

    1. 存在多個線程寫一個key的狀況,好比worker10曾經寫過key爲10,4,和3的記錄
    2. 對於出錯的sequenceNumber(38818368818)的key,爲何會被worker11提交
    3. 日誌中發現SequenceNumber不連續,存在跳躍的現象

前兩個問題很容易讓咱們陷入誤區,存在多個worker寫同一個key的狀況,而事實上這兩個問題都是源於group-commit機制,其它線程可能會代替你提交,致使你會看到同一個worker寫不一樣key的現象。這裏的group-commit包括兩個層次,server層group-commit和rocksdb引擎的group-commit。

  

從圖中能夠看出,在server層group-commit機制下,流入到rocksdb引擎層commit接口的都是串行的,既然是串行的,爲何sequenceNumber會存在跳躍呢?這時候我想到了binlog_order_commits參數,以前爲了提升性能,關閉了該參數,也就是在提交的最後一階段,多個事務併發在引擎層提交,會不會與併發寫memtable有關,由於在以前復現的過程當中,咱們發現關閉併發寫memtable特性(rocksdb_allow_concurrent_memtable_write=0),問題不會復現。

但使人失望的是,在併發寫memtable狀況下,即便打開了binlog_ordered_commit(server層串行commit),事務串行在引擎層提交仍然會出現一樣的問題。

       到這裏彷佛陷入了死衚衕,引擎層永遠只有一個事務進來,爲啥開啓併發寫memtable會影響正確性呢?由於一個事務無法併發。不知何時靈光一現,prepare階段和commit階段併發。由於rocksdb最終提交接口WriteImpl是prepare和commit公用的,經過傳入的參數來區別。prepare階段寫wal日誌,commit階段寫memtable和commit日誌。那咱們就重點來看prepare和commit併發進入WriteImpl時SequenceNumber相關的代碼,果真發現了問題。這裏我簡單介紹下開啓併發寫memtable選項時,事務的提交邏輯。

   1.每一個事務都對應一個write-batch
   2.第一個進入WriteImpl函數的線程爲leader,其它線程爲follower
   3.leader和follower根據前後順序串成一個鏈表
   4.對於併發寫memtable的狀況,leader根據每一個事務write-batch的count,計算每一個事務的start-sequenceNumber。
   5.leader寫完wal日誌後,follower根據各自start-sequenceNumber,併發寫memtable
   6.全部事務都寫完memtable後,leader更新全局的sequenceNumber。 

問題主要發生在第4個步驟,計算start-sequenceNumber時,忽略了prepare事務的判斷,致使在prepare事務與commit事務成爲一個group時,commit事務的sequence出現跳躍,而全局的sequenceNumber只統計了commit事務,最終致使了寫入memtable的sequenceNumber比全局sequenceNumber大的現象,進而發生了後續的錯誤。下面列舉一個錯誤的例子,假設slave_worker1和slave_worker2分別執行完事務trx1和trx2操做,更新位點後開始事務提交,trx1處於prepare階段,trx2處於commit階段,trx1和trx2組成一個commit-group, trx1是leader,trx2是follower,current_sequence 是101。

trx1: prepare phase, batch count is 3
put(user_key1,v1);
put(user_key2,v2);
put(user_key3,v3);

trx2: commit phase, batch count is 2
put(user_keyA,v1);
put(user_keyB,v2);

trx1是leader,所以trx2的start sequence 是101+3=104,寫入memtable中的user_keyA的sequence是104,user_keyB的sequence是105。Current sequence推動到103。這個group結束後,對於新事務trx3, 若是Current sequnce爲已經推動到120(全局任何事務提交都會推動sequence),trx3更新user_keyA,就會發現已經存在(user_keyA, 104),也就是咱們遇到的錯誤;而另一種狀況,假設current Sequence沒有推動,仍然爲103,則會發生更新丟失,由於查不到(user_keyA,104)這條記錄。這正好解釋了,爲啥咱們在同步過程當中,會發生丟失更新的問題。

while (w != pg->last_writer) {
// Writers that won't write don't get sequence allotment
if (!w->CallbackFailed()) {
sequence += WriteBatchInternal::Count(w->batch); # // BUG HERE: not check w-> ShouldWriteToMemtable, sequence out of bound.
}

w = w->link_newer;
w->sequence = sequence;
w->parallel_group = pg;
SetState(w, STATE_PARALLEL_FOLLOWER);
}

小插曲

      到這裏,咱們已經回答了以前的全部疑問,問題也最終定位。但萬萬沒想到,修改代碼提交後,複製問題依舊存在,我感嘆是否是不僅一個bug。因而繼續查,看了下日誌,已經不是以前的slave_worker_info表出錯了,而是一張業務表。後來才發現是由於替換mysqld後隔離級別沒有設置,重啓實例後,隔離級別變爲Read-Repeatable級別致使。這裏簡單說下RR隔離下,並行複製下,致使上述錯誤的緣由。首先明確一點,RR隔離是在事務的第一個語句獲取快照,之後事務中全部語句都使用這個快照,而RC隔離級別則是事務的每一個語句會單獨獲取快照。在並行複製模式下,假設這樣一種狀況:

時間軸

Trx1

Trx2

1

Begin

Begin

2

Update t1 set v=? where k=1

 

3

 

Update t2 set v=? where k=1

4

 

commit

5

Update t2 set v=? where k=1

 

RR隔離級別下,trx1會在第一個update語句獲取快照,更新t2表時,仍然使用以前的快照,而在這期間,t2表的k=1對應的記錄可能被修改,致使記錄的sequenceNumber大於trx1快照的sequenceNumber,進而致使更新t2失敗。而若是是RC級別,trx1執行更新t2表時則會從新獲取快照,不會存在問題。

問題解決

      處理sequenceNumber邏輯不正確主要會致使兩個問題,備庫丟失更新和備庫複製中斷。定位到問題緣由,而且對全部疑問都有合理的解釋後,修改就比較簡單了,在計算start-sequenceNumber函數LaunchParallelFollowers中,添加prepare事務的判斷便可,隨後還須要編寫測試用例穩定復現,並進行迴歸測試纔算是最終修復這個補丁。咱們將問題反饋給官方https://github.com/facebook/mysql-5.6/issues/481,很快獲得了官方的確認和回覆。

總結

      整個排查過程仍是比較曲折,由於這個bug涉及到併發,而且是特定參數組合的併發纔會出問題,因此對於這種複雜的場景,經過合理假設與日誌埋點能逐步獲得一些結論和依據,最後抽絲剝繭獲取與問題相關的信息,才最終解決問題。咱們在測試驗證中過程當中不斷髮現不少看似與預期不符的日誌,也正是這些日誌讓咱們把整個流程弄透徹,離解決問題愈來愈近,總之不要放過任何一個疑點,由於要堅信日誌不會騙人,而代碼邏輯可能由於你忽略了某些分支,致使會有錯誤的推斷。

相關文章
相關標籤/搜索