千亿级高并发MongoDB集群在某头部金融机构中的应用及性能优化实践(上)

root@:/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  root@:/data1/xxxx/xxxx/db#   root@:/data1/xxxx/xxxx/db#   root@:/data1/xxxx/xxxx/db#   root@:/data1/xxxx/xxxx/db#

root@:/data1/xxxx/xxx/db/diagnostic.data#   root@:/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  root@:/data1/xxx/xxxx/db/diagnostic.data#   root@:/data1/xxxx/xxxx/db/diagnostic.data#

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]

//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);      }  }

setParameter:    disabledSecureAllocatorDomains: '*'

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

cfg = rs.conf()  cfg.settings.heartbeatTimeoutSecs=20  cfg.settings.electionTimeoutMillis=20000  rs.reconfig(cfg)

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  

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

db.adminCommand({setParameter:1,tcmallocAggressiveMemoryDecommit: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.

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

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

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()};      }  
    //继续处理后续逻辑   ......  }

void execCommandDatabase(…) {          ......          if (!opCtx->getClient()->isInDirectClient() &&            readConcernArgs.getLevel() != repl::ReadConcernLevel::kAvailableReadConcern &&              (iAmPrimary ||               ((serverGlobalParams.featureCompatibility.getVersion() ==                 ServerGlobalParams::FeatureCompatibility::Version::kFullyUpgradedTo36) &&            //如果是从节点，则需要请求携带readConcern: { 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);      ......  }

use dbxx  db.getMongo().setReadPref('secondary')  //访问分片1从节点数据  db.collectionxx.find({"_id" : ObjectId("xxx")}).readConcern("local")  ......  //访问分片n从节点数据  db.collectionxx.find({"_id" : ObjectId("xxx")}).readConcern("local")