行業案例| 千億級高併發MongoDB叢集在某頭部金融機構中的應用及效能優化實踐(上)

MongoDB中文社群 發表於 2022-06-21
MongoDB

某頭部金融機構採用MongoDB儲存重要的金融資料,資料量較大,資料規模約2000億左右,讀寫流量較高,峰值突破百萬級/每秒。本文分享該千億級高併發MongoDB叢集的踩坑經驗及效能優化實踐,通過本文可以瞭解如下資訊:


  • 如何對海量MongoDB叢集進行效能瓶頸定位?

  • 千億規模叢集常用踩坑點有哪些?

  • 如何對高併發大資料量MongoDB叢集進行效能優化?

  • 叢集監控資訊缺失,如何分析叢集抖動問題?

  • 如何像原廠工程師一樣藉助 diagnose.data(not human-readable)分析核心問題?


業務背景及MongoDB FTDC診斷介紹



業務背景


該MongoDB叢集 採用多分片架構部署,業務不定期長時間高併發讀寫,該叢集業務背景總結如下:

  • 資料量大,該叢集總資料量突破千億規模
  • 叢集最大表總chunks數約500萬
  • 長時間高併發讀寫
  • 一致性要求較高,讀寫全走主節點
  • 高峰期持續性讀寫qps百萬/秒
  • 單分片峰值流量接近20萬/秒
  • 核心版本:3.6.3版本
  • 非雲上叢集
  • 除了節點日誌,詳細監控資料因歷史原因缺失,無MongoDB常用監控指標資訊


隨著時間推移,叢集資料規模超過千億,叢集遇到了一些疑難問題,如主從切換、節點異常掛掉、節點數秒卡頓、切主後新主數十分鐘不可用等問題,下面章節將逐步分享這些問題,並給出對應的優化方法。

鑑於篇幅,本文無法分享完該案例遇到的所有問題及其優化方法,因此《千億級高併發MongoDB叢集在某頭部金融機構中的應用及效能優化實踐(下)》中將繼續分享本案例遺留的效能優化方法,同時分享分散式資料庫核心路由模組原理,並給出騰訊雲資料庫在最新MongoDB版本中對路由重新整理模組所做的優化。


MongoDB FTDC診斷資料簡介


2.1 Full Time Diagnostic Data Capture

To facilitate analysis of the MongoDB server behavior by MongoDB Inc. engineers, mongod and mongos processes include a Full Time Diagnostic Data Collection (FTDC) mechanism. FTDC data files are compressed, are not human-readable, and inherit the same file access permissions as the MongoDB data files. Only users with access to FTDC data files can transmit the FTDC data. MongoDB Inc. engineers cannot access FTDC data independent of system owners or operators. MongoDB processes run with FTDC on by default. For more information on MongoDB Support options, visit Getting Started With MongoDB Support.


詳見MongoDb官方FTDC實時診斷說明,地址:


從上面可以看出,diagnose.data是為了官方工程師分析各種問題引入的功能。FTDC資料檔案是bson+壓縮+私有協議,不是直觀可讀的,繼承了MongoDB資料檔案相同的檔案訪問許可權,預設情況下所有mongo節點開啟ftdc功能。

2.2 diagnose.data目錄結構


如下所示:

    [email protected]:/data1/xxxx/xxxx/db# ls  TencetDTSData  WiredTiger.lock  WiredTiger.wt  _mdb_catalog.wt  area  diagnostic.data  local  mongod.lock  mongoshake  storage.bson  WiredTiger   WiredTiger.turtle  WiredTigerLAS.wt  admin  config  journal   maicai  mongod.pid  sizeStorer.wt  test  [email protected]:/data1/xxxx/xxxx/db#   [email protected]:/data1/xxxx/xxxx/db#   [email protected]:/data1/xxxx/xxxx/db#   [email protected]:/data1/xxxx/xxxx/db#

    diagnostic.data 目錄中按照時間記錄各種不同診斷資訊到metrics檔案,除了metrics.interim檔案,其他檔案內容大約10M左右。


      [email protected]:/data1/xxxx/xxx/db/diagnostic.data#   [email protected]:/data1/xxxx/xxxx/db/diagnostic.data# ls  metrics.xxxx-12-27T02-28-58Z-00000  metrics.xxxx-12-28T14-33-57Z-00000  metrics.xxxx-12-30T04-28-57Z-00000  metrics.xxxx-12-31T17-08-57Z-00000  metrics.xxxx-01-02T05-28-57Z-00000  metrics.xxxx-12-27T09-18-58Z-00000  metrics.xxxx-12-28T23-13-57Z-00000  metrics.xxxx-12-30T11-23-57Z-00000  metrics.xxxx-01-01T00-53-57Z-00000  metrics.interim  metrics.xxxx-12-27T16-28-57Z-00000  metrics.xxxx-12-29T06-08-57Z-00000  metrics.xxxx-12-30T19-18-57Z-00000  metrics.xxxx-01-01T07-23-57Z-00000  metrics.xxxx-12-28T00-48-57Z-00000  metrics.xxxx-12-29T12-58-57Z-00000  metrics.xxxx-12-31T02-58-57Z-00000  metrics.xxxx-01-01T14-18-57Z-00000  metrics.xxxx-12-28T07-38-57Z-00000  metrics.xxxx-12-29T21-18-57Z-00000  metrics.xxxx-12-31T09-48-57Z-00000  metrics.xxxx-01-01T22-38-57Z-00000  [email protected]:/data1/xxx/xxxx/db/diagnostic.data#   [email protected]:/data1/xxxx/xxxx/db/diagnostic.data#

      叢集踩坑過程及優化方法



      memlock不足引起的節點崩掉及解決辦法


      叢集在執行過程中,出現“Failed to mlock: Cannot allocate memory”,mongod程式崩掉,該問題和jira中的一下bug一模一樣:

      1. SERVER-29086
      連結如下:

      2. SERVER-28997
      連結如下:

      觸發該問題的日誌資訊如下:
        Xxxx 12 22:51:28.891 F -        [conn7625] Failed to mlock: Cannot allocate memory  Xxxx 12 22:51:28.891 F -        [conn7625] Fatal Assertion 28832 at src/mongo/base/secure_allocator.cpp 246  Xxxx 12 22:51:28.891 F -        [conn7625]  ***aborting after fassert() failure  Xxxx 12 22:51:28.918 F -        [conn7625] Got signal: 6 (Aborted).  ..........  ----- BEGIN BACKTRACE -----  {"backtrace":   libc.so.6(abort+0x148) [0x7fccf1b898c8]   mongod(_ZN5mongo32fassertFailedNoTraceWithLocationEiPKcj+0x0) [0x7fccf3b33ed2]   mongod(_ZN5mongo24secure_allocator_details8allocateEmm+0x59D) [0x7fccf51d6d6d]   mongod(_ZN5mongo31SaslSCRAMServerConversationImplINS_8SHABlockINS_15SHA1BlockTraitsEEEE26initAndValidateCredentialsEv+0x167) [0x7fccf4148ca7]   mongod(_ZN5mongo27SaslSCRAMServerConversation10_firstStepENS_10StringDataEPNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEE+0x959) [0x7fccf414dcd9]   mongod(_ZN5mongo27SaslSCRAMServerConversation4stepENS_10StringDataEPNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEE+0x9B) [0x7fccf414eecb]   mongod(_ZN5mongo31NativeSaslAuthenticationSession4stepENS_10StringDataEPNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEE+0x3C) [0x7fccf414731c]   mongod(+0xF355CD) [0x7fccf41405cd]   mongod(+0xF37D3A) [0x7fccf4142d3a]   mongod(_ZN5mongo12BasicCommand11enhancedRunEPNS_16OperationContextERKNS_12OpMsgRequestERNS_14BSONObjBuilderE+0x76) [0x7fccf4cefde6]

        官方 jira系統說明該bug已經在3.6版本中修復,但是又有新使用者在報告在3.6版本中遇到了同樣的問題,並且按照官方建議做了memlock unlimited配置。

        走讀 對應版本MongoDB核心程式碼,可以看出核心認證流程和建賬號流程會使用SecureAllocator記憶體分配器進行記憶體分配,預設情況通過mmap+mlock方式進行memlock分配,但是這裡核心原始碼實際上加了一個開關,使用者可以自己決定是否使用memlock。核心程式碼如下:
          
          //disabledSecureAllocatorDomains配置初始化配置  
          
          ExportedServerParameter<std::vector<std::string>, ServerParameterType::kStartupOnly>  
          
              SecureAllocatorDomains(ServerParameterSet::getGlobal(),  
          
          "disabledSecureAllocatorDomains",  
          
                                     &serverGlobalParams.disabledSecureAllocatorDomains);  
          
          
          
          template <typename NameTrait>   struct TraitNamedDomain { //該介面在SecureAllocatorDomain類中的相關介面中生效,決定走mlock流程還是普通malloc流程   static bool peg() {   const auto& dsmd = serverGlobalParams.disabledSecureAllocatorDomains;   const auto contains = [&](StringData dt) {   return std::find(dsmd.begin(), dsmd.end(), dt) != dsmd.end();          };  
          //注意這裡,如果disabledSecureAllocatorDomains配置為*,直接false   static const bool ret = !(contains("*"_sd) || contains(NameTrait::DomainType));   return ret;      }   };  
          void deallocate(pointer ptr, size_type n) {   return secure_allocator_details::deallocateWrapper(   //peg()決定是走mlock流程還是普通malloc流程   static_cast<void*>(ptr), sizeof(value_type) * n, DomainTraits::peg());   }  
          inline void* allocateWrapper(std::size_t bytes, std::size_t alignOf, bool secure) {   if (secure) {   //最終走mlock流程   return allocate(bytes, alignOf);      } else {   //走std::malloc普通記憶體分配流程   return mongoMalloc(bytes);      }   }

          上面的核心核心程式碼可以看出,認證流程、賬號建立流程的security記憶體分配有兩種方式,如下

          • Memlock記憶體方式

          預設方式,認證過程的scram::generateSecrets流程預設使用memlock。

          • 普通malloc記憶體方式

          需要新增disabledSecureAllocatorDomains: "*"配置,禁用mlock,使用普通記憶體。
           
          di sabledSecureAllocatorDomains在官方文件沒用說明,經過實際測試驗證,禁用memlock對連結認證影響不大,同時因為使用者是長連線請求,因此影響基本上忽略。

          M lock不足引起的節點崩掉問題可以通過在配置檔案增加如下配置解決:
            setParameter:    disabledSecureAllocatorDomains: '*'


            壓力過大引起的主從切換及優化方法


            問題: 主節點壓力大,叢集出現主從切換現象,切換期間業務訪問異常。

            4.1 日誌分析過程

            主從 切換過程中,由於讀寫流量都走主節點,因此切換過程會有大量報錯,收集對應日誌,核心日誌如下:
              Xxxx 11 12:02:19.125 I ASIO     [NetworkInterfaceASIO-RS-0] Ending connection to host x.x.x.x:11200 due to bad connection status; 2 connections to that host remain open  Xxxx 11 12:02:19.125 I REPL     [replication-18302] Restarting oplog query due to error: NetworkInterfaceExceededTimeLimit: error in fetcher batch callback :: caused by :: Operation timed out. Last fetched optime (with hash): { ts: Timestamp(1649926929, 5296), t: 31 }[-1846165485094137853]. Restarts remaining: 3  Xxxx 11 12:02:19.125 I REPL     [replication-18302] Scheduled new oplog query Fetcher source: x.x.x.x:11200 database: local query: { find: "oplog.rs", filter: { ts: { $gte: Timestamp(1649926929, 5296) } }, tailable: true, oplogReplay: true, awaitData: true, maxTimeMS: 60000, batchSize: 13981010, term: 31, readConcern: { afterClusterTime: Timestamp(1649926929, 5296) } } query metadata: { $replData: 1, $oplogQueryData: 1, $readPreference: { mode: "secondaryPreferred" } } active: 1 findNetworkTimeout: 65000ms getMoreNetworkTimeout: 10000ms shutting down?: 0 first: 1 firstCommandScheduler: RemoteCommandRetryScheduler request: RemoteCommand 3332431257 -- target:x.x.x.x:11200 db:local cmd:{ find: "oplog.rs", filter: { ts: { $gte: Timestamp(1649926929, 5296) } }, tailable: true, oplogReplay: true, awaitData: true, maxTimeMS: 60000, batchSize: 13981010, term: 31, readConcern: { afterClusterTime: Timestamp(1649926929, 5296) } } active: 1 callbackHandle.valid: 1 callbackHandle.cancelled: 0 attempt: 1 retryPolicy: RetryPolicyImpl maxAttempts: 1 maxTimeMillis: -1ms  Xxxx 11 12:02:20.211 I REPL     [replexec-4628] Starting an election, since we've seen no PRIMARY in the past 10000ms  Xxxx 11 12:02:20.211 I REPL     [replexec-4628] conducting a dry run election to see if we could be elected. current term: 31  Xxxx 11 12:02:20.215 I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to x.x.x.x:11200  Xxxx 11 12:02:20.393 I REPL     [replexec-4620] VoteRequester(term 31 dry run) received a yes vote from 10.22.13.85:11200; response message: { term: 31, voteGranted: true, reason: "", ok: 1.0, operationTime: Timestamp(1649926929, 5296), $gleStats: { lastOpTime: Timestamp(0, 0), electionId: ObjectId('7fffffff000000000000001b') }, $clusterTime: { clusterTime: Timestamp(1649926932, 3), signature: { hash: BinData(0, 0000000000000000000000000000000000000000), keyId: 0 } }, $configServerState: { opTime: { ts: Timestamp(1649926932, 3), t: 1 } } }  Xxxx 11 12:02:20.393 I REPL     [replexec-4620] dry election run succeeded, running for election in term 32  Xxxx 11 12:02:20.474 I REPL_HB  [replexec-4628] Error in heartbeat (requestId: 3332431247) to x.x.x.x:11200, response status: NetworkInterfaceExceededTimeLimit: Operation timed out  Xxxx 11 12:02:20.474 I REPL     [replexec-4628] Member x.x.x.x:11200 is now in state RS_DOWN  Xxxx 11 12:02:20.477 I REPL     [replexec-4628] VoteRequester(term 32) received a no vote from x.x.x.x:11200 with reason "candidate's data is staler than mine. candidate's last applied OpTime: { ts: Timestamp(1649926929, 5296), t: 31 }, my last applied OpTime: { ts: Timestamp(1649926940, 5), t: 31 }"; response message: { term: 31, voteGranted: false, reason: "candidate's data is staler than mine. candidate's last applied OpTime: { ts: Timestamp(1649926929, 5296), t: 31 }, my last applied OpTime: { ts: Times...", ok: 1.0, operationTime: Timestamp(1649926940, 5), $gleStats: { lastOpTime: Timestamp(0, 0), electionId: ObjectId('7fffffff000000000000001f') }, $clusterTime: { clusterTime: Timestamp(1649926940, 6), signature: { hash: BinData(0, 0000000000000000000000000000000000000000), keyId: 0 } }, $configServerState: { opTime: { ts: Timestamp(1649926937, 2), t: 1 } } }  Xxxx 11 12:02:20.629 I REPL     [replexec-4620] election succeeded, assuming primary role in term 32  Xxxx 11 12:02:20.630 I REPL     [replexec-4620] transition to PRIMARY from SECONDARY

              上面的核心日誌可以看出,該時間點從節點和主節點的保活超時了,該從節點從新發起了一次選舉,選舉大概1秒鐘左右完成,該從節點被提升為新的主節點。

              4.2 diagnose診斷分析確認根因

              上面日誌分析初步判斷主從切換由保活超時引起,問題根因定位就需要分析出引起保活超時的原因。由於該雲下叢集監控資訊缺失,因此收集使用者diagnose.data診斷資料進行分析,最終通過分析診斷資料確認根因。

              根據以往經驗,主從保活超時可能原因主要有以下幾種情況:

              • 網路抖動

              分析該叢集多個節點日誌,只有該從節點出現了保活超時現象,其他分片節點不存在該問題,並且該從節點一秒鐘內快速被選為新的主節點,因此可以排除網路抖動問題。

              • 主節點hang住

              對應時間點主節點有大量慢查,通過慢查可以看出該時間段慢查詢時間在幾十毫秒到數秒、數十秒波動,因此節點不是完全hang死的,可以排除節點長時間hang死的情況。

              • 主壓力過大

              如果主壓力過大,主節點的所有請求存在排隊現象,這時候就可能引起保活超時。同時,結合後面的診斷資料分析,最終確認該問題由主壓力過大引起。

              該叢集只有mongostat監控資訊,無其他監控資料,切換前一段時間該主節點對應mongostat監控資訊如下:

              undefined


              從上面的 列印結果可以看出,在切換前一段時間的流量較高,該分片主節點讀寫流量超過15W/s,used記憶體逐漸接近95%。但是很遺憾,接近切換前一分鐘內的mongostat監控沒有獲取到,對應報錯資訊如下:


              undefined


              從上面的mongostat監控看出,隨著userd使用越來越高,使用者執行緒開始阻塞並進行髒資料淘汰,讀寫效能也有所下降,qrw、arw活躍佇列和等待佇列也越來越高。通過這些現象可以基本確認請求排隊越來越嚴重,由於臨近主從切換時間點附近的mongostat資料沒有獲取到,因此解析diagnose.data診斷資料確定根因。


              主節點降級為從節點前30秒和後15秒的讀寫活躍佇列診斷資料如下(左圖為讀活躍佇列數,右圖為寫活躍佇列數):



              上圖為讀寫活躍請求數,也就是mongostat監控中的arw。同時分析diagnose.data中的讀寫等待佇列,其結果如下(左圖為讀等待佇列,右圖為寫等待佇列):



              上圖 讀寫請求佇列數,也就是mongostat中的qrw,分表代表佇列中排隊的讀請求數和寫請求數,切換前30秒左右讀寫佇列中排隊的請求數都很高,接近1000,排隊現象嚴重。

              由於從節點定期會和主節點進行保活探測,如果主節點10秒鐘沒應答,則從節點會主動發起選舉。從上面的分析可以確定根因,主壓力過大,排隊現象嚴重,因此最終造成從節點保活超時。

              說明:上面4個診斷圖中的value值為該時間點的診斷項取值,後面的inc-dec中的資料為每隔一秒鐘的增量資料,是相比上一秒的變化。

              4.3 優化方法

              • 業務梳理優化


              上一分析了該叢集主從切換原因主要由主節點壓力過大,達到了節點所能承載的最大負載引起。


              結合業務使用情況瞭解到該叢集由多個業務訪問,其中對叢集影響較大的主要是某個業務不定期長時間跑批處理任務進行大量資料讀寫。為了避免批量任務過程中對其他業務的影響,業務測進行如下改造:

              1. 適當降低批處理任務的併發數、拉長批處理任務的時長來緩解叢集整體壓力。
              2. 業務錯峰,批量任務啟動時間延後到凌晨。

              • 核心優化


              此外,在業務進行業務改造期間,為了避免主從切換後造成的叢集不可用問題,MongoDB核心也做了適當優化,主要通過適當調整主從保活超時時間來規避緩解問題:
                cfg = rs.conf()  cfg.settings.heartbeatTimeoutSecs=20  cfg.settings.electionTimeoutMillis=20000  rs.reconfig(cfg)

                總結:通過業務側 和核心優化最終規避了主從切換問題。


                節點十秒級hang住問題診斷及優化


                問題: 流量低峰期,叢集節點十秒級hang住,業務抖動。

                叢集執行過程中,還出現一些比較奇怪的問題,叢集有時候低峰期的時候出現hang住現象,這期間數秒甚至數十秒內所有請求超時,核心日誌如下:
                  Xxxx 11 10:08:22.107 I COMMAND  [conn15350423] command xx.xxx command:  find ........................... protocol:op_msg 92417ms  .............  Xxxx 11 10:08:22.108 I COMMAND  [conn15271960] serverStatus was very slow: { after basic: 0, after asserts: 0, after backgroundFlushing: 0, after connections: 0, after dur: 0, after extra_info: 0, after globalLock: 0, after locks: 0, after logicalSessionRecordCache: 0, after network: 0, after opLatencies: 0, after opcounters: 0, after opcountersRepl: 0, after repl: 0, after sharding: 0, after shardingStatistics: 0, after storageEngine: 0, after tcmalloc: 11515, after transactions: 11515, after wiredTiger: 11565, at end: 11565 }  .........  Xxxx 11 10:08:22.109 I COMMAND  [conn15350423] command xx.xxxx command:  find ........................... protocol:op_msg 112417ms  Xxxx 11 10:08:22.109 I COMMAND  [conn15350423] command xxx.xxx command:  find ........................... protocol:op_msg 116417ms


                  從上面 日誌可以看出,ftdc診斷模組已提示時延消耗主要集中在tcmalloc模組,也就是tcmalloc模組hang住引起了整個例項請求等待。於是解析對應時間點diagnose.data診斷資料,hang住異常時間點前後的tcmalloc診斷資料如下:


                  行業案例| 千億級高併發MongoDB叢集在某頭部金融機構中的應用及效能優化實踐(上)


                  上圖所示,異常時間點tcmalloc模組快取的記憶體十秒鐘內瞬間一次性釋放了接近40G記憶體,因此造成了整個節點hang住。


                  優化 方法:實時pageHeap釋放,避免一次性大量cache集中式釋放引起節點hang住,MongoDB實時加速釋放對應記憶體命令如下,可通過tcmallocReleaseRate控制釋放速度:

                    db.adminCommand( { setParameter: 1, tcmallocReleaseRate: 5.0 } )


                    命令可以加快釋放速度,部分MongoDB核心版本不支援,如果不支援也可以通過下面的命令來進行激進的記憶體釋放:

                      db.adminCommand({setParameter:1,tcmallocAggressiveMemoryDecommit:1})



                      切換成功後新主數十分鐘不可用問題及優化


                      該叢集除了遇到前面的幾個問題外,還遇到了一個更嚴重的問題,主從切換後數十分鐘不可用問題。下面我們開始結合日誌和診斷資料分析新主數十分鐘不可用問題根因:


                      6.1 問題現象


                      6.1.1 主從切換過程


                      主從切換日誌如下:

                        Xxx xxx  8 23:43:28.043 I REPL     [replication-4655] Restarting oplog query due to error: NetworkInterfaceExceededTimeLimit: error in fetcher batch callback :: caused by :: Operation timed out. Last fetched optime (with hash): { ts: Timestamp(1644334998, 110), t: 10 }[3906139038645227612]. Restarts remaining: 3  Xxx xxx  8 23:43:36.439 I REPL     [replexec-8667] Starting an election, since we've seen no PRIMARY in the past 10000ms  Xxx xxx  8 23:43:36.439 I REPL     [replexec-8667] conducting a dry run election to see if we could be elected. current term: 10  .....  Xxx xxx  8 23:43:44.260 I REPL     [replexec-8666] election succeeded, assuming primary role in term 11  .....  Xxx xxx  8 23:43:44.261 I REPL     [replexec-8666] transition to PRIMARY from SECONDARY  Xxx xxx  8 23:43:44.261 I REPL     [replexec-8666] Entering primary catch-up mode.


                        從上面的日誌可以,從節點發現主節點保活超時,大約15秒鐘內快速被提升為新的主節點,整個過程一切正常。


                        6.1.2 快速切主成功後,業務訪問半小時不可用


                        叢集由於流量過大,已提前關閉balance功能。但是,從節點切主後,業務訪問全部hang住,試著kill請求、手動HA、節點重啟等都無法解決問題。下面是一次完整主從切換後叢集不可用的日誌記錄及其分析過程,包括路由重新整理過程、訪問hang住記錄等。


                        MongoDB核心路由模組覆蓋分片叢集分散式功能的所有流程,功能極其複雜。鑑於篇幅,下面只分析其中核心流程。


                        切主後新主hang住半小時,切主hang住核心日誌如下:

                          Xxxx  9 00:16:22.728 I COMMAND  [conn359980] command db_xx.collection_xx command: find ....... ,shardVersion: [ Timestamp(42277, 3330213) ,ObjectId('61a355b18444860129c524ec') ] numYields:0 ok:0 errMsg:"shard version not ok: version epoch mismatch detected for DBXX.COLLECTIONXX, the collection may have been dropped and recreated" errName:StaleConfig errCode:13388 reslen:570 timeAcquiringMicros: { r: 1277246 }  protocol:op_msg 1941243ms  Xxxx  9 00:16:22.728 I COMMAND  [conn359980] command db_xx.collection_xx command: find ....... ,shardVersion: [ Timestamp(42277, 3330213) ,ObjectId('61a355b18444860129c524ec') ] numYields:0 ok:0 errMsg:"shard version not ok: version epoch mismatch detected for DBXX.COLLECTIONXX, the collection may have been dropped and recreated" errName:StaleConfig errCode:13388 reslen:570 timeAcquiringMicros: { r: 1277246 }  protocol:op_msg 1923443ms  Xxxx  9 00:16:22.728 I COMMAND  [conn359980] command db_xx.collection_xx command: find ....... ,shardVersion: [ Timestamp(42277, 3330213) ,ObjectId('61a355b18444860129c524ec') ]numYields:0 ok:0 errMsg:"shard version not ok: version epoch mismatch detected for DBXX.COLLECTIONXX, the collection may have been dropped and recreated" errName:StaleConfig errCode:13388 reslen:570 timeAcquiringMicros: { r: 1277246 }  protocol:op_msg 1831553ms  Xxxx  9 00:16:22.728 I COMMAND  [conn359980] command db_xx.collection_xx command: find ....... ,shardVersion: [ Timestamp(42277, 3330213) ,ObjectId('61a355b18444860129c524ec') ] numYields:0 ok:0 errMsg:"shard version not ok: version epoch mismatch detected for DBXX.COLLECTIONXX, the collection may have been dropped and recreated" errName:StaleConfig errCode:13388 reslen:570 timeAcquiringMicros: { r: 1277246 }  protocol:op_msg 1751243ms  Xxxx  9 00:16:22.728 I COMMAND  [conn359980] command db_xx.collection_xx command: find ....... ,shardVersion: [ Timestamp(42277, 3330213) ,ObjectId('61a355b18444860129c524ec') ]numYields:0 ok:0 errMsg:"shard version not ok: version epoch mismatch detected for DBXX.COLLECTIONXX, the collection may have been dropped and recreated" errName:StaleConfig errCode:13388 reslen:570 timeAcquiringMicros: { r: 1277246 }  protocol:op_msg 1954243ms


                          日誌中可以看出,所有使用者請求都hang住了。


                          從節點切主後路由重新整理過程核心日誌,切主後,新主刷路由核心流程如下:

                            Xxx xxx  8 23:43:53.306 I SHARDING [conn357594] Refreshing chunks for collection db_xx.collection_xx based on version 0|0||000000000000000000000000  Xxxx  9 00:15:47.486 I SHARDING [ConfigServerCatalogCacheLoader-0] Cache loader remotely refreshed for collection db_xx.collection_xx from collection version 42227|53397||ada355b18444860129css4ec  and found collection version 42277|53430||ada355b18444860129css4ec   Xxxx  9 00:16:06.352 I SHARDING [ConfigServerCatalogCacheLoader-0] Cache loader found enqueued metadata from 42227|53397||ada355b18444860129css4ec  to 42277|53430||ada355b18444860129css4ec  and persisted metadata from 185|504||ada355b18444860129css4ec  to 42277|53430||ada355b18444860129css4ec , GTE cache version 0|0||000000000000000000000000Xxxx  9 00:16:21.550 I SHARDING [ConfigServerCatalogCacheLoader-0] Refresh for collection db_xx.collection_xx took 1948243 ms and found version 42277|53430||ada355b18444860129css4ec


                            上面的刷路由過程主要時間段如下:


                            第一階段 從遠端config server獲取全量或者增量路由資訊 (持續32分鐘)

                            23:43:53 - 00:15:47 ,持續時間約 32 分鐘。


                            第二階段 把獲取到的增量chunks路由資訊持久化到本地 (持續時間約20秒 )

                            00:15:47 - 00:16:06,持續時間約20秒。


                            第三階段 載入本地cache.chunks表中的路由資訊到記憶體 (持續時間15秒)

                            00:16:06 - 00:16:21,持續時間15秒。


                            通過上面 的日誌分析,基本上可以確認問題是由於主從切換後路由重新整理引起,但是整個過程持續30分鐘左右,業務30分鐘左右不可用,這確實不可接受。


                            6.1.3 切主後路由重新整理核心原理


                            M ongoDB核心路由重新整理流程比較複雜,這裡只分析3.6.3版本切主後的路由重新整理主要流程:


                            1. mongos 攜帶本地最新的shard版本資訊轉發給shard server


                            例如 上面日誌中的mongos攜帶的路由版本資訊為:shardVersion: [ Timestamp(42277, 3330213) ,ObjectId('61a355b18444860129c524ec') ],shardVersion中的42277為該表路由大版本號,3330213為路由小版本號;ObjectId代表一個具體表,表不刪除不修改,該id一直不變。


                            2. 新主進行路由版本檢測


                            新主收到mongos轉發的請求後,從本地記憶體中獲取該表版本資訊,然後和mongos攜帶shardVersion版本號做比較,如果mongos轉發的主版本號比本地記憶體中的高,則說明本節點路由資訊不是最新的,因此就需要從config server獲取最新的路由版本資訊。


                            3. 進入路由重新整理流程


                            第一個請求到來後,進行路由版本檢測,發現本地版本低於接受到的版本,則進入重新整理路由流程。進入該流程前加鎖,後續路由重新整理交由ConfigServerCatalogCacheLoader執行緒池處理,第一個請求執行緒和後面的所有請求執行緒等待執行緒池非同步獲取路由資訊。


                            6.2 切主數十分鐘hang住問題優化方法


                            構造500萬chunk,然後模擬叢集主從切換刷路由流程,通過驗證可以復現上一節刷路由的第二階段20秒和第三階段15秒時延消耗,但是第一階段的32分鐘時延消耗始終無法復現。


                            6.2.1 刷路由程式碼走讀確認32分鐘hang住問題


                            到這裡,沒轍,只能走讀核心程式碼,通過走讀核心程式碼發現該版本在第一階段從config server獲取變化的路由資訊持久化到本地config.cache.chunks.db_xx.collection_xx表時,會增加一個waitForLinearizableReadConcern邏輯,對應程式碼如下:

                              
                              Status ShardServerCatalogCacheLoader::_ensureMajorityPrimaryAndScheduleTask(  
                              
                                  OperationContext* opCtx, const NamespaceString& nss, Task task) {  
                              
                              
                              
                              //寫一個noop到多數派節點成功才返回,如果這時候主從延遲過高,則這裡會卡頓      Status linearizableReadStatus = waitForLinearizableReadConcern(opCtx);   if (!linearizableReadStatus.isOK()) {   return {linearizableReadStatus.code(),            str::stream() << "Unable to schedule routing table update because this is not the"             << " majority primary and may not have the latest data. Error: "              << linearizableReadStatus.reason()};      }  
                              //繼續處理後續邏輯   ......   }


                              從上面程式碼可以看出,在把獲取到的增量路由資訊持久化到本地config.cache.chunks表的時候會寫入一個noop空操作到local.oplog.rs表,當noop空操作同步到大部分從節點後,該函式返回,否則一直阻塞等待。


                              6.2.2  診斷資料確認hang住過程是否由主從延遲引起


                              上面 程式碼走讀懷疑從config server獲取增量路由資訊由於主從延遲造成整個流程阻塞,由於該叢集沒有主從延遲相關監控,並且異常時間點mongostat資訊缺失,為了確認叢集異常時間點是否真的有主從延遲存在,因此只能藉助diagnose.data診斷資料來分析。


                              由於主節點已經hang住,不會有讀寫流量,如果主節點流量為0,並且從節點有大量的回放opcountersRepl.insert統計,則說明確實有主從延遲。刷路由hang住恢復時間點前35秒左右的opcountersRepl.insert增量診斷資料如下:


                              行業案例| 千億級高併發MongoDB叢集在某頭部金融機構中的應用及效能優化實踐(上)


                              從節點回放完成時間點,和刷路由hang住恢復時間點一致,從診斷資料可以確認問題由主從延遲引起。


                              6.2.3 模擬主從延遲情況下手動觸發路由重新整理復現問題


                              為了進一步驗證確認主從延遲對刷路由的影響,搭建分片叢集,向該叢集寫入百萬chunks,然後進行如下操作,手動觸發主節點進行路由重新整理:


                              1. 新增anyAction許可權賬號。

                              2. 通過mongos修改config.chunks表,手動修改一個chunk的主版本號為當前shardversion主版本號+1。

                              3. Shard server主節點中的所有節點設定為延遲節點,延遲時間1小時。

                              4. 通過mongos訪問屬於該chunk的一條資料。


                              通過mongos訪問該chunk資料,mongos會攜帶最新的shardVersion傳送給主節點,這時候主節點發現本地主版本號比mongos攜帶的請求版本號低,就會進入從config server獲取最新路由資訊的流程,最終走到waitForLinearizableReadConcern等待一個noop操作同步到多數節點的邏輯,由於這時候兩個從節點都是延遲節點,因此會一直阻塞


                              通過驗證,當取消從節點的延遲屬性,mongos訪問資料立刻返回了。從這個驗證邏輯可以看出,主從延遲會影響刷路由邏輯,最終造成請求阻塞。


                              說明:3.6.8版本開始去掉了刷路由需要等待多數派寫成功的邏輯,不會再有因為主從延遲引起的刷路由阻塞問題。


                              6.3.3 刷路由阻塞優化方法


                              1. 事前優化方法:避免切主進入路由重新整理流程


                              前面提到該叢集只會在主從切換的時候觸發路由重新整理,由於該叢集各個分片balance比較均衡,因此關閉了balance,這樣就不會進行moveChunk操作,表對應的shardVserion主版本號不會變化。


                              但是,由於該業務對一致性要求較高,因此只會讀寫主節點。路由後設資料預設持久化在cache.chunks.dbxx.collectionxx表中,記憶體中記錄路由資訊是一種“惰性”載入過程,由於從節點沒有讀流量訪問該表,因此記憶體中的該表的後設資料版本資訊一直為0,也就是日誌中的”GTE cache version 0|0||000000000000000000000000”,切主後記憶體後設資料版本同樣為0。當使用者通過mongos訪問新主的時候版本號肯定小於mongos轉發攜帶的版本號,進而會進入路由重新整理流程。


                              Chunk路由資訊儲存在cache.chunks.dbxx.collectionxx表中,從節點實時同步主節點該表的資料,但是該資料沒有載入到從記憶體後設資料中。如果我們在切主之前提前把cache.chunks表中持久化的路由資料載入到記憶體中,這樣切主後就可以保證和叢集該表的最新版本資訊一致,同時通過mongos訪問該主節點的時候因為版本資訊一致,就不會進入路由重新整理流程,從而優化規避切主進行路由重新整理的流程。


                              結合3.6.3版本MongoDB核心程式碼,核心只有在使用者請求同時帶有以下引數的情況下才會從對應從節點進行路由版本檢查並載入cache.chunks表中持久化的最新版本資訊到記憶體後設資料中:


                              • 請求帶有讀寫分離配置

                              • 請求攜帶readConcern: { level: <level> }配置或者請求攜帶afterClusterTime引數資訊


                              從節點進行版本檢測判斷及路由重新整理流程核心程式碼如下:

                                
                                void execCommandDatabase(…) {  
                                
                                        ......  
                                
                                if (!opCtx->getClient()->isInDirectClient() &&  
                                
                                          readConcernArgs.getLevel() != repl::ReadConcernLevel::kAvailableReadConcern &&  
                                
                                            (iAmPrimary ||  
                                
                                             ((serverGlobalParams.featureCompatibility.getVersion() ==  
                                
                                               ServerGlobalParams::FeatureCompatibility::Version::kFullyUpgradedTo36) &&  
                                
                                //如果是從節點,則需要請求攜帶readConcern: { level: <level> }配置
                                
                                //  或者請求攜帶afterClusterTime引數資訊  
                                
                                       (readConcernArgs.hasLevel() || readConcernArgs.getArgsClusterTime())))) {  
                                
                                //獲取版本資訊,並記錄下來  
                                
                                        oss.initializeShardVersion(NamespaceString(command>parseNs  
                                
                                                 (dbname, request.body)),   shardVersionFieldIdx);  
                                
                                        ......  
                                
                                }  
                                
                                
                                
                                //重新整理後設資料資訊,例如表對應chunk路由資訊等   Status ShardingState::onStaleShardVersion(…) {      ......   //本地的shardversion和代理mongos傳送過來的做比較,如果本地快取的 //版本號比mongos的高,則啥也不做不用重新整理後設資料   if (collectionShardVersion.epoch() == expectedVersion.epoch() &&          collectionShardVersion >= expectedVersion) {   return Status::OK();      }  
                                //如果本地路由版本比接收到的低,則直接進入路由重新整理流程      refreshMetadata(opCtx, nss);      ......   }


                                從上面的分析可以看出,只有對指定表做讀寫分離配置訪問,並且帶上相關readConcern配置,才會進行路由版本檢查,並會獲取最新路由資料同時載入到記憶體中。因此,如果在切主之前提前把最新的路由資料載入到記憶體,則mongos轉發請求到新主後就不會進入路由重新整理流程。

                                從節點提前實時載入最新路由資料到cache中,可以通過定期執行如下指令碼來實現,通過mongos定期訪問所有分片從節點,指令碼核心程式碼如下:
                                  use dbxx  db.getMongo().setReadPref('secondary')  //訪問分片1從節點資料  db.collectionxx.find({"_id" : ObjectId("xxx")}).readConcern("local")  ......  //訪問分片n從節點資料  db.collectionxx.find({"_id" : ObjectId("xxx")}).readConcern("local")

                                  2. 事後優化方法

                                  通過上面的定期探測指令碼,從節點實時載入最新路由到記憶體中可以規避極大部分情況下切主進入路由重新整理的流程。但是由於只能定時探測執行指令碼,因此如果在兩次探測期間叢集路由版本發生了變化,並且變化的路由還沒有載入到記憶體中,這時候還是有可能存在路由版本資訊不一致的情況,還是會進入路由重新整理流程。如果這時候主從有延遲,還是會觸發刷路由卡頓較長時間問題。

                                  為了解決這種極端情況主從延遲引起的路由重新整理長時間hang住問題,可以在切主後進行主從延遲檢查,如果存在多數從節點有延遲的情況,可以通過以下方法優化解決:

                                  • 登入新主

                                  • rs.printSlaveReplicationInfo()檢視主從延遲

                                  • 確認有延遲的從節點

                                  • rs.remove()剔除有延遲的從節點


                                  剔除從節點後,刷路由即可立馬完成。

                                  6.3 路由重新整理hang住問題總結

                                  上面分析可以看出,《問題現象》章節提到路由重新整理過程三個階段耗時分別為:32分鐘、20秒、15秒。其中,第一階段已分析完成,第二階段的20秒和第三階段的15秒時間消耗依然待解決。

                                  在4.x版本及最新的5.0版本,全量路由重新整理和增量路由重新整理過程總體做了一些優化,但是當chunks數達到百萬級別時,路由重新整理過程還是有秒級抖動。

                                  本文只分析了路由重新整理的主要流程,鑑於篇幅,後續會在專門的《千億級高併發MongoDB叢集在某頭部金融機構中的應用及效能優化實踐(下)》和《MongoDB分片叢集核心路由原理及其實現細節》中進行更詳細的分析,並給出騰訊雲MongoDB團隊在路由重新整理流程中的核心優化方法。
                                   
                                  說明:

                                  如前文所述,本文中部分定位步驟依賴FTDC是因為系統監控和運維工具的缺失導致只能從下層工具入手定位和分析問題,如果有一個好的運維監控系統,本文裡的很多問題將能更輕鬆地解決。


                                  關於作者— 騰訊雲MongoDB團隊



                                  來自 “ ITPUB部落格 ” ,連結:http://blog.itpub.net/69961190/viewspace-2901813/,如需轉載,請註明出處,否則將追究法律責任。