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<

	

	這一點也能在啟動日志中進一步得到驗證。

	

	如果 WT_SESSION 數量超過 20000，將會觸發 out of sessions 的報錯。

	
/*Findthefirstinactivesessionslot.*/
for(session_ret=conn->sessions,i=0;isession_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 版本官方已經停止提供服務了，建議盡快升級。