摘要：本文详细阐述了根据引起 Crash 操作进行从配置到源码的分析过程，层层递进，定位复现并给出解决故障方案。
作者：徐耀荣
爱可生南区交付服务部 DBA 团队成员，主要负责 MySQL 故障处理以及相关技术支持。爱好电影，旅游。
本文来源：原创投稿
- 爱可生开源社区出品，原创内容未经授权不得随意使用，转载请联系小编并注明来源。
故障现象
近日，朋友遇到一个 MongoDB 实例 Crash 的问题，找到我帮忙一起分析原因，事情经过以及分析过程如下，可供学习。
操作过程
运维人员在优化慢查询时针对性创建了一个索引，语句如下：
db.c1.createIndex('name':1,background:true)
随后又将表上一个没能用上的索引删除，语句如下：
db.c1.dropIndex('idx_age')
在主节点上很顺利的就完成了，但是不久后就发现从节点发生了 Crash，日志中包含下列崩溃信息。
2023-04-13T07:00:50.752+0000 E STORAGE [conn3569849] WiredTiger error (-31802) [1681369250:752455][9937:0x7fe740144700], WT_CONNECTION.open_session: __open_session, 2058: out of sessions, configured for 20030 (including internal sessions): WT_ERROR: non-specific WiredTiger error Raw: [1681369250:752455][9937:0x7fe740144700], WT_CONNECTION.open_session: __open_session, 2058: out of sessions, configured for 20030 (including internal sessions): WT_ERROR: non-specific WiredTiger error
2023-04-13T07:00:50.752+0000 I NETWORK [listener] connection accepted from xxx.xxx.xxx.xxx #3570023 (20576 connections now open)
2023-04-13T07:00:50.753+0000 F - [conn3569849] Invariant failure: conn->open_session(conn, NULL, "isolation=snapshot", &_session) resulted in status UnknownError: -31802: WT_ERROR: non-specific WiredTiger error at src/mongo/db/storage/wiredtiger/wiredtiger_session_cache.cpp 111
其它信息
- 变更表是一张几千万的大表；
- 数据库架构为 MongoDB 4.0.14 的 PSA 架构；
- 应用开启了读写分离，从节点也存在大量只读请求。
问题分析
根据日志信息，初步怀疑是连接打满了，检查最大连接数配置。
初步排查
shard1:PRIMARY> db.serverStatus().connections;
{ "current" : 7, "available" : 29993, "totalCreated" : 7, "active" : 2 }
最大连接数是由 maxIncomingConnections 参数和 ulimit 决定的。
net:
maxIncomingConnections: 30000
在测试环境模拟连接数打满的情况，发现在连接数满了的情况下实例只会拒绝新的连接，而非直接 Crash。
connecting to: mongodb://10.186.64.88:27017/admin?gssapiServiceName=mongodb
2023-04-19T13:59:26.578+0000 I NETWORK [js] DBClientConnection failed to receive message from 10.186.64.88:27017 - HostUnreachable: Connection closed by peer
2023-04-19T13:59:26.579+0000 E QUERY [js] Error: network error while attempting to run command 'isMaster' on host '10.186.64.88:27017' :
connect@src/mongo/shell/mongo.js:344:17
@(connect):2:6
exception: connect failed
根据 SERVER-30462 描述怀疑是 WT_SESSION 打满的情况。
WT_SESSION 是 MongoDB Server 和 WiredTiger 存储引擎内部交互使用的会话，几乎所有操作都是在 WT_SESSION 的上下文中执行的。因此 WT_SESSION 在超过限制后将会触发较为严重的情况。
![]()
源码分析
在源码 mongo/wiredtiger_kv_engine.cpp 中可以看到 WT_SESSION 硬编码指定为 20000。
std::stringstream ss;
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 的报错。
/* Find the first inactive session slot. */
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, "out of sessions, configured for %" PRIu32
" (including "
"internal sessions)",
conn->session_size);
提出疑问
分析到这开始疑惑 WT_SESSION 打满与索引操作存在什么样的关系？为什么相同的操作在主节点可以正常完成，而从节点会发生 Crash？
在创建索引时指定 background:true 可以在后台构建索引，不会加锁阻塞集合上的其它操作，这也是我们日常添加索引常用的方式。
但在删除索引时，我们有一点需要注意，但又常常被忽略，在主节点删除索引后同步到从节点回放时，如果从节点正在跑同一个集合上后台创建索引的操作，那么删除索引的操作将会被阻塞，更严重的是这时候实例上所有 namespace 的访问都将会被阻塞。针对这一现象在官网 dropIndex 文档中有提及：
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-13T05:34:27.002+0000 I - [repl index builder 178] Index Build (background): 122873800/640018757 19%
2023-04-13T05:34:30.002+0000 I - [repl index builder 178] Index Build (background): 122976300/640018769 19%
2023-04-13T05:34:30.434+0000 I COMMAND [repl writer worker 11] CMD: dropIndexes test.c1
初步结论
到此，我们得出初步结论。事情起因是主节点在同一个集合上执行创建索引和删除索引后，在从节点回放时出现了很严重的阻塞，大量的只读请求开始不断积压，最后导致 WT_SESSION 消耗殆尽，Server 无法与 WiredTiger 进行内部通信，最终导致实例 Crash。
问题复现
下面的案例在测试环境复现 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 -*-
import multiprocessing
import pymongo
def find():
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
while x<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()
错误日志如下，与生产日志相同。
![]()
总结
net.maxIncomingConnections 设置应小于 WT_SESSION；- 可以根据实际需求调整游标超时时间，避免出现大面积积压的情况；
- 避免创建索引和删除索引先后执行，特别是先执行后台创建索引的情况下；
- 4.2 版本中废弃了
background 选项，对索引创建过程进行了优化，只会在索引创建的开始和结束时持有 exclusive lock；并且 4.0 版本官方已经停止提供服务了，建议尽快升级。
本文关键字：#MongoDB# #WiredTiger# #源码#
关于 SQLE
爱可生开源社区的 SQLE 是一款面向数据库使用者和管理者，支持多场景审核，支持标准化上线流程，原生支持 MySQL 审核且数据库类型可扩展的 SQL 审核工具。
SQLE 获取
