MongoDB索引操作导致Crash

公众号新闻

2023-06-19 11:06

作者：徐耀荣

爱可生南区交付服务部 DBA 团队成员，主要负责 MySQL 故障处理以及相关技术支持。爱好电影，旅游。

爱可生开源社区出品

1故障现象

近日，朋友遇到一个 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 架构；
应用开启了读写分离，从节点也存在大量只读请求。

2问题分析

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

初步排查

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 xxx.xxx.xxx.xxx - 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^[1] 打满的情况。

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

源码分析

在源码 mongo/wiredtiger_kv_engine.cpp^[3] 中可以看到 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^[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-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。

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 -*-
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()

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

4总结

net.maxIncomingConnections 设置应小于 WT_SESSION；
可以根据实际需求调整游标超时时间，避免出现大面积积压的情况；
避免创建索引和删除索引先后执行，特别是先执行后台创建索引的情况下；
4.2 版本中废弃了 background 选项，对索引创建过程进行了优化，只会在索引创建的开始和结束时持有 exclusive lock；并且 4.0 版本官方已经停止提供服务了，建议尽快升级。