1 故障現(xiàn)象

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

操作過程

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

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

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

db.c1.dropIndex('idx_age')

在主節(jié)點(diǎn)上很順利的就完成了，但是不久后就發(fā)現(xiàn)從節(jié)點(diǎn)發(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é)點(diǎn)也存在大量只讀請(qǐng)求。

2 問題分析

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

初步排查

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

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

net:
maxIncomingConnections:30000

在測(cè)試環(huán)境模擬連接數(shù)打滿的情況，發(fā)現(xiàn)在連接數(shù)滿了的情況下實(shí)例只會(huì)拒絕新的連接，而非直接 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] 存儲(chǔ)引擎內(nèi)部交互使用的會(huì)話，幾乎所有操作都是在 WT_SESSION 的上下文中執(zhí)行的。因此 WT_SESSION 在超過限制后將會(huì)觸發(fā)較為嚴(yán)重的情況。

源碼分析

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

std::stringstreamss;
ss<

	

	這一點(diǎn)也能在啟動(dòng)日志中進(jìn)一步得到驗(yàn)證。

	

	如果 WT_SESSION 數(shù)量超過 20000，將會(huì)觸發(fā) out of sessions 的報(bào)錯(cuò)。

	
/*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é)點(diǎn)可以正常完成，而從節(jié)點(diǎn)會(huì)發(fā)生 Crash？

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

	但在刪除索引時(shí)，我們有一點(diǎn)需要注意，但又常常被忽略，在主節(jié)點(diǎn)刪除索引后同步到從節(jié)點(diǎn)回放時(shí)，如果從節(jié)點(diǎn)正在跑同一個(gè)集合上后臺(tái)創(chuàng)建索引的操作，那么刪除索引的操作將會(huì)被阻塞，更嚴(yán)重的是這時(shí)候?qū)嵗纤?namespace 的訪問都將會(huì)阻塞。針對(duì)這一現(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 時(shí)，應(yīng)避免在集合上刪除索引。如果你試圖在 Primary 上刪除一個(gè)索引，而該集合在 Secondary 上有一個(gè)索引正在后臺(tái)創(chuàng)建，那么所有 namespace 的訪問將被停止，復(fù)制也會(huì)停止，直到后臺(tái)索引建立完成。

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

	
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é)點(diǎn)在同一個(gè)集合上執(zhí)行創(chuàng)建索引和刪除索引后，在從節(jié)點(diǎn)回放時(shí)出現(xiàn)了很嚴(yán)重的阻塞，大量的只讀請(qǐng)求開始不斷積壓，最后導(dǎo)致 WT_SESSION 消耗殆盡，Server 無法與 WiredTiger 進(jìn)行內(nèi)部通信，最終導(dǎo)致實(shí)例 Crash。

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

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

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

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


	

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

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


	

	這時(shí) MongoDB 實(shí)例還在正常運(yùn)行，因?yàn)槲覀兊恼?qǐng)求還沒有真正的進(jìn)入到 WiredTiger 引擎層，但一旦我們手動(dòng)釋放排它鎖，所有請(qǐng)求都會(huì)在短時(shí)間內(nèi)進(jìn)入 WiredTiger 引擎，WT_SESSION 瞬間超過限制，實(shí)例緊接著發(fā)生 Crash。

	
mongo>db.fsyncUnlock()


	

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

	

	4 總結(jié)

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

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

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





	

	

	審核編輯：劉清