本文是我前同事付秋雷最近遇到到一个关于 MongoDB 执行计划选择的问题,非常有意思,在探索源码之后,他将整个问题搞明白并整理分享出来。付秋雷 (他的博客)曾是 Tair(阿里内部用得非常广泛的 KV 存储系统)的核心开发成员,目前就职于蘑菇街。
反馈线上某条查询很慢(
- 苏先生
),语句相当于
- 10+ seconds
- db.myColl.find({
- app: "my_app",
- requestTime: {
- $gte: 1492502247000,
- $lt: 1492588800000
- }
- }).sort({
- _id: -1
- }).limit(1)
这个
- myColl
中的记录内容类似于:
- collection
- {
- "_id": ObjectId("58fd895359cb8757d493ce60"),
- "app": "my_app",
- "eventId": 141761066,
- "requestTime": NumberLong("1493010771753"),
- "scene": "scene01"
- } {
- "_id": ObjectId("58fd895359cb8757d493ce52"),
- "app": "my_app",
- "eventId": 141761052,
- "requestTime": NumberLong("1493010771528"),
- "scene": "scene02"
- } {
- "_id": ObjectId("58fd895359cb8757d493ce36"),
- "app": "my_app",
- "eventId": 141761024,
- "requestTime": NumberLong("1493010771348"),
- "scene": "scene03"
- } {
- "_id": ObjectId("58fd895359cb8757d493ce31"),
- "app": "my_app",
- "eventId": 141761019,
- "requestTime": NumberLong("1493010771303"),
- "scene": "scene01"
- } {
- "_id": ObjectId("58fd895359cb8757d493ce2d"),
- "app": "my_app",
- "eventId": 141761015,
- "requestTime": NumberLong("1493010771257"),
- "scene": "scene01"
- } {
- "_id": ObjectId("58fd895259cb8757d493ce10"),
- "app": "my_app",
- "eventId": 141760986,
- "requestTime": NumberLong("1493010770866"),
- "scene": "scene01"
- } {
- "_id": ObjectId("58fd895259cb8757d493ce09"),
- "app": "my_app",
- "eventId": 141760979,
- "requestTime": NumberLong("1493010770757"),
- "scene": "scene01"
- } {
- "_id": ObjectId("58fd895259cb8757d493ce02"),
- "app": "my_app",
- "eventId": 141760972,
- "requestTime": NumberLong("1493010770614"),
- "scene": "scene03"
- } {
- "_id": ObjectId("58fd895259cb8757d493cdf1"),
- "app": "my_app",
- "eventId": 141760957,
- "requestTime": NumberLong("1493010770342"),
- "scene": "scene02"
- } {
- "_id": ObjectId("58fd895259cb8757d493cde6"),
- "app": "my_app",
- "eventId": 141760946,
- "requestTime": NumberLong("1493010770258"),
- "scene": "scene01"
- }
相关的索引有:
- [
- {
- "v" : 1,
- "key" : {
- "_id" : 1
- },
- "name" : "_id_",
- "ns" : "myDatabase.myColl"
- },
- {
- "v" : 1,
- "key" : {
- "responseTime" : -1
- },
- "name" : "idx_responseTime_-1",
- "ns" : "myDatabase.myColl"
- },
- {
- "v" : 1,
- "key" : {
- "app" : 1,
- "scene" : 1,
- "eventId" : -1,
- "requestTime" : -1
- },
- "name" : "idx_app_1_scene_1_eventId_-1_requestTime_-1",
- "ns" : "myDatabase.myColl"
- }
- ]
慢查询就是在
中查找符合
- myColl
这个时间范围的所有记录,** 以下描述中称这条查询为
- [1492502247000, 1492588800000)
**。
- bad query
如果去掉
这个约束条件,查找
- $lt:1492588800000
这个时间范围,就会很快(
- [1492502247000, +∞)
)。
- milliseconds
- db.myColl.find({
- app: "my_app",
- requestTime: {
- $gte: 1492502247000
- }
- }).sort({
- _id: -1
- }).limit(1)
以下描述中称这条查询为
。
- good query
问题来了:
这两条查询都是走的什么索引呢?导致执行时间相差如此之大
- [问题A]
如果两条查询选取的索引不同,为什么会有这个不同呢,这两条查询长得还是挺像的
- [问题B]
如果
- [问题C]
选取和
- bad query
一样的索引,是否还会有一样的问题呢
- good query
- 问题A
这两条查询都是走的什么索引呢?导致执行时间相差如此之大
和
一样,
- Mysql
也提供了
- Mongodb
语句,可以获取
- explain
的查询计划(
- query语句
)、以及执行过程中的统计信息(
- queryPlanner
)。
- executionStats
违和发散:
中也是有类似的功能,
- Cassandra
中目前是没有看到的。
- Hbase
在
中的使用方法是在
- mongo shell
后面加上
- query语句
,对于上面的
- .explain('executionStats')
,对应的
- good query
语句为:
- explain
- db.myColl.find({
- app: "my_app",
- requestTime: {
- $gte: 1492502247000
- }
- }).sort({
- _id: -1
- }).limit(1).explain('executionStats')
的
- good query
语句的执行结果如下,无关细节用
- explain
省略:
- ...
- {
- "queryPlanner" : {
- "plannerVersion" : 1,
- "namespace" : "myDatabase.myColl",
- "indexFilterSet" : false,
- "parsedQuery" : ...
- "winningPlan" : {
- "stage" : "LIMIT",
- "limitAmount" : 1,
- "inputStage" : {
- "stage" : "FETCH",
- "filter" : ...,
- "inputStage" : {
- "stage" : "IXSCAN",
- "keyPattern" : {
- "_id" : 1
- },
- "indexName" : "_id_",
- ...
- "direction" : "backward",
- "indexBounds" : {
- "_id" : [
- "[MaxKey, MinKey]"
- ]
- }
- }
- }
- },
- "rejectedPlans" : ...,
- },
- "executionStats" : {
- "executionSuccess" : true,
- "nReturned" : 1,
- "executionTimeMillis" : 0,
- "totalKeysExamined" : 8,
- "totalDocsExamined" : 8,
- "executionStages" : {
- "stage" : "LIMIT",
- ...
- "inputStage" : {
- "stage" : "FETCH",
- ...
- "inputStage" : {
- "stage" : "IXSCAN",
- ...
- "direction" : "backward",
- "indexBounds" : {
- "_id" : [
- "[MaxKey, MinKey]"
- ]
- },
- "keysExamined" : 8,
- ...
- }
- }
- }
- },
- "serverInfo" : ...,
- "ok" : 1
- }
结果分为四部分:
、
- queryPlanner
、
- executionStats
、
- serverInfo
,仅关注
- ok
、
- queryPlanner
这两部分。
- executionStats
就是执行
- executionStats
这个计划时的统计信息,可以从
- queryPlanner.winningPlan
看到
- indexBounds
在索引扫描(
- good query
)阶段,** 使用的索引是
- IXSCAN
主键索引 **。从
- _id
这个阶段的
- IXSCAN
统计可以解释为什么
- keysExamined
执行的这么快,只扫描了
- good query
数据。
- 8条
同样使用
语句看看
- explain
使用的是什么索引:
- bad query
- {
- "queryPlanner" : {
- ...
- "winningPlan" : {
- "stage" : "SORT",
- ...
- "inputStage" : {
- "stage" : "SORT_KEY_GENERATOR",
- "inputStage" : {
- "stage" : "FETCH",
- "inputStage" : {
- "stage" : "IXSCAN",
- "keyPattern" : {
- "app" : 1,
- "scene" : 1,
- "eventId" : -1,
- "requestTime" : -1
- },
- "indexName" : "idx_app_1_scene_1_eventId_-1_requestTime_-1",
- ...
- "direction" : "forward",
- "indexBounds" : {
- "app" : [
- "[\"my_app\", \"my_app\"]"
- ],
- "scene" : [
- "[MinKey, MaxKey]"
- ],
- "eventId" : [
- "[MaxKey, MinKey]"
- ],
- "requestTime" : [
- "(1492588800000.0, 1492502247000.0]"
- ]
- }
- }
- }
- }
- },
- "rejectedPlans" : ...,
- },
- "executionStats" : {
- "executionSuccess" : true,
- "nReturned" : 1,
- "executionTimeMillis" : 56414,
- "totalKeysExamined" : 3124535,
- "totalDocsExamined" : 275157,
- "executionStages" : {
- "stage" : "SORT",
- ...
- "inputStage" : {
- "stage" : "SORT_KEY_GENERATOR",
- ...
- "inputStage" : {
- "stage" : "FETCH",
- ...
- "inputStage" : {
- "stage" : "IXSCAN",
- ...
- "direction" : "forward",
- "indexBounds" : {
- "app" : [
- "[\"my_app\", \"my_app\"]"
- ],
- "scene" : [
- "[MinKey, MaxKey]"
- ],
- "eventId" : [
- "[MaxKey, MinKey]"
- ],
- "requestTime" : [
- "(1492588800000.0, 1492502247000.0]"
- ]
- },
- "keysExamined" : 3124535,
- ...
- }
- }
- }
- }
- },
- "serverInfo" : ...,
- "ok" : 1
- }
可以看到 **
使用的索引是一个复合索引(Compound Indexes),确实和
- bad query
使用的索引不一样 **。同样,从
- good query
这个阶段的
- IXSCAN
统计可以看到扫描了
- keysExamined
条数据,所以执行时间会很长。
- 3124535
- 问题B
如果两条查询选取的索引不同,为什么会有这个不同呢,这两条查询长得还是挺像的
是如何为查询选取认为合适的索引的呢?
- Mongodb
粗略来说,会先选几个候选的查询计划,然后会为这些查询计划按照某个规则来打分,分数最高的查询计划就是合适的查询计划,这个查询计划里面使用的索引就是认为合适的索引。
好,粗略地说完了,现在细致一点说(还是那句话:没有代码的解释都是耍流氓,以下所有的代码都是基于
)。
- mongodb-3.2.10
先看一个栈:
- mongo::PlanRanker::scoreTree
- mongo::PlanRanker::pickBestPlan
- mongo::MultiPlanStage::pickBestPlan
- mongo::PlanExecutor::pickBestPlan
- mongo::PlanExecutor::make
- mongo::PlanExecutor::make
- mongo::getExecutor
- mongo::getExecutorFind
- mongo::FindCmd::explain
这是使用
来调试
- lldb
时,在
- mongod
(代码位于
- mongo::PlanRanker::scoreTree
)处设置断点打印出来的栈。
- src/mongo/db/query/plan_ranker.cpp
里面就是计算每个查询计划的得分的:
- scoreTree
- // We start all scores at 1. Our "no plan selected" score is 0 and we want all plans to
- // be greater than that.
- double baseScore = 1;
- // How many "units of work" did the plan perform. Each call to work(...)
- // counts as one unit.
- size_t workUnits = stats->common.works;
- // How much did a plan produce?
- // Range: [0, 1]
- double productivity =
- static_cast<double>(stats->common.advanced) / static_cast<double>(workUnits);
- ...
- double tieBreakers = noFetchBonus + noSortBonus + noIxisectBonus;
- double score = baseScore + productivity + tieBreakers;
并没有执行查询,只是根据已有的
- scoreTree
来进行计算。那么,是什么时候执行查询来获取查询计划的
- PlanStageStats* stats
的呢?
- PlanStageStats* stats
在
(代码位于
- mongo::MultiPlanStage::pickBestPlan
)中,会调用
- src/mongo/db/exec/multi_plan.cpp
来执行所有的查询计划,最多会调用
- workAllPlans
次:
- numWorks
- size_t numWorks = getTrialPeriodWorks(getOpCtx(), _collection);
- size_t numResults = getTrialPeriodNumToReturn(*_query);
- // Work the plans, stopping when a plan hits EOF or returns some
- // fixed number of results.
- for (size_t ix = 0; ix < numWorks; ++ix) {
- bool moreToDo = workAllPlans(numResults, yieldPolicy);
- if (!moreToDo) {
- break;
- }
- }
- 问题C
如果
选取和
- bad query
一样的索引,是否还会有一样的问题呢
- good query
查询时,可以借助于
- Mongodb
命令强制选取某一条索引来进行查询,比如上述的
- hint
加上
- bad query
,就可以强制使用主键索引:
- .hint({_id:1})
- db.myColl.find({
- app: "my_app",
- requestTime: {
- $gte: 1492502247000,
- $lt: 1492588800000
- }
- }).sort({
- _id: -1
- }).limit(1).hint({
- _id: 1
- })
然而,即使是这样,查询还是很慢,依然加上
看一下执行情况,解答
- .explain('executionStats')
时已经对
- 问题A
的结果做了些解释,所以这次着重看
- explain
阶段的
- IXSCAN
:
- keysExamined
- {
- ...
- "executionStages" : {
- "stage" : "LIMIT",
- ...
- "inputStage" : {
- "stage" : "FETCH",
- "filter" : {
- "$and" : [
- {
- "app" : {
- "$eq" : "my_app"
- }
- },
- {
- "requestTime" : {
- "$lt" : 1492588800000
- }
- },
- {
- "requestTime" : {
- "$gte" : 1492502247000
- }
- }
- ]
- },
- "nReturned" : 1,
- ...
- "inputStage" : {
- "stage" : "IXSCAN",
- ...
- "nReturned" : 32862524,
- ...
- "keysExamined" : 32862524,
- ...
- ...
- }
扫描了
条记录,依然很慢。这个现象比较好解释了,从
- 32862524
可以看到,加了
- executionStats.executionStages
的查询经历了
- hint
=>
- LIMIT
=>
- FETCH
这几个阶段,
- IXSCAN
这个阶段返回了
- IXSCAN
条记录,被
- 32862524
阶段过滤只剩下一条,所以有
- FETCH
条无效扫描,为什么会有这么多无效扫描呢?
- 32862523
这个和业务逻辑是相关的,
时间戳是随时间增长的,主键
- requestTime
也可以认为随时间增长的,所以按照主键索引倒序来,最开始被扫描的是最新的记录,最新的记录是满足
- _id
这个条件的,所以
- "requestTime" : {"$gte" : 1492502247000}
只需要满足
- good query
就会很快返回;
- "app" : {"$eq" : "my_app"}
然而
的约束条件
- bad query
中的
- "requestTime" : {"$gte" : 1492502247000, "$lt" : 1492588800000}
是无法被满足的,** 必须要把所有比
- "$lt" : 1492588800000
这个时间戳新的记录都扫描完了之后才会返回 **。
- 1492588800000
提出了完美的解决方案:不使用
- 苏先生
来排序,而是使用
- _id
来进行排序。这样就会使用
- request_time
这条索引,只需要进行
- "requestTime" : -1
的过滤,也是
- "app" : {"$eq" : "my_app"}
时间内完成查询。
- milliseconds
快速搭建本地集群
- salt
感谢
在排查过程中提供的关键帮助。
- 林青大神
来源: https://yq.aliyun.com/articles/74635