MongoDB 實例 Crash 的故障現(xiàn)象問題

1故障現(xiàn)象

近日，朋友遇到一個 MongoDB 實例 Crash 的問題，找到我?guī)兔σ黄鸱治鲈颍虑榻?jīng)過以及分析過程如下，可供學(xué)習(xí)。

操作過程

運維人員在優(yōu)化慢查詢時針對性創(chuàng)建了一個索引，語句如下：

db.c1.createIndex('name':1,background:true)

隨后又將表上一個沒能用上的索引刪除，語句如下：

db.c1.dropIndex('idx_age')

在主節(jié)點上很順利的就完成了，但是不久后就發(fā)現(xiàn)從節(jié)點發(fā)生了 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

其它信息

變更表是一張幾千萬的大表；

數(shù)據(jù)庫架構(gòu)為 MongoDB 4.0.14 的 PSA 架構(gòu)；

應(yīng)用開啟了讀寫分離，從節(jié)點也存在大量只讀請求。

2問題分析

根據(jù)日志信息，初步懷疑是連接打滿了，檢查最大連接數(shù)配置。

初步排查

shard1:PRIMARY>db.serverStatus().connections;
{"current":7,"available":29993,"totalCreated":7,"active":2}

最大連接數(shù)是由 maxIncomingConnections 參數(shù)和 ulimit 決定的。

net:
maxIncomingConnections:30000

在測試環(huán)境模擬連接數(shù)打滿的情況，發(fā)現(xiàn)在連接數(shù)滿了的情況下實例只會拒絕新的連接，而非直接 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

根據(jù) SERVER-30462 描述懷疑是 WT_SESSION[1] 打滿的情況。

WT_SESSION 是 MongoDB Server 和 WiredTiger[2] 存儲引擎內(nèi)部交互使用的會話，幾乎所有操作都是在 WT_SESSION 的上下文中執(zhí)行的。因此 WT_SESSION 在超過限制后將會觸發(fā)較為嚴重的情況。

源碼分析

在源碼 mongo/wiredtiger_kv_engine.cpp[3] 中可以看到 WT_SESSION 硬編碼指定為 20000。

std::stringstreamss;
ss<

	

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

	

	如果 WT_SESSION 數(shù)量超過 20000，將會觸發(fā) 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 打滿與索引操作存在什么樣的關(guān)系？為什么相同的操作在主節(jié)點可以正常完成，而從節(jié)點會發(fā)生 Crash？

	在創(chuàng)建索引時指定 background:true 可以在后臺構(gòu)建索引，不會加鎖阻塞集合上的其它操作，這也是我們?nèi)粘Ｌ砑铀饕Ｓ玫姆绞健?/p>

	但在刪除索引時，我們有一點需要注意，但又常常被忽略，在主節(jié)點刪除索引后同步到從節(jié)點回放時，如果從節(jié)點正在跑同一個集合上后臺創(chuàng)建索引的操作，那么刪除索引的操作將會被阻塞，更嚴重的是這時候?qū)嵗纤?namespace 的訪問都將會阻塞。針對這一現(xiàn)象在官網(wǎng) 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.

	當(dāng)任何創(chuàng)建索引操作復(fù)制到 Secondary 時，應(yīng)避免在集合上刪除索引。如果你試圖在 Primary 上刪除一個索引，而該集合在 Secondary 上有一個索引正在后臺創(chuàng)建，那么所有 namespace 的訪問將被停止，復(fù)制也會停止，直到后臺索引建立完成。

	回到錯誤日志中查找更多內(nèi)容，就能發(fā)現(xiàn)從節(jié)點在后臺創(chuàng)建索引時，又執(zhí)行了同一個集合上的刪除索引操作。

	
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


	

	初步結(jié)論

	到此，我們得出初步結(jié)論。事情起因是主節(jié)點在同一個集合上執(zhí)行創(chuàng)建索引和刪除索引后，在從節(jié)點回放時出現(xiàn)了很嚴重的阻塞，大量的只讀請求開始不斷積壓，最后導(dǎo)致 WT_SESSION 消耗殆盡，Server 無法與 WiredTiger 進行內(nèi)部通信，最終導(dǎo)致實例 Crash。

	3問題復(fù)現(xiàn)

	下面的案例在測試環(huán)境復(fù)現(xiàn) WT_SESSION 超過限制的情況，dropIndex 導(dǎo)致從節(jié)點鎖阻塞的問題有興趣可自己測試復(fù)現(xiàn)，這里就不做演示了。

	WT_SESSION 上限是由 wiredtiger_open 配置中的 session_max 決定的，但 MongoDB 并未直接暴露 session_max的配置方式，只能通過下列方式進行覆蓋設(shè)置。

	
mongod-f/etc/mongod.conf--wiredTigerEngineConfigString="session_max=5"


	

	然后在數(shù)據(jù)庫內(nèi)部發(fā)起一個全局排它鎖。

	
mongo>db.fsyncLock()


	

	編寫下列 Python 腳本模擬并發(fā)線程。

	
#!/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 引擎層，但一旦我們手動釋放排它鎖，所有請求都會在短時間內(nèi)進入 WiredTiger 引擎，WT_SESSION 瞬間超過限制，實例緊接著發(fā)生 Crash。

	
mongo>db.fsyncUnlock()


	

	錯誤日志如下，與生產(chǎn)日志相同。

	

	4總結(jié)

	net.maxIncomingConnections 設(shè)置應(yīng)小于 WT_SESSION；

	可以根據(jù)實際需求調(diào)整游標(biāo)超時時間，避免出現(xiàn)大面積積壓的情況；

	避免創(chuàng)建索引和刪除索引先后執(zhí)行，特別是先執(zhí)行后臺創(chuàng)建索引的情況下；

	4.2 版本中廢棄了 background 選項，對索引創(chuàng)建過程進行了優(yōu)化，只會在索引創(chuàng)建的開始和結(jié)束時持有 exclusive lock；并且 4.0 版本官方已經(jīng)停止提供服務(wù)了，建議盡快升級。