千亿级高并发MongoDB集群在某头部金融系统中的应用及性能优化实践(上)
某头部金融系统采用MongoDB存储重要的金融数据，数据量较大，数据规模约2000亿左右，读写流量较高，峰值突破百万级/每秒。本文分享该千亿级高并发MongoDB集群的踩坑及性能优化实践，通过本文可以了解如下信息：
- 如何对海量MongoDB集群进行性能瓶颈定位
- 千亿规模集群常用踩坑点
- 如何对高并发大数据量MongoDB集群进行性能优化
- 集群监控信息缺失，如何分析集群抖动问题
- 如何像原厂工程师一样借助diagnose.data(not human-readable)分析内核问题
第一章：业务背景及MongoDB FTDC诊断介绍
1. 业务背景
该MongoDB集群采用多分片架构部署，业务不定期长时间高并发读写，该集群业务背景总结如下：
- 数据量大，该集群总数据量突破千亿规模
- 集群最大表总chunks数约500万
- 长时间高并发读写
- 一致性要求较高，读写全走主节点
- 高峰期持续性读写qps百万/秒
- 单分片峰值流量接近20万/秒
- 内核版本：3.6.3版本
- 非云上集群
- 除了节点日志，详细监控数据因历史原因缺失，无MongoDB常用监控指标信息
随着时间推移，集群数据规模超过千亿，集群遇到了一些疑难问题，如主从切换、节点异常挂掉、节点数秒卡顿、切主后新主数十分钟不可用等问题，下面章节将逐步分享这些问题，并给出对应的优化方法。
鉴于篇幅，本文无法分享完该案例遇到的所有问题及其优化方法，因此《千亿级高并发MongoDB集群在某头部金融系统中的应用及性能优化实践(下)》中将继续分享本案例遗留的性能优化方法，同时分享分布式数据库核心路由模块原理，并给出腾讯云在最新MongoDB版本中对路由刷新模块所做的优化。
2. MongoDB ftdc诊断数据简介
Diagnose.data数据由MongoDb内核的Full Time Diagnostic Data Capture (FTDC)实现，在MongoDB 3.2中引入，以全量+增量方式收集某些诊断命令的结果，以帮助MongoDB原厂工程师排查分析问题。
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.
从上面可以看出，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);
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. };
16. //注意这里，如果disabledSecureAllocatorDomains配置为*，直接false
17. static const bool ret = !(contains("*"_sd) || contains(NameTrait::DomainType));
18. return ret;
19. }
20. };
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. }
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内存分配有两种方式，如下：
- Memlock内存方式
默认方式，认证过程的scram::generateSecrets流程默认使用memlock。
- 普通malloc内存方式
需要添加disabledSecureAllocatorDomains: "*"配置，禁用mlock，使用普通内存。
disabledSecureAllocatorDomains在官方文档没用说明，经过实际测试验证，禁用memlock对链接认证影响不大，同时因为用户是长连接请求，因此影响基本上忽略。
Mlock不足引起的节点崩掉问题可以通过在配置文件增加如下配置解决：
1. setParameter:
2. disabledSecureAllocatorDomains: '*' 1. 压力过大引起的主从切换及优化方法
问题：主节点压力大，集群出现主从切换现象，切换期间业务访问异常。
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死的，可以排除节点长时间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.1. 问题现象功后新主数十分钟不可用问题及优化方法
该集群除了遇到前面的几个问题外，还遇到了一个更严重的问题，主从切换后数十分钟不可用问题。下面我们开始结合日志和诊断数据分析新主数十分钟不可用问题根因：
1.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住半小时
切主后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||000000000000000000000000
4. 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
上面的刷路由过程主要时间段如下：
- 第一阶段： 从远端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. 切主后路由刷新核心原理
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) {
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. }
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. }
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. }
27. //如果本地路由版本比接收到的低，则直接进入路由刷新流程
28. refreshMetadata(opCtx, nss);
29. ......
30. }
从上面的分析可以看出，只有对指定表做读写分离配置访问，并且带上相关readConcern配置，才会进行路由版本检查，并会获取最新路由数据同时加载到内存中。因此，如果在切主之前提前把最新的路由数据加载到内存，则mongos转发请求到新主后就不会进入路由刷新流程。
从节点提前实时加载最新路由数据到cache中，可以通过定期运行如下脚本来实现，通过mongos定期访问所有分片从节点，脚本核心代码如下：
1. use dbxx
2. db.getMongo().setReadPref('secondary')