MongoDB 实例 Crash 的故障现象问题

1故障现象

近日，朋友遇到一个 MongoDB 实例 Crash 的问题，找到我帮忙一起分析原因，事情经过以及分析过程如下，可供学习。

操作过程

运维人员在优化慢查询时针对性创建了一个索引，语句如下：

db.c1.createIndex('name':1,background:true)

随后又将表上一个没能用上的索引删除，语句如下：

db.c1.dropIndex('idx_age')

在主节点上很顺利的就完成了，但是不久后就发现从节点发生了 Crash，日志中包含下列崩溃信息。

2023-04-13T0750.752+0000ESTORAGE[conn3569849]WiredTigererror(-31802)[1681369250:752455][9937:0x7fe740144700],WT_CONNECTION.open_session:__open_session,2058:outofsessions,configuredfor20030(includinginternalsessions):WT_ERROR:non-specificWiredTigererrorRaw:[1681369250:752455][9937:0x7fe740144700],WT_CONNECTION.open_session:__open_session,2058:outofsessions,configuredfor20030(includinginternalsessions):WT_ERROR:non-specificWiredTigererror
2023-04-13T0750.752+0000INETWORK[listener]connectionacceptedfromxxx.xxx.xxx.xxx#3570023(20576connectionsnowopen)
2023-04-13T0750.753+0000F-[conn3569849]Invariantfailure:conn->open_session(conn,NULL,"isolation=snapshot",&_session)resultedinstatusUnknownError:-31802:WT_ERROR:non-specificWiredTigererroratsrc/mongo/db/storage/wiredtiger/wiredtiger_session_cache.cpp111

其它信息

变更表是一张几千万的大表；

数据库架构为 MongoDB 4.0.14 的 PSA 架构；

应用开启了读写分离，从节点也存在大量只读请求。

2问题分析

根据日志信息，初步怀疑是连接打满了，检查最大连接数配置。

初步排查

shard1:PRIMARY>db.serverStatus().connections;
{"current":7,"available":29993,"totalCreated":7,"active":2}

最大连接数是由 maxIncomingConnections 参数和 ulimit 决定的。

net:
maxIncomingConnections:30000

在测试环境模拟连接数打满的情况，发现在连接数满了的情况下实例只会拒绝新的连接，而非直接 Crash。

connectingto:mongodb://10.186.64.88:27017/admin?gssapiServiceName=mongodb
2023-04-19T1326.578+0000INETWORK[js]DBClientConnectionfailedtoreceivemessagefromxxx.xxx.xxx.xxx-HostUnreachable:Connectionclosedbypeer
2023-04-19T1326.579+0000EQUERY[js]Error:networkerrorwhileattemptingtoruncommand'isMaster'onhost'10.186.64.88:27017':
connect@src/mongo/shell/mongo.js17
@(connect)6
exception:connectfailed

根据 SERVER-30462 描述怀疑是 WT_SESSION[1] 打满的情况。

WT_SESSION 是 MongoDB Server 和 WiredTiger[2] 存储引擎内部交互使用的会话，几乎所有操作都是在 WT_SESSION 的上下文中执行的。因此 WT_SESSION 在超过限制后将会触发较为严重的情况。

源码分析

在源码 mongo/wiredtiger_kv_engine.cpp[3] 中可以看到 WT_SESSION 硬编码指定为 20000。

std::stringstreamss;
ss<< "create,";
    ss << "cache_size=" << cacheSizeMB << "M,";
    ss << "cache_overflow=(file_max=" << maxCacheOverflowFileSizeMB << "M),";
    ss << "session_max=20000,";
    ss << "eviction=(threads_min=4,threads_max=4),";
    ss << "config_base=false,";
    ss << "statistics=(fast),";

这一点也能在启动日志中进一步得到验证。

如果 WT_SESSION 数量超过 20000，将会触发 out of sessions 的报错。

/*Findthefirstinactivesessionslot.*/
for(session_ret=conn->sessions,i=0;i< conn->session_size;++session_ret,++i)
if(!session_ret->active)
break;
if(i==conn->session_size)
WT_ERR_MSG(session,WT_ERROR,"outofsessions,configuredfor%"PRIu32
"(including"
"internalsessions)",
conn->session_size);

提出疑问

分析到这开始疑惑 WT_SESSION 打满与索引操作存在什么样的关系？为什么相同的操作在主节点可以正常完成，而从节点会发生 Crash？

在创建索引时指定 background:true 可以在后台构建索引，不会加锁阻塞集合上的其它操作，这也是我们日常添加索引常用的方式。

但在删除索引时，我们有一点需要注意，但又常常被忽略，在主节点删除索引后同步到从节点回放时，如果从节点正在跑同一个集合上后台创建索引的操作，那么删除索引的操作将会被阻塞，更严重的是这时候实例上所有 namespace 的访问都将会阻塞。针对这一现象在官网 dropIndex[4] 文档中有提及：

Avoid dropping an index on a collection while any index is being replicated on a secondary. If you attempt to drop an index from a collection on a primary while the collection has a background index building on a secondary, reads will be halted across all namespaces and replication will halt until the background index build completes.

当任何创建索引操作复制到 Secondary 时，应避免在集合上删除索引。如果你试图在 Primary 上删除一个索引，而该集合在 Secondary 上有一个索引正在后台创建，那么所有 namespace 的访问将被停止，复制也会停止，直到后台索引建立完成。

回到错误日志中查找更多内容，就能发现从节点在后台创建索引时，又执行了同一个集合上的删除索引操作。

2023-04-13T0527.002+0000I-[replindexbuilder178]IndexBuild(background):122873800/64001875719%
2023-04-13T0530.002+0000I-[replindexbuilder178]IndexBuild(background):122976300/64001876919%
2023-04-13T0530.434+0000ICOMMAND[replwriterworker11]CMD:dropIndexestest.c1

初步结论

到此，我们得出初步结论。事情起因是主节点在同一个集合上执行创建索引和删除索引后，在从节点回放时出现了很严重的阻塞，大量的只读请求开始不断积压，最后导致 WT_SESSION 消耗殆尽，Server 无法与 WiredTiger 进行内部通信，最终导致实例 Crash。

3问题复现

下面的案例在测试环境复现 WT_SESSION 超过限制的情况，dropIndex 导致从节点锁阻塞的问题有兴趣可自己测试复现，这里就不做演示了。

WT_SESSION 上限是由 wiredtiger_open 配置中的 session_max 决定的，但 MongoDB 并未直接暴露 session_max的配置方式，只能通过下列方式进行覆盖设置。

mongod-f/etc/mongod.conf--wiredTigerEngineConfigString="session_max=5"

然后在数据库内部发起一个全局排它锁。

mongo>db.fsyncLock()

编写下列 Python 脚本模拟并发线程。

#!/usr/bin/python
#-*-coding:UTF-8-*-
importmultiprocessing
importpymongo

deffind():
cnx_args=dict(username='root',password='abcd123#',host='127.0.0.1',port=27018,authSource='admin')
client=pymongo.MongoClient(**cnx_args)
db=client['test']
results=db.tab100.insert_one({"name":"jack"})
if__name__=="__main__":
x=1
whilex<350:
        p=multiprocessing.Process(target=find)
        p.start()
        print("start thread:",x)
        x+=1
    p.join()

这时 MongoDB 实例还在正常运行，因为我们的请求还没有真正的进入到 WiredTiger 引擎层，但一旦我们手动释放排它锁，所有请求都会在短时间内进入 WiredTiger 引擎，WT_SESSION 瞬间超过限制，实例紧接着发生 Crash。

mongo>db.fsyncUnlock()

错误日志如下，与生产日志相同。

4总结

net.maxIncomingConnections 设置应小于 WT_SESSION；

可以根据实际需求调整游标超时时间，避免出现大面积积压的情况；

避免创建索引和删除索引先后执行，特别是先执行后台创建索引的情况下；

4.2 版本中废弃了 background 选项，对索引创建过程进行了优化，只会在索引创建的开始和结束时持有 exclusive lock；并且 4.0 版本官方已经停止提供服务了，建议尽快升级。