深刻解析 MongoDB Plan Cache

時間  2019-12-05
標籤 深刻 解析 mongodb plan cache 欄目 MongoDB 简体版
原文   原文鏈接

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

  1. 背景
  2. MongoDB生成執行計劃是如何選擇索引的
    2.1. 過濾符合條件的索引
    2.2. 選擇合適的索引
  3. MongoDB Plan Cache機制
  4. 遇到該Bug如何處理
  5. 附錄

一、背景

在2月26號下午2點37的時候，咱們線上MongoDB性能出現拐點，開始出現大量的慢查，最終形成MongoDB異常夯住，最後經過重啓MongoDB故障恢復。sql

首先咱們知道是因爲同類型的SQL忽然改變執行計劃選擇了其餘的索引，形成後續的SQL直接採用Cache中的執行計劃所有成爲慢查。那這裏咱們概括爲2個主要問題：mongodb

- 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/"})ui

它會選擇帶有operation.sha1Code、operation.is_prefix、operation.des_url字段的索引，無論是單個索引仍是複合索引，因此在實際生產環境中選擇了以下索引：lua

{
  "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
  }

可是上述索引誰最合適呢？url

2.2. 選擇合適的索引

前面咱們提到了MongoDB會根據謂詞條件選擇多個索引，可是最終執行計劃會選擇一個索引，那MongoDB是怎麼判斷哪一個索引能更快的得出該SQL的結果呢？spa

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

numWorks = std::max(static_cast<size_t>(internalQueryPlanEvaluationWorks),
                            static_cast<size_t>(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<double>(stats->common.advanced) / static_cast<double>(workUnits);
    const double epsilon = std::min(1.0 / static_cast<double>(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<double>(stats->common.advanced) / static_cast<double>(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<double>(10 * workUnits), 1e-4);

這裏workUnits就是每一個索引的掃描次數，那麼這裏的意思就是取1.0 / static_cast<double>(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<size_t>(internalQueryPlanEvaluationWorks),
                            static_cast<size_t>(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並無選錯索引，它選的很正確。

三、MongoDB Plan Cache機制

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

在CachedPlanStage::pickBestPlan方法中，MongoDB會決定該SQL是繼續採用cache中的執行計劃，仍是須要從新生成執行計劃。

CachedPlanStage::pickBestPlan主要邏輯以下：

一、以Cache中執行計劃的索引命中數量（works）*10=須要掃描的數量（B次）
二、繼續用該索引掃描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的邏輯：
一、首先須要掃描上次索引命中次數10，那就是17014610=1701460
二、這裏咱們從日誌中能夠看到該條sql operation.des_url: "astro/"的命中數量只有21366條，因此它是否是尚未掃描完1701460條就達到了IS_EOF狀態了？
三、若是達到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的邏輯：
一、首先須要掃描上次索引命中次數10，那就是17014610=1701460
二、這裏咱們從日誌中能夠看到該條sql operation.des_url: "hebei/"的命中數量只有80967條，因此它是否是尚未掃描完1701460條就達到了IS_EOF狀態了？
三、若是達到IS_EOF狀態就直接採用cache中的執行計劃。

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

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年以前的日誌，都是這種狀況。

四、遇到該Bug如何處理

咱們經過上述分析得出該次故障確實是因爲MongoDB自身執行計劃cache機制致使，那咱們有什麼應對方案呢？

一、重啓實例
這個是最粗暴的方式，針對於MongoDB異常夯住不能登陸的狀況
二、清理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()

固然咱們在緊急的狀況下直接執行第三條命令便可。

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

五、附錄

最後筆者貼上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<mongo::WorkingSet,std::default_delete<mongo::WorkingSet> > ws, std::unique_ptr<mongo::PlanStage,std::default_delete<mongo::PlanStage> > rt, std::unique_ptr<mongo::QuerySolution,std::default_delete<mongo::QuerySolution> > qs, std::unique_ptr<mongo::CanonicalQuery,std::default_delete<mongo::CanonicalQuery> > cq, const mongo::Collection * collection, const std::basic_string<char,std::char_traits<char>,std::allocator<char> > & ns, mongo::PlanExecutor::YieldPolicy yieldPolicy) 行 143    C++
    mongod.exe!mongo::PlanExecutor::make(mongo::OperationContext * opCtx, std::unique_ptr<mongo::WorkingSet,std::default_delete<mongo::WorkingSet> > ws, std::unique_ptr<mongo::PlanStage,std::default_delete<mongo::PlanStage> > rt, std::unique_ptr<mongo::QuerySolution,std::default_delete<mongo::QuerySolution> > qs, std::unique_ptr<mongo::CanonicalQuery,std::default_delete<mongo::CanonicalQuery> > cq, const mongo::Collection * collection, mongo::PlanExecutor::YieldPolicy yieldPolicy) 行 127    C++
    mongod.exe!mongo::getExecutor(mongo::OperationContext * txn, mongo::Collection * collection, std::unique_ptr<mongo::CanonicalQuery,std::default_delete<mongo::CanonicalQuery> > 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<mongo::CanonicalQuery,std::default_delete<mongo::CanonicalQuery> > canonicalQuery, mongo::PlanExecutor::YieldPolicy yieldPolicy) 行 582    C++
    mongod.exe!mongo::FindCmd::run(mongo::OperationContext * txn, const std::basic_string<char,std::char_traits<char>,std::allocator<char> > & dbname, mongo::BSONObj & cmdObj, int options, std::basic_string<char,std::char_traits<char>,std::allocator<char> > & 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++
相關文章
相關標籤/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公眾號
   歡迎關注本站公眾號,獲取更多信息
聯繫我們 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程