深刻解析 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教程