myrocks複製中斷問題排查

来源:http://www.cnblogs.com/cchust/archive/2016/12/29/6231510.html
-Advertisement-
Play Games

背景 mysql可以支持多種不同的存儲引擎，innodb由於其高效的讀寫性能，並且支持事務特性，使得它成為mysql存儲引擎的代名詞，使用非常廣泛。隨著SSD逐漸普及，硬體存儲成本越來越高，面向寫優化的rocksdb引擎逐漸流行起來，我們也是看中了rocksdb引擎在寫放大和空間放大的優勢，將其引入 ...


背景

      mysql可以支持多種不同的存儲引擎，innodb由於其高效的讀寫性能，並且支持事務特性，使得它成為mysql存儲引擎的代名詞，使用非常廣泛。隨著SSD逐漸普及，硬體存儲成本越來越高，面向寫優化的rocksdb引擎逐漸流行起來，我們也是看中了rocksdb引擎在寫放大和空間放大的優勢，將其引入到mysql體系。兩種引擎的結構B-Tree(innodb引擎)和LSM-Tree(rocksdb引擎)很好地形成互補，我們可以根據業務類型來選擇合適的存儲。一般mysql預設是mysql+innodb引擎，而mysql+rocksdb引擎稱之為myrocks。今天要討論的就是myrocks複製中斷問題，案例來源於真實的業務場景。

問題現象

 

複製過程中，出現了1756錯誤，根據錯誤日誌和debug確認是slave-sql線程在更新slave_worker_info表時出錯導致，堆棧如下：

#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的工作流程如下：

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

從我們抓的堆棧來看，是worker線程在執行執行第2步出錯，現在我們得到了初步的信息，更新位點表失敗直接導致了錯誤。

問題定位與分析

接下來，我們要看看最終是什麼導致了更新位點表失敗？根據最後的錯誤碼，我們調試時設置了若幹斷點，最終得到瞭如下堆棧

#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涉及到併發，並且是特定參數組合的併發才會出問題，所以對於這種複雜的場景，通過合理假設與日誌埋點能逐步得到一些結論和依據，最後抽絲剝繭獲取與問題相關的信息，才最終解決問題。我們在測試驗證中過程中不斷發現很多看似與預期不符的日誌，也正是這些日誌讓我們把整個流程弄透徹，離解決問題越來越近，總之不要放過任何一個疑點，因為要堅信日誌不會騙人，而代碼邏輯可能因為你忽略了某些分支，導致會有錯誤的推斷。

 


您的分享是我們最大的動力!

-Advertisement-
Play Games
更多相關文章
  • MySQL：Fabric 安裝
    MySQL Fabric安裝 MySQL Fabric是Oracle提供的用於輔助進行ha\sharding的工具，它的基本架構： 從上面看出，藉助於Fabric， 可以搭建 HA 集群、Sharing 、HA+Sharding。 應用從fabric中得知各個資料庫、表、分區等的映射關係，然後訪問相 ...
  • Oracle 列數據聚合方法彙總
    網上流傳眾多列數據聚合方法，現將各方法整理彙總，以做備忘。 wm_concat 該方法來自wmsys下的wm_concat函數，屬於Oracle內部函數，返回值類型varchar2，最大字元數4000。隨著版本的變更返回值類型可能會有改動，項目中使用時候最好在新的用戶下創建一個函數。 使用方法： s ...
  • SQL數據類型
    1.Character 字元串： 2.Unicode字元串： 3.Binary類型： 4.Number類型： 固定精度和比例的數字。允許從 -10^38 +1 到 10^38 -1 之間的數字。 p 參數指示可以存儲的最大位數（小數點左側和右側）。p 必須是 1 到 38 之間的值。預設是 18。 ...
  • 一款實用免費的日誌自動化分析工具
    PAL是什麼? PAL（Performance Analysis of Logs）是一個實用、免費的日誌分析自動化工具，協助快速診斷伺服器級別的性能問題。 PAL有什麼特性？ PAL主要用來自動分析PerfMon（性能監視器）產生的日誌信息，一步一步嚮導式的簡單操作方式。 PAL基於微軟支持團隊的主 ...
  • SSIS 包部署 Package Store 後，在 IS 中可以執行，AGENT 執行卻報錯
    可以執行 SSIS Package ，證明用 SSIS Package 的賬戶是可以執行成功的。SQL Server Agent 預設指定賬號是 Network Service。 那麼可以嘗試一下將 SQL Server Agent 和 SQL Server Integration Service ...
  • Oracle Standard Error 列表
    1 ORA-00001: 違反唯一約束條件 (.) 2 ORA-00017: 請求會話以設置跟蹤事件 3 ORA-00018: 超出最大會話數 4 ORA-00019: 超出最大會話許可數 5 ORA-00020: 超出最大進程數 () 6 ORA-00021: 會話附屬於其它某些進程；無法轉換會話 ...
  • ORACLE從共用池刪除指定SQL的執行計劃
    Oracle 11g在DBMS_SHARED_POOL包中引入了一個名為PURGE的新存儲過程，用於從對象庫緩存中刷新特定對象，例如游標，包，序列，觸發器等。也就是說可以刪除、清理特定SQL的執行計劃，這樣在特殊情況下，就避免你要將整個SHARED POOL清空的危險情況。例如某個SQL語句由於優化... ...
  • Kafka：主要參數詳解（轉）
    原文地址：http://kafka.apache.org/documentation.html ############################# System ############################# #唯一標識在集群中的ID，要求是正數。 broker.id=0 #服務... ...
一周排行
    -Advertisement-
    Play Games
  • 移動開發（一）：使用.NET MAUI開發第一個安卓APP
    移動開發（一）：使用.NET MAUI開發第一個安卓APP 對於工作多年的C#程式員來說，近來想嘗試開發一款安卓APP，考慮了很久最終選擇使用.NET MAUI這個微軟官方的框架來嘗試體驗開發安卓APP，畢竟是使用Visual Studio開發工具，使用起來也比較的順手，結合微軟官方的教程進行了安卓 ...
  • wpf ToggleButton選中效果和一個登錄界面
    前言 QuestPDF 是一個開源 .NET 庫，用於生成 PDF 文檔。使用了C# Fluent API方式可簡化開發、減少錯誤並提高工作效率。利用它可以輕鬆生成 PDF 報告、發票、導出文件等。 項目介紹 QuestPDF 是一個革命性的開源 .NET 庫，它徹底改變了我們生成 PDF 文檔的方 ...
  • 彈幕樹洞項目功能新增篇
    項目地址 項目後端地址： https://github.com/ZyPLJ/ZYTteeHole 項目前端頁面地址： ZyPLJ/TreeHoleVue (github.com) https://github.com/ZyPLJ/TreeHoleVue 目前項目測試訪問地址： http://tree ...
  • 第27篇 sqlserver2022詳細安裝步驟
    話不多說，直接開乾 一.下載 1.官方鏈接下載： https://www.microsoft.com/zh-cn/sql-server/sql-server-downloads 2.在下載目錄中找到下麵這個小的安裝包 SQL2022-SSEI-Dev.exe，運行開始下載SQL server； 二. ...
  • .NET 開源高性能 MQTT 類庫
    前言 隨著物聯網（IoT）技術的迅猛發展，MQTT（消息隊列遙測傳輸）協議憑藉其輕量級和高效性，已成為眾多物聯網應用的首選通信標準。 MQTTnet 作為一個高性能的 .NET 開源庫，為 .NET 平臺上的 MQTT 客戶端與伺服器開發提供了強大的支持。 本文將全面介紹 MQTTnet 的核心功能 ...
  • Serilog文檔翻譯系列（六） - 可用的接收器、增強器、格式化輸出
    Serilog支持多種接收器用於日誌存儲，增強器用於添加屬性，LogContext管理動態屬性，支持多種輸出格式包括純文本、JSON及ExpressionTemplate。還提供了自定義格式化選項，適用於不同需求。 ...
  • 警惕 Visual Studio 屬性求值副作用導致邏輯不符合預期
    目錄簡介獲取 HTML 文檔解析 HTML 文檔測試參考文章 簡介 動態內容網站使用 JavaScript 腳本動態檢索和渲染數據，爬取信息時需要模擬瀏覽器行為，否則獲取到的源碼基本是空的。 本文使用的爬取步驟如下： 使用 Selenium 獲取渲染後的 HTML 文檔 使用 HtmlAgility ...
  • [使用目前最新版]HybridCLR6.9.0+YooAsset2.2.4實現純C# Unity熱更新方案 (一)
    1.前言 什麼是熱更新 游戲或者軟體更新時，無需重新下載客戶端進行安裝，而是在應用程式啟動的情況下，在內部進行資源或者代碼更新 Unity目前常用熱更新解決方案 HybridCLR，Xlua，ILRuntime等 Unity目前常用資源管理解決方案 AssetBundles，Addressable， ...
  • 在 ASP.NET Core Web API 中使用操作篩選器統一處理通用操作
    本文章主要是在C# ASP.NET Core Web API框架實現向手機發送驗證碼簡訊功能。這裡我選擇是一個互億無線簡訊驗證碼平臺，其實像阿裡雲，騰訊雲上面也可以。 首先我們先去 互億無線 https://www.ihuyi.com/api/sms.html 去註冊一個賬號 註冊完成賬號後，它會送 ...
  • 第28篇 如何.net中實現高效可靠數據同步api
    通過以下方式可以高效，並保證數據同步的可靠性 1.API設計 使用RESTful設計，確保API端點明確，並使用適當的HTTP方法（如POST用於創建，PUT用於更新）。 設計清晰的請求和響應模型，以確保客戶端能夠理解預期格式。 2.數據驗證 在伺服器端進行嚴格的數據驗證，確保接收到的數據符合預期格 ...
所有分類