摘要：本文詳細闡述了根據引起 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# #源碼#