深入解析 MongoDB Plan Cache

Pluser 發(fā)布于2019-06-26 17:42 / 1150人閱讀

摘要：所以在掃描次后，率先到達狀態(tài)，那么此刻將停止掃描，進入到算分的階段。除了這條引發(fā)故障的之外，其他的字段命中索引數(shù)量都非常小，有的甚至只有一條。那這里很明顯在中只去根據(jù)中執(zhí)行計劃的相關(guān)索引來進行判斷是不合理的。

前段時間筆者遇到一個MongoBD Plan Cache的bug，于是深究了下MongoDB優(yōu)化器相關(guān)源碼。在這里分享給大家，一方面讓大家知道MongoDB優(yōu)化器工作原理，一方面就是避免踩坑。
首先帖一下筆者反饋給官方的bug地址：https://jira.mongodb.org/brow...
注意目前官方仍在修復(fù)中，最新動態(tài)可參考：https://jira.mongodb.org/brow...
接下來我們就進入正題，本文分為以下4個章節(jié)：

背景

MongoDB生成執(zhí)行計劃是如何選擇索引的
2.1. 過濾符合條件的索引
2.2. 選擇合適的索引

MongoDB Plan Cache機制

遇到該Bug如何處理

附錄

1、背景

在2月26號下午2點37的時候，我們線上MongoDB性能出現(xiàn)拐點，開始出現(xiàn)大量的慢查，最終造成MongoDB異常夯住，最后通過重啟MongoDB故障恢復(fù)。

首先我們知道是由于同類型的SQL突然改變執(zhí)行計劃選擇了其他的索引，造成后續(xù)的SQL直接采用Cache中的執(zhí)行計劃全部成為慢查。那這里我們歸納為2個主要問題：

- MongoDB生成執(zhí)行計劃是如何選擇索引的？

- MongoDB決定是否采用cache中的執(zhí)行計劃的條件是什么？

在有多個執(zhí)行計劃可選擇的時候，MongoDB會選擇一個最優(yōu)的執(zhí)行計劃存放在cache中，MongoDB對同一類型的SQL（SQL基本一樣，只有過濾條件具體的value不一樣）會直接從cache中拿出執(zhí)行計劃，但是在采用cache之前也會進行判斷是否繼續(xù)采用cache中的執(zhí)行計劃。

那搞清楚上述兩個問題之后，我們再結(jié)合我們線上的問題場景進行分析就可以得出最終的結(jié)論。

2. MongoDB生成執(zhí)行計劃是如何選擇索引的 2.1. 過濾符合條件的索引

MongoDB會根據(jù)謂詞條件也就是過濾條件來過濾合適的索引，比如以下SQL：

db.files.find({"operation.sha1Code":"acca33867df96b97a05bdbd81f2aee13a50zbdba","operation.is_prefix":true,"operation.des_url":"sh/"})

它會選擇帶有operation.sha1Code、operation.is_prefix、operation.des_url字段的索引，不管是單個索引還是復(fù)合索引，所以在實際生產(chǎn)環(huán)境中選擇了如下索引：

  {
  "v" : 1,
  "key" : {
  "operation.is_prefix" : 1
  },
  "name" : "operation.is_prefix_1",
  "ns" : "fs.files",
  "background" : true
  },
  {
  "v" : 1,
  "key" : {
  "operation.des_url" : 1
  },
  "name" : "operation.des_url_1",
  "ns" : "fs.files",
  "background" : true
  },
  {
  "v" : 1,
  "key" : {
  "operation.sha1Code" : 1
  },
  "name" : "operation.sha1Code_1",
  "ns" : "fs.files",
  "background" : true
  }

但是上述索引誰最合適呢？

2.2. 選擇合適的索引

前面我們提到了MongoDB會根據(jù)謂詞條件選擇多個索引，但是最終執(zhí)行計劃會選擇一個索引，那MongoDB是怎么判斷哪個索引能更快的得出該SQL的結(jié)果呢？

在MongoDB中，每個索引對應(yīng)一種執(zhí)行計劃，在MongoDB中叫解決方案，在選擇執(zhí)行計劃的時候每個執(zhí)行計劃都會掃描A次，這里的A次計算公式如下：

numWorks = std::max(static_cast(internalQueryPlanEvaluationWorks),
                            static_cast(fraction * collection->numRecords(txn)));

internalQueryPlanEvaluationWorks=10000
fraction=0.29
collection->numRecords(txn) 則為collection的總記錄數(shù)

那就是collection的總記錄數(shù)*0.29如果比10000小就掃描10000次，如果比10000大那么就掃描collection數(shù)量*0.29次。

那在每個執(zhí)行計劃掃描A次之后，MongoDB是如何選出最優(yōu)的執(zhí)行計劃呢？

這里MongoDB有個計算score的公式：

    double baseScore = 1;
    size_t workUnits = stats->common.works;
    double productivity =
        static_cast(stats->common.advanced) / static_cast(workUnits);
    const double epsilon = std::min(1.0 / static_cast(10 * workUnits), 1e-4);

    double noFetchBonus = epsilon;
    if (hasStage(STAGE_PROJECTION, stats) && hasStage(STAGE_FETCH, stats)) {
        noFetchBonus = 0;
    }

    double noSortBonus = epsilon;
    if (hasStage(STAGE_SORT, stats)) {
        noSortBonus = 0;
    }

    double noIxisectBonus = epsilon;
    if (hasStage(STAGE_AND_HASH, stats) || hasStage(STAGE_AND_SORTED, stats)) {
        noIxisectBonus = 0;
    }
    double tieBreakers = noFetchBonus + noSortBonus + noIxisectBonus;
    double score = baseScore + productivity + tieBreakers;

我們可以看到總的score是由baseScore+productivity+productivity構(gòu)成的：

首先我們看看baseScore最開始賦值為1，后面再沒有改變過，這里就不說了。

然后我們看看productivity的計算公式：

    double productivity =
        static_cast(stats->common.advanced) / static_cast(workUnits);

這里的common.advanced是每個索引掃描的時候是否能在collection拿到符合條件的記錄，如果能拿到記錄那么common.advanced就加1，workUnits則是總共掃描的次數(shù)

這里所有的執(zhí)行計劃掃描的次數(shù)都是一樣的，所以common.advanced多的肯定productivity就大，MongoDB這樣做主要是想選擇能快速拿到SQL結(jié)果的索引。

然后我們再看tieBreakers，它是由noFetchBonus和noSortBonus和noIxisectBonus總和構(gòu)成的。我們根據(jù)上述代碼可以看到這三個值主要是控制MongoDB不要選擇如下狀態(tài)的：

STAGE_PROJECTION&&STAGE_FETCH（限定返回字段）
STAGE_SORT（避免排序）
STAGE_AND_HASH || STAGE_AND_SORTED（這個主要在交叉索引時產(chǎn)生）

它們的出現(xiàn)都比較影響性能，所以一旦它們出現(xiàn)，相應(yīng)的值都會被設(shè)置成0.

這里的noFetchBonus和noSortBonus和noIxisectBonus的初始值都是epsilon，那么看看epsilon的計算公式：

   const double epsilon = std::min(1.0 / static_cast(10 * workUnits), 1e-4);

這里workUnits就是每個索引的掃描次數(shù)，那么這里的意思就是取1.0 / static_cast(10 * workUnits)和1e-4中最小的值。

通過上述的計算score的公式，MongoDB就可以選擇一個最優(yōu)的執(zhí)行計劃，那這里還有一個起著決定性作用的一個狀態(tài)，就是IS_EOF。

在MongoDB掃描A次的時候，如果某個索引的命中數(shù)量小于A次，那它必然會提前掃描完，然后標(biāo)志位狀態(tài)為IS_EOF，這個時候MongoDB就會停止掃描，直接進入到計算score階段，為什么要停止？

在我們執(zhí)行SQL的時候，選擇的索引針對于它的過濾條件是不是命中次數(shù)越少越好呀？這樣我們最后掃描的collection記錄是不是越少，這樣總體執(zhí)行時間就會越小。

所以在MongoDB計算score的時候，除了上述公式，還有以下條件：

        if (statTrees[i]->common.isEOF) {
            LOG(5) << "Adding +" << eofBonus << " EOF bonus to score." << endl;
            score += 1;
        }

如果狀態(tài)為IS_EOF則加一分，所以一般達到IS_EOF狀態(tài)的索引都會被選中為最優(yōu)執(zhí)行計劃。

OK，說了這么多原理，我們以實際的生產(chǎn)SQL為例簡單參照公式計算下，我們就以出問題的那個SQL來計算：

db.files.find({"operation.sha1Code":"acca33867df96b97a05bdbd81f2aee13a50zbdba","operation.is_prefix":true,"operation.des_url":"sh/"})

首先MongoDB會選擇operation.sha1Code、operation.is_prefix、operation.des_url這三個字段的索引，然后掃描A次。OK，我們來計算一下A次是多少：

numWorks = std::max(static_cast(internalQueryPlanEvaluationWorks),
                            static_cast(fraction * collection->numRecords(txn)));

首先看看 0.29*collection總記錄數(shù)量：

comos_temp:SECONDARY> db.files.find().count()
551033614

也就是551033614*0.29=159799748

那么A=159799748

然后我們再看看每個索引的命中數(shù)量：

comos_temp:SECONDARY> db.files.find({"operation.sha1Code":"acca33867df96b97a05bdbd81f2aee13a50zbdba"}).count()
539408
comos_temp:SECONDARY> db.files.find({"operation.is_prefix":true}).count()
463885621
comos_temp:SECONDARY> db.files.find({"operation.des_url":"sh/"}).count()
180999

這里我們很明顯的看到operation.des_url字段的索引命中數(shù)量最小，只有180999，而且比A要小。所以在掃描180999次后，operation.des_url率先到達IS_EOF狀態(tài)，那么此刻將停止掃描，進入到算分的階段。

這里計算score我就不一一計算了，因為這里很明顯最后會選擇operation.des_url字段的索引，因為它率先達到了IS_EOF狀態(tài)，說明它需要掃描的記錄數(shù)量是最小的，最后的score的分值也是最高的，感興趣的朋友可以計算下。

所以在線上我們看到這個問題SQL選擇了operation.des_url字段的索引而不是像之前選擇的operation.sha1Code字段的索引，這個時候我們就以為是MongoDB選錯索引了，其實在這個SQL中，MongoDB并沒有選錯索引，它選的很正確。

3、MongoDB Plan Cache機制

上面我們提到了MongoDB是如何選擇索引最后生成最優(yōu)的執(zhí)行計劃，那MongoDB會將最優(yōu)的執(zhí)行計劃緩存到cache中，等待下次同樣的SQL執(zhí)行的時候會采用cache中的執(zhí)行計劃，但是在MongoDB中，它并不是直接就采用了cache中的計劃，而是有一些條件去判斷，下面我們來看看MongoDB是如何判斷的？

在CachedPlanStage::pickBestPlan方法中，MongoDB會決定該SQL是繼續(xù)采用cache中的執(zhí)行計劃，還是需要重新生成執(zhí)行計劃。

CachedPlanStage::pickBestPlan主要邏輯如下：

1、以Cache中執(zhí)行計劃的索引命中數(shù)量（works）*10=需要掃描的數(shù)量（B次）
2、繼續(xù)用該索引掃描B次,掃描的過程中有如下幾種情況：

- 索引每次掃描出來會去掃描collection，collection根據(jù)篩選條件如果能拿到記錄，則返回advanced，如果返回的advanced累積次數(shù)超過101次，則繼續(xù)用該執(zhí)行計劃。
- 索引掃描該字段的命中數(shù)量少于B次，則最終肯定會達到IS_EOF狀態(tài)，這個時候還是繼續(xù)用緩存中的執(zhí)行計劃。
- 如果掃描完了B次，但是發(fā)現(xiàn)返回advanced累積次數(shù)沒有達到101次，則會重新生成執(zhí)行計劃
- 如果在掃描過程遇見錯誤，則會返回FAILURE，也會觸發(fā)重新生成執(zhí)行計劃

OK，那我們來以實際故障舉一個例子：

我們知道故障那一天從2月26號下午14點37分那條SQL重新生成執(zhí)行計劃后，就采用operation.des_url字段索引而不是采用之前的operation.sha1Code。并且后面的類似的SQL都是采用operation.des_url字段索引，這樣導(dǎo)致大量的慢查。那這里我們可以看到后續(xù)的SQL其實都是直接采用cache中的執(zhí)行計劃，而沒有重新生成執(zhí)行計劃。那為什么繼續(xù)采用了cache中的執(zhí)行計劃呢？

我們實際看幾條SQL（直接選用當(dāng)時故障時候的慢查SQL）：

SQL1：

2018-02-26T14:39:11.049+0800 I COMMAND  [conn3959231] command fs.files command: find { find: "files", filter: { operation.sha1Code: "e635838088b717ccfba83586375711c0a49zbdba", operation.is_prefix: true, operation.des_url: "astro/" }, limit: 1, singleBatch: true } planSummary: IXSCAN { operation.des_url: 1.0 } keysExamined:21366 docsExamined:21366 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1146 nreturned:1 reslen:768 locks:{ Global: { acquireCount: { r: 2294 }, acquireWaitCount: { r: 1135 }, timeAcquiringMicros: { r: 21004892 } }, Database: { acquireCount: { r: 1147 } }, Collection: { acquireCount: { r: 1147 } } } protocol:op_query 50414ms

我們套用剛剛我們說的判斷是否采用cache的邏輯：
1、首先需要掃描上次索引命中次數(shù)10，那就是17014610=1701460
2、這里我們從日志中可以看到該條sql operation.des_url: "astro/"的命中數(shù)量只有21366條，所以它是不是還沒有掃描完1701460條就達到了IS_EOF狀態(tài)了？
3、如果達到IS_EOF狀態(tài)就直接采用cache中的執(zhí)行計劃。

那我們可能會猜想是不是真的就是這個執(zhí)行計劃最優(yōu)呢？我們上面已經(jīng)詳細說明了MongoDB是如何選擇索引，其實我們簡單的看看各個字段索引對應(yīng)的命中數(shù)量我們就知道那個索引最優(yōu)了。

comos_temp:SECONDARY> db.files.find({"operation.sha1Code": "e635838088b717ccfba83586375711c0a49zbdba"}).count()
1
comos_temp:SECONDARY> db.files.find({"operation.is_prefix":true}).count()
463885621
comos_temp:SECONDARY> db.files.find({"operation.des_url": "astro/"}).count()
23000（這里是現(xiàn)在的記錄，當(dāng)時是21366）

所以我們不用計算score是不是就能快速的得出結(jié)論，是不是采用operation.sha1Code字段的索引會更快一些，因為它只需要掃描1條記錄。

SQL2:

2018-02-26T14:40:08.200+0800 I COMMAND  [conn3935510] command fs.files command: find { find: "files", filter: { operation.sha1Code: "46cdc6924ad8fc298f2cac0b3e853698583zbdba", operation.is_prefix: true, operation.des_url: "hebei/" }, limit: 1, singleBatch: true } planSummary: IXSCAN { operation.des_url: 1.0 } keysExamined:80967 docsExamined:80967 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:2807 nreturned:0 reslen:114 locks:{ Global: { acquireCount: { r: 5616 }, acquireWaitCount: { r: 2712 }, timeAcquiringMicros: { r: 53894897 } }, Database: { acquireCount: { r: 2808 } }, Collection: { acquireCount: { r: 2808 } } } protocol:op_query 127659ms

我們套用剛剛我們說的判斷是否采用cache的邏輯：
1、首先需要掃描上次索引命中次數(shù)10，那就是17014610=1701460
2、這里我們從日志中可以看到該條sql operation.des_url: "hebei/"的命中數(shù)量只有80967條，所以它是不是還沒有掃描完1701460條就達到了IS_EOF狀態(tài)了？
3、如果達到IS_EOF狀態(tài)就直接采用cache中的執(zhí)行計劃。

comos_temp:SECONDARY> db.files.find({"operation.sha1Code": "46cdc6924ad8fc298f2cac0b3e853698583zbdba"}).count()
4
comos_temp:SECONDARY> db.files.find({"operation.is_prefix":true}).count()
463885621
comos_temp:SECONDARY> db.files.find({"operation.des_url": "hebei/"}).count()
85785（這里是現(xiàn)在的記錄，當(dāng)時是80967）

所以我們不用計算score是不是就能快速的得出結(jié)論，是不是采用operation.sha1Code字段的索引會更快一些，因為它只需要掃描4條記錄。

當(dāng)然可以繼續(xù)去找后面的慢查日志（當(dāng)然一定是重啟前的日志，重啟后MongoDB會重新生成執(zhí)行計劃，這也是我們?yōu)槭裁粗貑ongoDB之后故障就恢復(fù)了）都是這種情況，所以這就是為什么有大量慢查，最終導(dǎo)致MongoDB異常夯住。

那這里我們是不是可以得出，只要operation.des_url字段索引命中數(shù)量少于1701460條就會繼續(xù)采用operation.des_url字段索引，那這里其實就是MongoDB認為只要operation.des_url字段索引小于cache中該字段索引命中數(shù)量*10就認為這個索引是最優(yōu)的，但是之前cache中的最優(yōu)執(zhí)行計劃是建立在operation.sha1Code字段索引命中數(shù)量遠大于operation.des_url字段索引命中數(shù)量的基礎(chǔ)上。當(dāng)時那個引發(fā)故障的SQL各個字段索引命中數(shù)量如下：

comos_temp:SECONDARY> db.files.find({"operation.sha1Code":"acca33867df96b97a05bdbd81f2aee13a50zbdba"}).count()
539408
comos_temp:SECONDARY> db.files.find({"operation.is_prefix":true}).count()
463885621
comos_temp:SECONDARY> db.files.find({"operation.des_url":"sh/"}).count()
180999

但是我們知道，operation.sha1Code字段索引命中數(shù)量是會變化的，隨著具體的value不一樣，其命中數(shù)量也不會一樣。除了這條引發(fā)故障的SQL之外，其他SQL的operation.sha1Code字段命中索引數(shù)量都非常小，有的甚至只有一條。那這里很明顯MongoDB在cache中只去根據(jù)cache中執(zhí)行計劃的相關(guān)索引來進行判斷是不合理的。

當(dāng)然這里還有一部分原因就是本身我們的collection有5億條記錄，那這個也是放大這次故障的一個主要原因。

那這里我們是不是想到了后面只要出現(xiàn)這條SQL就會導(dǎo)致慢查最終導(dǎo)致故障？

是的，確實是會導(dǎo)致慢查，但是不一定會導(dǎo)致故障，因為早在2017年的時候該SQL就出現(xiàn)了好幾次。但是最終都自己恢復(fù)了，我們來看看是什么原因。

在2017-11-24T09:22:42的時候也執(zhí)行了該SQL，不同的是operation.des_url 是 "sd/",不過這并不影響，可以看到該sql出現(xiàn)，馬上改變執(zhí)行計劃，開始采用operation.des_url索引，然后后面都是一些慢查了。

2017-11-24T09:22:42.767+0800 I COMMAND  [conn3124017] command fs.files command: find { find: "files", filter: { operation.sha1Code: "acca33867df96b97a05bdbd81f2aee13a50zbdba", operation.is_prefix: true, operation.des_url: "sd/" }, limit: 1, singleBatch: true } planSummary: IXSCAN { operation.des_url: 1.0 } keysExamined:103934 docsExamined:103934 fromMultiPlanner:1 replanned:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:7923 nreturned:1 reslen:719 locks:{ Global: { acquireCount: { r: 15848 }, acquireWaitCount: { r: 860 }, timeAcquiringMicros: { r: 2941600 } }, Database: { acquireCount: { r: 7924 } }, Collection: { acquireCount: { r: 7924 } } } protocol:op_query 79379ms
2017-11-24T09:22:42.767+0800 I COMMAND  [conn3080461] command fs.files command: find { find: "files", filter: { operation.sha1Code: "acca33867df96b97a05bdbd81f2aee13a50zbdba", operation.is_prefix: true, operation.des_url: "sd/" }, limit: 1, singleBatch: true } planSummary: IXSCAN { operation.des_url: 1.0 } keysExamined:103934 docsExamined:103934 fromMultiPlanner:1 replanned:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:7781 nreturned:1 reslen:719 locks:{ Global: { acquireCount: { r: 15564 }, acquireWaitCount: { r: 671 }, timeAcquiringMicros: { r: 2370524 } }, Database: { acquireCount: { r: 7782 } }, Collection: { acquireCount: { r: 7782 } } } protocol:op_query 64711ms
2017-11-24T09:24:05.957+0800 I COMMAND  [conn3032629] command fs.files command: find { find: "files", filter: { operation.sha1Code: "3a85283ed90820d65174572f566026d8d1azbdba", operation.is_prefix: true, operation.des_url: "sinacn/" }, limit: 1, singleBatch: true } planSummary: IXSCAN { operation.sha1Code: 1.0 } keysExamined:0 docsExamined:0 fromMultiPlanner:1 replanned:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:8762 nreturned:0 reslen:114 locks:{ Global: { acquireCount: { r: 17526 }, acquireWaitCount: { r: 1000 }, timeAcquiringMicros: { r: 16267930 } }, Database: { acquireCount: { r: 8763 } }, Collection: { acquireCount: { r: 8763 } } } protocol:op_query 70696ms
2017-11-24T09:24:05.963+0800 I COMMAND  [conn3038640] command fs.files command: find { find: "files", filter: { operation.sha1Code: "e84012269998d1f076f3d93cde43b1726fezbdba", operation.is_prefix: true, operation.des_url: "sinacn/" }, limit: 1, singleBatch: true } planSummary: IXSCAN { operation.sha1Code: 1.0 } keysExamined:0 docsExamined:0 fromMultiPlanner:1 replanned:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:8666 nreturned:0 reslen:114 locks:{ Global: { acquireCount: { r: 17334 }, acquireWaitCount: { r: 864 }, timeAcquiringMicros: { r: 14671764 } }, Database: { acquireCount: { r: 8667 } }, Collection: { acquireCount: { r: 8667 } } } protocol:op_query 58881ms
2017-11-24T09:24:06.006+0800 I COMMAND  [conn3033497] command fs.files command: find { find: "files", filter: { operation.sha1Code: "19576f5a3b1ad0406080e15a4513d17badbzbdba", operation.is_prefix: true, operation.des_url: "sinacn/" }, limit: 1, singleBatch: true } planSummary: IXSCAN { operation.sha1Code: 1.0 } keysExamined:0 docsExamined:0 fromMultiPlanner:1 replanned:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:8806 nreturned:0 reslen:114 locks:{ Global: { acquireCount: { r: 17614 }, acquireWaitCount: { r: 1054 }, timeAcquiringMicros: { r: 16842848 } }, Database: { acquireCount: { r: 8807 } }, Collection: { acquireCount: { r: 8807 } } } protocol:op_query 75916ms
2017-11-24T09:24:06.006+0800 I COMMAND  [conn3065049] command fs.files command: find { find: "files", filter: { operation.sha1Code: "6e267e339f19f537aca8d6388974a8c3429zbdba", operation.is_prefix: true, operation.des_url: "sinacn/" }, limit: 1, singleBatch: true } planSummary: IXSCAN { operation.sha1Code: 1.0 } keysExamined:1 docsExamined:1 fromMultiPlanner:1 replanned:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:8620 nreturned:1 reslen:651 locks:{ Global: { acquireCount: { r: 17242 }, acquireWaitCount: { r: 676 }, timeAcquiringMicros: { r: 11482889 } }, Database: { acquireCount: { r: 8621 } }, Collection: { acquireCount: { r: 8621 } } } protocol:op_query 48621ms
2017-11-24T09:24:06.014+0800 I COMMAND  [conn3127183] command fs.files command: find { find: "files", filter: { operation.sha1Code: "2c06710b75d4b4c92c0cdffb5350659bb74zbdba", operation.is_prefix: true, operation.des_url: "sinacn/" }, limit: 1, singleBatch: true } planSummary: IXSCAN { operation.sha1Code: 1.0 } keysExamined:0 docsExamined:0 fromMultiPlanner:1 replanned:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:8412 nreturned:0 reslen:114 locks:{ Global: { acquireCount: { r: 16826 }, acquireWaitCount: { r: 510 }, timeAcquiringMicros: { r: 10260087 } }, Database: { acquireCount: { r: 8413 } }, Collection: { acquireCount: { r: 8413 } } } protocol:op_query 37187ms
2017-11-24T09:27:38.725+0800 I COMMAND  [conn3032706] command fs.files command: find { find: "files", filter: { operation.sha1Code: "acca33867df96b97a05bdbd81f2aee13a50zbdba", operation.is_prefix: true, operation.des_url: "sd/" }, limit: 1, singleBatch: true } planSummary: IXSCAN { operation.des_url: 1.0 } keysExamined:103934 docsExamined:103934 fromMultiPlanner:1 replanned:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:4886 nreturned:1 reslen:719 locks:{ Global: { acquireCount: { r: 9774 }, acquireWaitCount: { r: 316 }, timeAcquiringMicros: { r: 471809 } }, Database: { acquireCount: { r: 4887 } }, Collection: { acquireCount: { r: 4887 } } } protocol:op_query 24573ms
2017-11-24T09:28:02.643+0800 I COMMAND  [conn3062092] command fs.files command: find { find: "files", filter: { operation.sha1Code: "0a7dab951084d5a88a1ca736319998237fazbdba", operation.is_prefix: true, operation.des_url: "sinacn/" }, limit: 1, singleBatch: true } planSummary: IXSCAN { operation.sha1Code: 1.0 } keysExamined:0 docsExamined:0 fromMultiPlanner:1 replanned:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:8126 nreturned:0 reslen:114 locks:{ Global: { acquireCount: { r: 16254 }, acquireWaitCount: { r: 68 }, timeAcquiringMicros: { r: 819435 } }, Database: { acquireCount: { r: 8127 } }, Collection: { acquireCount: { r: 8127 } } } protocol:op_query 12645ms

但是在2017-11-24T09:28:02的時候，該SQL重新生成執(zhí)行計劃，然后重新選擇operation.sha1Code: 1.0索引，更新cache中執(zhí)行計劃，然后后續(xù)類似SQL都走operation.sha1Code: 1.0索引，這樣MongoDB又恢復(fù)了正常，相關(guān)日志如下：

19564934:2017-11-24T09:28:02.643+0800 I COMMAND  [conn3062092] command fs.files command: find { find: "files", filter: { operation.sha1Code: "0a7dab951084d5a88a1ca736319998237fazbdba", operation.is_prefix: true, operation.des_url: "sinacn/" }, limit: 1, singleBatch: true } planSummary: IXSCAN { operation.sha1Code: 1.0 } keysExamined:0 docsExamined:0 fromMultiPlanner:1 replanned:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:8126 nreturned:0 reslen:114 locks:{ Global: { acquireCount: { r: 16254 }, acquireWaitCount: { r: 68 }, timeAcquiringMicros: { r: 819435 } }, Database: { acquireCount: { r: 8127 } }, Collection: { acquireCount: { r: 8127 } } } protocol:op_query 12645ms

那我們看看它為什么可以觸發(fā)重新生成執(zhí)行計劃呢，而不采用cache中的執(zhí)行計劃。首先我們看最開始重新生成執(zhí)行計劃選擇operation.des_url索引的SQL，operation.des_url字段索引的命中次數(shù)是103934，也就是說后續(xù)的SQL在判斷是否采用cache中的執(zhí)行計劃時需要掃描103934*10次，如果沒有超過101次Advanced狀態(tài)（也是通過索引在collection中拿到滿足條件的記錄則返回Advanced累積次數(shù)），那么則放棄cache中的執(zhí)行計劃并且重新生成執(zhí)行計劃。我們看看上面這條SQL的operation.des_url: "sinacn/"字段索引命中記錄數(shù)是多少？

comos_temp:SECONDARY> db.files.find({"operation.des_url":"sinacn/"}).count()
147195372

OK，我們再看這個SQL的nreturned是0，說明符合查詢條件的記錄是0，那及時全部掃描完成10393410也達不到101次Advanced，別忘了我們還有一個條件，觸發(fā)IS_EOF就會直接采用cache中的執(zhí)行計劃，但是"operation.des_url":"sinacn/"的記錄數(shù)量遠遠大于10393410，所以也不可能達到IS_EOF的狀態(tài)。

那么此時該SQL在掃描完103934*10次后就會觸發(fā)重新生成執(zhí)行計劃。

這里是不是就明白為什么之前的故障自動恢復(fù)了，因為它出現(xiàn)了一個operation.des_url字段索引遠大于cache執(zhí)行計劃中索引字段命中次數(shù)*10。而且也達不到101次advanced，所以只能重新生成執(zhí)行計劃。當(dāng)然大家可以在看看2017年之前的日志，都是這種情況。

4、遇到該Bug如何處理

我們通過上述分析得出該次故障確實是由于MongoDB自身執(zhí)行計劃cache機制導(dǎo)致，那我們有什么應(yīng)對方案呢？

1、重啟實例
這個是最粗暴的方式，針對于MongoDB異常夯住不能登錄的情況
2、清理cache中的執(zhí)行計劃

- 列出cache中保存的SQL過濾條件

db.files.getPlanCache().listQueryShapes()

comos_temp:SECONDARY> db.files.getPlanCache().listQueryShapes()
[
    {
        "query" : {
            "operation.sha1Code" : "acca33867df96b97a05bdbd81f2aee13a50zbdba",
            "operation.is_prefix" : true,
            "operation.des_url" : "sh/"
        },
        "sort" : {
            
        },
        "projection" : {
            
        }
    }
]

- 根據(jù)該條件查看cache中的執(zhí)行計劃

db.files.getPlanCache().getPlansByQuery({"operation.sha1Code":"acca33867df96b97a05bdbd81f2aee13a50zbdba","operation.is_prefix":true,"operation.des_url":"sh/"})

- 清理該cache中的執(zhí)行計劃

db.files.getPlanCache().clear()

當(dāng)然我們在緊急的情況下直接執(zhí)行第三條命令即可。

3、反饋官方，優(yōu)化執(zhí)行計劃cache機制，進行MongoDB升級
https://jira.mongodb.org/brow...

5、附錄

最后筆者貼上MongoDB優(yōu)化器調(diào)用棧，方便擼源碼的同學(xué)快速上手

    mongod.exe!mongo::IndexScan::work(unsigned __int64 * out) 行 227    C++
    mongod.exe!mongo::FetchStage::work(unsigned __int64 * out) 行 91    C++
    mongod.exe!mongo::CachedPlanStage::pickBestPlan(mongo::PlanYieldPolicy * yieldPolicy) 行 95    C++
    mongod.exe!mongo::PlanExecutor::pickBestPlan(mongo::PlanExecutor::YieldPolicy policy) 行 206    C++
    mongod.exe!mongo::PlanExecutor::make(mongo::OperationContext * txn, std::unique_ptr > ws, std::unique_ptr > rt, std::unique_ptr > qs, std::unique_ptr > cq, const mongo::Collection * collection, const std::basic_string,std::allocator > & ns, mongo::PlanExecutor::YieldPolicy yieldPolicy) 行 143    C++
    mongod.exe!mongo::PlanExecutor::make(mongo::OperationContext * opCtx, std::unique_ptr > ws, std::unique_ptr > rt, std::unique_ptr > qs, std::unique_ptr > cq, const mongo::Collection * collection, mongo::PlanExecutor::YieldPolicy yieldPolicy) 行 127    C++
    mongod.exe!mongo::getExecutor(mongo::OperationContext * txn, mongo::Collection * collection, std::unique_ptr > canonicalQuery, mongo::PlanExecutor::YieldPolicy yieldPolicy, unsigned __int64 plannerOptions) 行 448    C++
    mongod.exe!mongo::getExecutorFind(mongo::OperationContext * txn, mongo::Collection * collection, const mongo::NamespaceString & nss, std::unique_ptr > canonicalQuery, mongo::PlanExecutor::YieldPolicy yieldPolicy) 行 582    C++
    mongod.exe!mongo::FindCmd::run(mongo::OperationContext * txn, const std::basic_string,std::allocator > & dbname, mongo::BSONObj & cmdObj, int options, std::basic_string,std::allocator > & errmsg, mongo::BSONObjBuilder & result) 行 278    C++
    mongod.exe!mongo::Command::run(mongo::OperationContext * txn, const mongo::rpc::RequestInterface & request, mongo::rpc::ReplyBuilderInterface * replyBuilder) 行 1468    C++
    mongod.exe!mongo::Command::execCommand(mongo::OperationContext * txn, mongo::Command * command, const mongo::rpc::RequestInterface & request, mongo::rpc::ReplyBuilderInterface * replyBuilder) 行 1336    C++
    mongod.exe!mongo::runCommands(mongo::OperationContext * txn, const mongo::rpc::RequestInterface & request, mongo::rpc::ReplyBuilderInterface * replyBuilder) 行 505    C++
    mongod.exe!mongo::`anonymous namespace"::receivedRpc(mongo::OperationContext * txn, mongo::Client & client, mongo::DbResponse & dbResponse, mongo::Message & message) 行 306    C++
    mongod.exe!mongo::assembleResponse(mongo::OperationContext * txn, mongo::Message & m, mongo::DbResponse & dbresponse, const mongo::HostAndPort & remote) 行 525    C++
    mongod.exe!mongo::`anonymous namespace"::MyMessageHandler::process(mongo::Message & m, mongo::AbstractMessagingPort * port) 行 180    C++
    mongod.exe!mongo::PortMessageServer::handleIncomingMsg(void * arg) 行 229    C++

GPU云服務(wù)器云服務(wù)器深入學(xué)習(xí)mongodb mongodb管理與開發(fā)實戰(zhàn)詳解深入云計算 mongodb管理與開發(fā)實戰(zhàn)詳解-深入云計算深入解析windows操作系統(tǒng)

文章版權(quán)歸作者所有，未經(jīng)允許請勿轉(zhuǎn)載,若此文章存在違規(guī)行為，您可以聯(lián)系管理員刪除。

轉(zhuǎn)載請注明本文地址：http://systransis.cn/yun/19283.html

發(fā)表評論

登陸后可評論

0條評論

Pluser

男|高級講師

我要關(guān)注我要私信

TA的文章

《JavaScript百煉成仙》統(tǒng)一回復(fù)粉絲們的一些問題

閱讀 1903·2021-11-15 11:39
搭載超高性能RSSD云盤的快杰云數(shù)據(jù)庫UDB重磅上線

閱讀 1117·2020-12-03 17:06
UCloud撬動?xùn)|南亞市場，占領(lǐng)競技手游“淘金地”

閱讀 765·2019-12-27 11:42
1像素下邊框引發(fā)移動端設(shè)備像素比的應(yīng)用

閱讀 3295·2019-08-30 13:59
JS手動實現(xiàn)柯里化(curry)函數(shù)

閱讀 1494·2019-08-26 13:22
遮罩層彈框頁面滾動

閱讀 3307·2019-08-26 12:15
js深度克隆的幾種方法

閱讀 2493·2019-08-26 10:22
調(diào)用攝像頭-截圖并保存圖像

閱讀 1589·2019-08-23 18:40

成人国产在线小视频_日韩寡妇人妻调教在线播放_色成人www永久在线观看_2018国产精品久久_亚洲欧美高清在线30p_亚洲少妇综合一区_黄色在线播放国产_亚洲另类技巧小说校园_国产主播xx日韩_a级毛片在线免费

資訊專欄INFORMATION COLUMN

上云采購季！| 2核2G4M爆款云服務(wù)器低至59元/年，更有多臺、長期優(yōu)惠，快來選購！

深入解析 MongoDB Plan Cache

相關(guān)文章

TiDB 源碼閱讀系列文章（二十三）Prepare/Execute 請求處理

TiDB 社區(qū)成長足跡與小紅花 | TiDB DevCon 2019

發(fā)表評論

0條評論

Pluser

男|高級講師

TA的文章

《JavaScript百煉成仙》統(tǒng)一回復(fù)粉絲們的一些問題

搭載超高性能RSSD云盤的快杰云數(shù)據(jù)庫UDB重磅上線

UCloud撬動?xùn)|南亞市場，占領(lǐng)競技手游“淘金地”

1像素下邊框引發(fā)移動端設(shè)備像素比的應(yīng)用

JS手動實現(xiàn)柯里化(curry)函數(shù)

遮罩層彈框頁面滾動

js深度克隆的幾種方法

調(diào)用攝像頭-截圖并保存圖像

最新活動

資訊專欄INFORMATION COLUMN

上云采購季！| 2核2G4M爆款云服務(wù)器低至59元/年，更有多臺、長期優(yōu)惠，快來選購！

深入解析 MongoDB Plan Cache

相關(guān)文章

發(fā)表評論

0條評論

男|高級講師

TA的文章

最新活動

上云采購季！| 2核2G4M爆款云服務(wù)器低至59元/年，更有多臺、長期優(yōu)惠，快來選購！