深入解析 MongoDB Plan Cache

Pluser 發布于2019-06-26 17:42 / 1120人閱讀

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

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

背景

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

MongoDB Plan Cache機制

遇到該Bug如何處理

附錄

1、背景

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

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

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

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

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

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

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

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

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

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

  {
  "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會根據謂詞條件選擇多個索引，但是最終執行計劃會選擇一個索引，那MongoDB是怎么判斷哪個索引能更快的得出該SQL的結果呢？

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

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

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

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

那在每個執行計劃掃描A次之后，MongoDB是如何選出最優的執行計劃呢？

這里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構成的：

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

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

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

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

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

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

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

它們的出現都比較影響性能，所以一旦它們出現，相應的值都會被設置成0.

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

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

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

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

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

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

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

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

如果狀態為IS_EOF則加一分，所以一般達到IS_EOF狀態的索引都會被選中為最優執行計劃。

OK，說了這么多原理，我們以實際的生產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總記錄數量：

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

也就是551033614*0.29=159799748

那么A=159799748

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

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字段的索引命中數量最小，只有180999，而且比A要小。所以在掃描180999次后，operation.des_url率先到達IS_EOF狀態，那么此刻將停止掃描，進入到算分的階段。

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

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

3、MongoDB Plan Cache機制

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

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

CachedPlanStage::pickBestPlan主要邏輯如下：

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

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

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

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

我們實際看幾條SQL（直接選用當時故障時候的慢查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、首先需要掃描上次索引命中次數10，那就是17014610=1701460
2、這里我們從日志中可以看到該條sql operation.des_url: "astro/"的命中數量只有21366條，所以它是不是還沒有掃描完1701460條就達到了IS_EOF狀態了？
3、如果達到IS_EOF狀態就直接采用cache中的執行計劃。

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

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（這里是現在的記錄，當時是21366）

所以我們不用計算score是不是就能快速的得出結論，是不是采用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、首先需要掃描上次索引命中次數10，那就是17014610=1701460
2、這里我們從日志中可以看到該條sql operation.des_url: "hebei/"的命中數量只有80967條，所以它是不是還沒有掃描完1701460條就達到了IS_EOF狀態了？
3、如果達到IS_EOF狀態就直接采用cache中的執行計劃。

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（這里是現在的記錄，當時是80967）

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

當然可以繼續去找后面的慢查日志（當然一定是重啟前的日志，重啟后MongoDB會重新生成執行計劃，這也是我們為什么重啟MongoDB之后故障就恢復了）都是這種情況，所以這就是為什么有大量慢查，最終導致MongoDB異常夯住。

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

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字段索引命中數量是會變化的，隨著具體的value不一樣，其命中數量也不會一樣。除了這條引發故障的SQL之外，其他SQL的operation.sha1Code字段命中索引數量都非常小，有的甚至只有一條。那這里很明顯MongoDB在cache中只去根據cache中執行計劃的相關索引來進行判斷是不合理的。

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

那這里我們是不是想到了后面只要出現這條SQL就會導致慢查最終導致故障？

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

在2017-11-24T09:22:42的時候也執行了該SQL，不同的是operation.des_url 是 "sd/",不過這并不影響，可以看到該sql出現，馬上改變執行計劃，開始采用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重新生成執行計劃，然后重新選擇operation.sha1Code: 1.0索引，更新cache中執行計劃，然后后續類似SQL都走operation.sha1Code: 1.0索引，這樣MongoDB又恢復了正常，相關日志如下：

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

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

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

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

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

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

4、遇到該Bug如何處理

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

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

- 列出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" : {
            
        }
    }
]

- 根據該條件查看cache中的執行計劃

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

- 清理該cache中的執行計劃

db.files.getPlanCache().clear()

當然我們在緊急的情況下直接執行第三條命令即可。

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

5、附錄

最后筆者貼上MongoDB優化器調用棧，方便擼源碼的同學快速上手

    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云服務器云服務器深入學習mongodb mongodb管理與開發實戰詳解深入云計算 mongodb管理與開發實戰詳解-深入云計算深入解析windows操作系統

文章版權歸作者所有，未經允許請勿轉載,若此文章存在違規行為，您可以聯系管理員刪除。

轉載請注明本文地址：http://specialneedsforspecialkids.com/yun/19283.html

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

摘要：作者蘇立在之前的一篇文章源碼閱讀系列文章三的一生中，我們介紹了在收到客戶端請求包時，最常見的的請求處理流程。通常的執行后，會向客戶端持續返回結果，返回速率受控制見源碼閱讀系列文章十和執行框架簡介，但實際中返回的結果集可能非常大。作者：蘇立在之前的一篇文章《TiDB 源碼閱讀系列文章（三）SQL 的一生》中，我們介紹了 TiDB 在收到客戶端請求包時，最常見的 Command ---...

Tony_Zby 2019-06-25 19:02 評論0 收藏0
TiDB 社區成長足跡與小紅花 | TiDB DevCon 2019

摘要：在上，我司聯合創始人崔秋帶大家一起回顧了年社區成長足跡，在社區榮譽時刻環節，我們為新晉授予了證書，并為年度最佳貢獻個人團隊頒發了榮譽獎杯。同時，我們也為新晉授予了證書，并為年最佳社區貢獻個人最佳社區貢獻團隊頒發了榮譽獎杯。 2018 年 TiDB 產品變得更加成熟和穩定，同時 TiDB 社區力量也在發展壯大。在 TiDB DevCon 2019 上，我司聯合創始人崔秋帶大家一起回顧了 ...

hlcfan 2019-06-25 19:04 評論0 收藏0

發表評論

登陸后可評論

0條評論

Pluser

男|高級講師

我要關注我要私信

TA的文章

《JavaScript百煉成仙》統一回復粉絲們的一些問題

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

閱讀 1073·2020-12-03 17:06
UCloud撬動東南亞市場，占領競技手游“淘金地”

閱讀 729·2019-12-27 11:42
1像素下邊框引發移動端設備像素比的應用

閱讀 3267·2019-08-30 13:59
JS手動實現柯里化(curry)函數

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

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

閱讀 2471·2019-08-26 10:22
調用攝像頭-截圖并保存圖像

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

国产xxxx99真实实拍_久久不雅视频_高清韩国a级特黄毛片_嗯老师别我我受不了了小说

資訊專欄INFORMATION COLUMN

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

深入解析 MongoDB Plan Cache

相關文章

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

TiDB 社區成長足跡與小紅花 | TiDB DevCon 2019

發表評論

0條評論

Pluser

男|高級講師

TA的文章

《JavaScript百煉成仙》統一回復粉絲們的一些問題

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

UCloud撬動東南亞市場，占領競技手游“淘金地”

1像素下邊框引發移動端設備像素比的應用

JS手動實現柯里化(curry)函數

遮罩層彈框頁面滾動

js深度克隆的幾種方法

調用攝像頭-截圖并保存圖像

最新活動