Secondary節(jié)點(diǎn)為何阻塞請(qǐng)求近一個(gè)小時(shí)？

lyhabc

看到Secondary節(jié)點(diǎn)上的日志，我的內(nèi)心的崩潰的，鑒權(quán)請(qǐng)求居然耗時(shí)2977790ms（約50分鐘），經(jīng)詳細(xì)統(tǒng)計(jì)，這個(gè)Secondary節(jié)點(diǎn)上，所有16:54之后發(fā)起的用戶請(qǐng)求，都阻塞到17:54左右才返回，處理時(shí)間最長的請(qǐng)求約1個(gè)小時(shí)。

2016-06-17T17:54:57.575+0800 I COMMAND  [conn2581] command admin.system.users command: saslStart { saslStart: 1, mechanism: "SCRAM-SHA-1", payload: "xxx" } keyUpdates:0 writeConflicts:0 numYields:0 reslen:171 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocolp_query 2977790ms
2016-06-17T17:54:57.575+0800 I COMMAND  [conn2740] command admin.system.users command: saslStart { saslStart: 1, mechanism: "SCRAM-SHA-1", payload: "xxx" } keyUpdates:0 writeConflicts:0 numYields:0 reslen:171 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocolp_query 2416390ms
經(jīng)過調(diào)查，引發(fā)備節(jié)點(diǎn)阻塞近1個(gè)小時(shí)主要是對(duì)一個(gè)很大的集合『后臺(tái)建立索引 + 刪除索引』2個(gè)動(dòng)作導(dǎo)致。

背景知識(shí)

Secondary從Primary拉取到一批oplog后，重放oplog的過程會(huì)加一把特殊的鎖，這個(gè)鎖會(huì)阻塞所有的reader，這么做的原因我個(gè)人理解是避免讓reader看到中間狀態(tài)，只有等一批oplog全部應(yīng)用成功才讓客戶端可讀，避免出現(xiàn)臟讀的問題。
建索引有前臺(tái)（foreground）和后臺(tái)（background）2種模式，前臺(tái)建索引會(huì)加在整個(gè)過程中對(duì)DB加互斥寫鎖，同一個(gè)DB下的讀寫操作均會(huì)阻塞至索引建立結(jié)束；后臺(tái)建索引只會(huì)對(duì)DB加意向?qū)戞i，對(duì)DB下的讀寫無影響。
Secondary重放建立索引的命令時(shí)，如果是前臺(tái)模式，則整個(gè)重放建索引的過程都會(huì)阻塞所有的reader；如果是后臺(tái)模式，重放時(shí)建索引的動(dòng)作會(huì)放到后臺(tái)線程里做，只會(huì)阻塞reader很短的時(shí)間。
為了盡量避免建索引影響業(yè)務(wù)，通常

在集合創(chuàng)建的時(shí)候，就建立好索引，此時(shí)因?yàn)榧�合為空，建索引的開銷很小。（以后每次寫入，同時(shí)會(huì)更新索引）
如果建索引時(shí)，集合內(nèi)已經(jīng)寫入了很多文檔，盡量使用后臺(tái)模式，避免『主節(jié)點(diǎn)上影響某個(gè)DB的所有讀寫』以及『備節(jié)點(diǎn)上影響所有的讀』。
問題分析

在我們遇到的問題里，創(chuàng)建索引使用的后臺(tái)模式，最終仍然導(dǎo)致Secondary阻塞讀reader近1個(gè)小時(shí)，接下來分析下問題產(chǎn)生的原因，主要事件的過程如下所示。

TIME        PRIMARY        SECONDARY
15:07:00        db.coll 開始后臺(tái)創(chuàng)建索引       
16:32:35        db.coll 創(chuàng)建索引結(jié)束        從oplog拉取到createIndex的操作，并開始重放
16:54:53        刪除db數(shù)據(jù)庫下某個(gè)索引        從oplog拉取到dropIndex的請(qǐng)求并開始重放，此時(shí)所有的請(qǐng)求開始阻塞
17:54:53                重放createIndex結(jié)束，開始應(yīng)答阻塞的請(qǐng)求
15:07:00 Primary上發(fā)起后臺(tái)建索引，創(chuàng)建索引的過程耗費(fèi)近1.5小時(shí)
16:32:25 創(chuàng)建索引完成，Primary上記錄oplog，Secondary拉取到oplog并重放該動(dòng)作，由于是后臺(tái)建索引，Secondary會(huì)啟動(dòng)一個(gè)單獨(dú)的線程來建索引，建索引的過程會(huì)對(duì)DB加意向鎖，所以重放動(dòng)作只會(huì)阻塞reader很短的時(shí)間（毫秒級(jí)別）。
16:54:53 用戶在同一個(gè)DB下發(fā)起了一個(gè)刪除索引的動(dòng)作，刪除動(dòng)作在主上很快結(jié)束，備拉取到oplog開始重放，刪除索引的動(dòng)作需要對(duì)DB加互斥鎖，而此時(shí)Secondary后臺(tái)建索引還在進(jìn)行中，已經(jīng)對(duì)DB加了意向鎖，導(dǎo)致這個(gè)互斥鎖需要等待后臺(tái)建索引結(jié)束，而重放oplog時(shí)，Secondary占用的特殊鎖會(huì)阻塞所有的reader，所以從這個(gè)時(shí)間點(diǎn)開始，所有的reader都阻塞等待了。
17:54:53 Secondary后臺(tái)建索引結(jié)束，刪除索引獲得互斥鎖并完成刪除動(dòng)作，重放結(jié)束，阻塞的reader加鎖成功并得到處理。
總結(jié)

上述問題主要因?yàn)镸ongoDB的設(shè)計(jì)機(jī)制導(dǎo)致，Secondary節(jié)點(diǎn)重放oplog時(shí)的鎖粒度太大，會(huì)阻塞所有的讀請(qǐng)求；但如果降低鎖粒度，就可能會(huì)出現(xiàn)臟讀的問題，這對(duì)于某些業(yè)務(wù)場(chǎng)景是不可接受的。目前來說，只要不把『耗時(shí)長并且需要同步到備節(jié)點(diǎn)』的操作放到業(yè)務(wù)邏輯里，影響是完全可以忽略的，如果實(shí)在無法避免，最終出現(xiàn)了Secondary長時(shí)間阻塞的情況，就直接使用默認(rèn)的readPreference，只從Primary上讀數(shù)據(jù)。

鎖粒度太大，不是document級(jí)別的鎖粒度，也不是collection級(jí)別的鎖粒度，而是DB級(jí)別的鎖粒度，并發(fā)很差
所以mongodb也是有很多坑的