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;
可以根据实际需求调整游标超时时间,避免出现大面积积压的情况;
避免创建索引和删除索引先后执行,特别是先执行后台创建索引的情况下。
审核编辑:刘清
-
存储器
+关注
关注
38文章
7487浏览量
163808 -
python
+关注
关注
56文章
4795浏览量
84661 -
PSA
+关注
关注
0文章
50浏览量
13456 -
mongodb
+关注
关注
0文章
22浏览量
365
原文标题:MongoDB索引操作导致Crash
文章出处:【微信号:OSC开源社区,微信公众号:OSC开源社区】欢迎添加关注!文章转载请注明出处。
发布评论请先 登录
相关推荐
评论