某头部金融系统采用 MongoDB 存储重要的金融数据，数据量较大，数据规模约 2000 亿左右，读写流量较高，峰值突破百万级/每秒。本文分享该千亿级高并发 MongoDB 集群的踩坑及性能优化实践，通过本文可以了解如下信息：
l 如何对海量 MongoDB 集群进行性能瓶颈定位
千亿规模集群常用踩坑点
如何对高并发大数据量 MongoDB 集群进行性能优化
集群监控信息缺失，如何分析集群抖动问题
如何像原厂工程师一样借助 diagnose.data(not human-readable)分析内核问题
第一章：业务背景及 MongoDB FTDC 诊断介绍
1. 业务背景
该 MongoDB 集群采用多分片架构部署，业务不定期长时间高并发读写，该集群业务背景总结如下：
随着时间推移，集群数据规模超过千接近 2000 亿，集群遇到了一些疑难问题，如主从切换、节点异常挂掉、节点数秒卡顿、切主后新主数十分钟不可用等问题，下面章节将逐步分享这些问题，并给出对应的优化方法。
鉴于篇幅，本文无法分享完该案例遇到的所有问题及其优化方法，因此《千亿级高并发 MongoDB 集群在某头部金融系统中的应用及性能优化实践(下)》中将继续分享本案例遗留的性能优化方法，同时分享分布式数据库核心路由模块原理，并给出腾讯云在最新 MongoDB 版本中对路由刷新模块所做的优化。
2. MongoDB ftdc 诊断数据简介
Diagnose.data 数据由 MongoDb 内核的 Full Time Diagnostic Data Capture (FTDC)实现，在 MongoDB 3.2 中引入，以全量+增量方式收集某些诊断命令的结果，以帮助 MongoDB 原厂工程师排查分析问题。
1.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 目录结构
如下所示：
1. root@:/data1/xxxx/xxxx/db# ls 2. 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 3. root@:/data1/xxxx/xxxx/db# 4. root@:/data1/xxxx/xxxx/db# 5. root@:/data1/xxxx/xxxx/db# 6. root@:/data1/xxxx/xxxx/db#
复制代码
diagnostic.data 目录中按照时间记录各种不同诊断信息到 metrics 文件，除了 metrics.interim 文件，其他文件内容大约 10M 左右。
1. root@:/data1/xxxx/xxx/db/diagnostic.data# 2. root@:/data1/xxxx/xxxx/db/diagnostic.data# ls 3. metrics.xxxx-12-27T02-28-58Z-00000 metrics.xxxx-12-28T14-33-57Z-00000 4. metrics.xxxx-12-30T04-28-57Z-00000 metrics.xxxx-12-31T17-08-57Z-00000 5. metrics.xxxx-01-02T05-28-57Z-00000 metrics.xxxx-12-27T09-18-58Z-00000 6. metrics.xxxx-12-28T23-13-57Z-00000 metrics.xxxx-12-30T11-23-57Z-00000 7. metrics.xxxx-01-01T00-53-57Z-00000 metrics.interim 8. metrics.xxxx-12-27T16-28-57Z-00000 metrics.xxxx-12-29T06-08-57Z-00000 9. metrics.xxxx-12-30T19-18-57Z-00000 metrics.xxxx-01-01T07-23-57Z-00000 10. metrics.xxxx-12-28T00-48-57Z-00000 metrics.xxxx-12-29T12-58-57Z-00000 11. metrics.xxxx-12-31T02-58-57Z-00000 metrics.xxxx-01-01T14-18-57Z-00000 12. metrics.xxxx-12-28T07-38-57Z-00000 metrics.xxxx-12-29T21-18-57Z-00000 13. metrics.xxxx-12-31T09-48-57Z-00000 metrics.xxxx-01-01T22-38-57Z-00000 14. root@:/data1/xxx/xxxx/db/diagnostic.data# 15. root@:/data1/xxxx/xxxx/db/diagnostic.data#
复制代码
第二章：集群踩坑过程及优化方法
3. mem lock 不足引起的节点崩掉问题及解决方法
该集群在运行过程中，出现“Failed to mlock: Cannot allocate memory”，mongod 进程崩掉，该问题和 jira 中的一下 bug 一模一样：
1. SERVER-29086
2. SERVER-28997
触发该问题的日志信息如下：
1. Xxxx 12 22:51:28.891 F - [conn7625] Failed to mlock: Cannot allocate memory 2. Xxxx 12 22:51:28.891 F - [conn7625] Fatal Assertion 28832 at src/mongo/base/secure_allocator.cpp 246 3. Xxxx 12 22:51:28.891 F - [conn7625] 4. ***aborting after fassert() failure 5. Xxxx 12 22:51:28.918 F - [conn7625] Got signal: 6 (Aborted). 6. .......... 7. ----- BEGIN BACKTRACE ----- 8. {"backtrace": 9. libc.so.6(abort+0x148) [0x7fccf1b898c8] 10. mongod(_ZN5mongo32fassertFailedNoTraceWithLocationEiPKcj+0x0) [0x7fccf3b33ed2] 11. mongod(_ZN5mongo24secure_allocator_details8allocateEmm+0x59D) [0x7fccf51d6d6d] 12. mongod(_ZN5mongo31SaslSCRAMServerConversationImplINS_8SHABlockINS_15SHA1BlockTraitsEEEE26initAndValidateCredentialsEv+0x167) [0x7fccf4148ca7] 13. mongod(_ZN5mongo27SaslSCRAMServerConversation10_firstStepENS_10StringDataEPNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEE+0x959) [0x7fccf414dcd9] 14. mongod(_ZN5mongo27SaslSCRAMServerConversation4stepENS_10StringDataEPNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEE+0x9B) [0x7fccf414eecb] 15. mongod(_ZN5mongo31NativeSaslAuthenticationSession4stepENS_10StringDataEPNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEE+0x3C) [0x7fccf414731c] 16. mongod(+0xF355CD) [0x7fccf41405cd] 17. mongod(+0xF37D3A) [0x7fccf4142d3a] 18. mongod(_ZN5mongo12BasicCommand11enhancedRunEPNS_16OperationContextERKNS_12OpMsgRequestERNS_14BSONObjBuilderE+0x76) [0x7fccf4cefde6]
复制代码
官方 jira 系统说明该 bug 已经在 3.6 版本中修复，但是又有新用户在报告在 3.6 版本中遇到了同样的问题，并且按照官方建议做了 memlock unlimited 配置。
走读对应版本 MongoDB 内核代码，可以看出内核认证流程和建账号流程会使用 SecureAllocator 内存分配器进行内存分配，默认情况通过 mmap+mlock 方式进行 memlock 分配，但是这里内核源码实际上加了一个开关，用户可以自己决定是否使用 memlock。核心代码如下：
1. //disabledSecureAllocatorDomains配置初始化配置 2. ExportedServerParameter<std::vector<std::string>, ServerParameterType::kStartupOnly> 3. SecureAllocatorDomains(ServerParameterSet::getGlobal(), 4. "disabledSecureAllocatorDomains", 5. &serverGlobalParams.disabledSecureAllocatorDomains); 6. 7. template <typename NameTrait> 8. struct TraitNamedDomain { 9. //该接口在SecureAllocatorDomain类中的相关接口中生效，决定走mlock流程还是普通malloc流程 10. static bool peg() { 11. const auto& dsmd = serverGlobalParams.disabledSecureAllocatorDomains; 12. const auto contains = [&](StringData dt) { 13. return std::find(dsmd.begin(), dsmd.end(), dt) != dsmd.end(); 14. }; 15. 16. //注意这里，如果disabledSecureAllocatorDomains配置为*，直接false 17. static const bool ret = !(contains("*"_sd) || contains(NameTrait::DomainType)); 18. return ret; 19. } 20. }; 21. 22. void deallocate(pointer ptr, size_type n) { 23. return secure_allocator_details::deallocateWrapper( 24. //peg()决定是走mlock流程还是普通malloc流程 25. static_cast<void*>(ptr), sizeof(value_type) * n, DomainTraits::peg()); 26. } 27. 28. inline void* allocateWrapper(std::size_t bytes, std::size_t alignOf, bool secure) { 29. if (secure) { 30. //最终走mlock流程 31. return allocate(bytes, alignOf); 32. } else { 33. //走std::malloc普通内存分配流程 34. return mongoMalloc(bytes); 35. } 36. }
复制代码
从上面的内核核心代码可以看出，认证流程、账号创建流程的 security 内存分配有两种方式，如下：
默认方式，认证过程的 scram::generateSecrets 流程默认使用 memlock。
需要添加 disabledSecureAllocatorDomains: "*"配置，禁用 mlock，使用普通内存。
disabledSecureAllocatorDomains 在官方文档没用说明，经过实际测试验证，禁用 memlock 对链接认证影响不大，同时因为用户是长连接请求，因此影响基本上忽略。
Mlock 不足引起的节点崩掉问题可以通过在配置文件增加如下配置解决：
1. setParameter: 2. disabledSecureAllocatorDomains: '*'
复制代码
4. 压力过大引起的主从切换及优化方法
问题：主节点压力大，集群出现主从切换现象，切换期间业务访问异常。
4.1. 日志分析过程
主从切换过程中，由于读写流量都走主节点，因此切换过程会有大量报错，收集对应日志，核心日志如下：
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 2. 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 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 4. Xxxx 11 12:02:20.211 I REPL [replexec-4628] Starting an election, since we've seen no PRIMARY in the past 10000ms 5. 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 6. Xxxx 11 12:02:20.215 I ASIO [NetworkInterfaceASIO-Replication-0] Connecting to x.x.x.x:11200 7. 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 } } } 8. Xxxx 11 12:02:20.393 I REPL [replexec-4620] dry election run succeeded, running for election in term 32 9. 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 10. Xxxx 11 12:02:20.474 I REPL [replexec-4628] Member x.x.x.x:11200 is now in state RS_DOWN 11. 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 } } } 12. Xxxx 11 12:02:20.629 I REPL [replexec-4620] election succeeded, assuming primary role in term 32 13. Xxxx 11 12:02:20.630 I REPL [replexec-4620] transition to PRIMARY from SECONDARY
复制代码
从上面的核心日志可以看出，该时间点从节点和主节点的保活超时了，该从节点从新发起了一次选举，选举大概 1 秒钟左右完成，该从节点被提升为新的主节点。
4.2. diagnose 诊断分析确认根因
上面的日志分析初步判断主从切换由保活超时引起，问题根因定位就需要分析出引起保活超时的原因。由于该云下集群监控信息缺失，因此收集用户 diagnose.data 诊断数据进行分析，最终通过分析诊断数据确认根因。
根据以往经验，主从保活超时可能原因主要有以下几种情况：
分析该集群多个节点日志，只有该从节点出现了保活超时现象，其他分片节点不存在该问题，并且该从节点一秒钟内快速被选为新的主节点，因此可以排除网络抖动问题。
对应时间点主节点有大量慢查，通过慢查可以看出该时间段慢查询时间在几十毫秒到数秒、数十秒波动，因此节点不是完全 hang 死的，可以排除节点长时间 hang 死的情况。
如果主压力过大，主节点的所有请求存在排队现象，这时候就可能引起保活超时。同时，结合后面的诊断数据分析，最终确认该问题由主压力过大引起。
该集群只有 mongostat 监控信息，无其他监控数据，切换前一段时间该主节点对应 mongostat 监控信息如下：
从上面打印可以看出，在切换前一段时间的流量较高，该分片主节点读写流量超过 15W/s，used 内存逐渐接近 95%。但是很遗憾，接近切换前一分钟内的 mongostat 监控没有获取到，对应报错信息如下：
从上面的 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 内核也做了适当优化，主要通过适当调整主从保活超时时间来规避缓解问题：
1. cfg = rs.conf() 2. cfg.settings.heartbeatTimeoutSecs=20 3. cfg.settings.electionTimeoutMillis=20000 4. rs.reconfig(cfg)
复制代码
总结：通过业务侧和内核优化最终规避了主从切换问题。
5. 节点十秒级 hang 住问题诊断及优化
问题：流量低峰期，集群节点十秒级 hang 住，业务抖动。
在集群运行过程中，还出现一些比较奇怪的问题，集群有时候低峰期的时候出现 hang 住现象，这期间数秒甚至数十秒内所有请求超时，核心日志如下：
1. Xxxx 11 10:08:22.107 I COMMAND [conn15350423] command xx.xxx command: find ........................... protocol:op_msg 92417ms 2. ............. 3. 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 } 4. ......... 5. Xxxx 11 10:08:22.109 I COMMAND [conn15350423] command xx.xxxx command: find ........................... protocol:op_msg 112417ms 6. 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 诊断数据如下：
如上图所示，异常时间点 tcmalloc 模块缓存的内存十秒钟内瞬间一次性释放了接近 40G 内存，因此造成了整个节点 hang 住。
优化方法：实时 pageHeap 释放，避免一次性大量 cache 集中式释放引起节点 hang 住，MongoDB 实时加速释放对应内存命令如下，可通过 tcmallocReleaseRate 控制释放速度：
db.adminCommand( { setParameter: 1, tcmallocReleaseRate: 5.0 } )
复制代码
该命令可以加快释放速度，部分 MongoDB 内核版本不支持，如果不支持也可以通过下面的命令来进行激进的内存释放：
db.adminCommand({setParameter:1,tcmallocAggressiveMemoryDecommit:1})
复制代码
6. 主从切换成功后新主数十分钟不可用问题及优化方法
该集群除了遇到前面的几个问题外，还遇到了一个更严重的问题，主从切换后数十分钟不可用问题。下面我们开始结合日志和诊断数据分析新主数十分钟不可用问题根因：
6.1. 问题现象
6.1.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 2. Xxx xxx 8 23:43:36.439 I REPL [replexec-8667] Starting an election, since we've seen no PRIMARY in the past 10000ms 3. 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 4. ..... 5. Xxx xxx 8 23:43:44.260 I REPL [replexec-8666] election succeeded, assuming primary role in term 11 6. ..... 7. Xxx xxx 8 23:43:44.261 I REPL [replexec-8666] transition to PRIMARY from SECONDARY 8. 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 主核心日志如下：
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 住了。
切主后，新主刷路由核心流程如下：
1. Xxx xxx 8 23:43:53.306 I SHARDING [conn357594] Refreshing chunks for collection db_xx.collection_xx based on version 0|0||000000000000000000000000 2. 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 3. 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||0000000000000000000000004. Xxxx 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
复制代码
上面的刷路由过程主要时间段如下：
23:43:53 - 00:15:47，持续时间约 32 分钟。
00:15:47 - 00:16:06，持续时间约 20 秒
00:16:06 - 00:16:21，持续时间 15 秒。
通过上面的日志分析，基本上可以确认问题是由于主从切换后路由刷新引起，但是整个过程持续 30 分钟左右，业务 30 分钟左右不可用，这确实不可接受。
6.1.3. 切主后路由刷新核心原理
MongoDB 内核路由刷新流程比较复杂，这里只分析 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 逻辑，对应代码如下：
1. Status ShardServerCatalogCacheLoader::_ensureMajorityPrimaryAndScheduleTask( 2. OperationContext* opCtx, const NamespaceString& nss, Task task) { 3. 4. //写一个noop到多数派节点成功才返回，如果这时候主从延迟过高，则这里会卡顿 5. Status linearizableReadStatus = waitForLinearizableReadConcern(opCtx); 6. if (!linearizableReadStatus.isOK()) { 7. return {linearizableReadStatus.code(), 8. str::stream() << "Unable to schedule routing table update because this is not the" 9. << " majority primary and may not have the latest data. Error: " 10. << linearizableReadStatus.reason()}; 11. } 12. 13. //继续处理后续逻辑14. ...... 15. }
复制代码
从上面代码可以看出，在把获取到的增量路由信息持久化到本地 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 增量诊断数据如下：
从节点回放完成时间点，和刷路由 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. 刷路由阻塞优化方法
前面提到该集群只会在主从切换的时候触发路由刷新，由于该集群各个分片 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 表中持久化的最新版本信息到内存元数据中：
1. 请求带有读写分离配置
2. 请求携带 readConcern: { level: <level> }配置或者请求携带 afterClusterTime 参数信息
从节点进行版本检测判断及路由刷新流程核心代码如下:
1. void execCommandDatabase(…) { 2. ...... 3. if (!opCtx->getClient()->isInDirectClient() && 4. readConcernArgs.getLevel() != repl::ReadConcernLevel::kAvailableReadConcern && 5. (iAmPrimary || 6. ((serverGlobalParams.featureCompatibility.getVersion() == 7. ServerGlobalParams::FeatureCompatibility::Version::kFullyUpgradedTo36) && 8. //如果是从节点，则需要请求携带readConcern: { level: <level> }配置9. // 或者请求携带afterClusterTime参数信息 10. (readConcernArgs.hasLevel() || readConcernArgs.getArgsClusterTime())))) { 11. //获取版本信息，并记录下来 12. oss.initializeShardVersion(NamespaceString(command>parseNs 13. (dbname, request.body)), shardVersionFieldIdx); 14. ...... 15. } 16. 17. //刷新元数据信息，例如表对应chunk路由信息等 18. Status ShardingState::onStaleShardVersion(…) { 19. ...... 20. //本地的shardversion和代理mongos发送过来的做比较，如果本地缓存的21. //版本号比mongos的高，则啥也不做不用刷新元数据 22. if (collectionShardVersion.epoch() == expectedVersion.epoch() && 23. collectionShardVersion >= expectedVersion) { 24. return Status::OK(); 25. } 26. 27. //如果本地路由版本比接收到的低，则直接进入路由刷新流程 28. refreshMetadata(opCtx, nss); 29. ...... 30. }
复制代码
从上面的分析可以看出，只有对指定表做读写分离配置访问，并且带上相关 readConcern 配置，才会进行路由版本检查，并会获取最新路由数据同时加载到内存中。因此，如果在切主之前提前把最新的路由数据加载到内存，则 mongos 转发请求到新主后就不会进入路由刷新流程。
从节点提前实时加载最新路由数据到 cache 中，可以通过定期运行如下脚本来实现，通过 mongos 定期访问所有分片从节点，脚本核心代码如下：
1. use dbxx 2. db.getMongo().setReadPref('secondary') 3. //访问分片1从节点数据 4. db.collectionxx.find({"_id" : ObjectId("xxx")}).readConcern("local") 5. ...... 6. //访问分片n从节点数据 7. db.collectionxx.find({"_id" : ObjectId("xxx")}).readConcern("local")
复制代码
通过上面的定期探测脚本，从节点实时加载最新路由到内存中可以规避极大部分情况下切主进入路由刷新的流程。但是由于只能定时探测运行脚本，因此如果在两次探测期间集群路由版本发生了变化，并且变化的路由还没有加载到内存中，这时候还是有可能存在路由版本信息不一致的情况，还是会进入路由刷新流程。如果这时候主从有延迟，还是会触发刷路由卡顿较长时间问题。
为了解决这种极端情况主从延迟引起的路由刷新长时间 hang 住问题，可以在切主后进行主从延迟检查，如果存在多数从节点有延迟的情况，可以通过以下方法优化解决：
1. 登录新主
2. rs.printSlaveReplicationInfo()查看主从延迟
3. 确认有延迟的从节点
4. rs.remove()剔除有延迟的从节点
剔除从节点后，刷路由即可立马完成。
6.3. 路由刷新 hang 住问题总结
上面分析可以看出，《问题现象》章节提到路由刷新过程三个阶段耗时分别为：32 分钟、20 秒、15 秒。其中，第一阶段已分析完成，第二阶段的 20 秒和第三阶段的 15 秒时间消耗依然待没有解决。
在 4.x 版本及最新的 5.0 版本，全量路由刷新和增量路由刷新过程总体做了一些优化，但是当 chunks 数达到百万级别时，路由刷新过程还是有秒级抖动。
本文只分析了路由刷新的主要流程，鉴于篇幅，后续会在专门的《千亿级高并发 MongoDB 集群在某头部金融系统中的应用及性能优化实践(下)》和《MongoDB 分片集群核心路由原理及其实现细节》中进行更详细的分析，并给出腾讯云 MongoDB 团队在路由刷新流程中的内核优化方法。
说明：
如前文所述，本文中部分定位步骤依赖 FTDC 是因为系统监控和运维工具的缺失导致只能从下层工具入手定位和分析问题，如果有一个好的运维监控系统，本文里的很多问题将能更轻松地解决。
腾讯云 MongoDB 已经集成 DBbrain 智能数据库管家，提供一站式 MongoDB 运维服务，帮助用户轻松发现、解决和预防运维问题。
关于作者
腾讯云 MongoDB 团队：
腾讯云 MongoDB 当前服务于游戏、电商、社交、教育、新闻资讯、金融、物联网、软件服务等多个行业；MongoDB 团队(简称 CMongo)致力于对开源 MongoDB 内核进行深度研究及持续性优化(如百万库表、物理备份、免密、审计等)，为用户提供高性能、低成本、高可用性的安全数据库存储服务。后续持续分享 MongoDB 在腾讯内部及外部的典型应用场景、踩坑案例、性能优化、内核模块化分析。
评论