优化参考
查询优化问题,需要有大量的数据来支持,我们通过java插入了500W条数据到数据库中,数据结构如下所示
{
"_id" : ObjectId("5a3b28b8b932f02bc038744d"),
"type" : "fatal",
"date" : ISODate("2000-07-19T13:03:25.207Z"),
"ip" : "111.176.23.100",
"operator" : "error",
"user" : "asd"
}
我们要进行查询优化,首先需要一些参考依据,当我们完成如下查询
db.logs.find({type:"fatal"}).sort({date:-1}).limit(1)
查询时间为6m,当查询时间超过100ms,这个查询就会在日志系统中有所记录
2017-12-21T17:59:17.409+0800 I COMMAND [conn95] command demo.logs appName: "MongoDB Shell" command: find { find: "logs", filter: { type: "fatal" }, limit: 1.0, singleBatch: false, sort: { date: -1.0 } } planSummary: COLLSCAN keysExamined:0 docsExamined:5000000 hasSortStage:1 cursorExhausted:1 numYields:39176 nreturned:1 reslen:194 locks:{ Global: { acquireCount: { r: 78354 } }, Database: { acquireCount: { r: 39177 } }, Collection: { acquireCount: { r: 39177 } } } protocol:op_command 6552ms
这个信息是我们排查查询效率的一个非常好的途径,通过这个信息我们首先看到{find:"logs",filter:{type:"fatal"}}
这里指明了查询的collection,通过type来查询,并且limit了1条和通过Date排序,通过这个信息我们可以定位到我们具体的查询中,后面的信息,我们会在explain中详细讲解。
日志是第一种慢查询的分析手段,我们的第二种手段是使用PROFILER查询分析器,PROFILER查询分析器默认是关闭的使用setProfilingLevel
可以开启查询分析器。
db.setProfilingLevel(2)表示开启查询分析器,级别为2级,会详细的记录每个读写操作
db.setProfilingLevel(1,50)表示设置监控级别为1级,并且当查询时间超过50ms就会启动监控
db.setProfilingLevel(0)表示关闭监控级别
当开启了2级查询之后,默认会监听100ms已上的查询,当使用了以下查询之后
db.logs.find({type:"fatal"}).sort({ip:-1}).limit(1)
查询时间超过了7秒,所有的监控结果会保存在一个特殊的集合中,可以通过system.profile来进行查询,这个集合的大小是固定的,在3.0版本后分配了128k的空间,当超过这个大小会覆盖掉原来的信息,目前由于只有一条信息,我们可以通过findOne来进行查询
>db.system.profile.findOne({})
{
"op" : "query",
"ns" : "demo.logs",
"query" : {
"find" : "logs",
"filter" : {
"type" : "fatal"
},
"limit" : 1.0,
"singleBatch" : false,
"sort" : {
"ip" : -1.0
}
},
"keysExamined" : 0,
"docsExamined" : 5000000,
"hasSortStage" : true,
"cursorExhausted" : true,
"numYield" : 39169,
"locks" : {
"Global" : {
"acquireCount" : {
"r" : NumberLong(78340)
}
},
"Database" : {
"acquireCount" : {
"r" : NumberLong(39170)
}
},
"Collection" : {
"acquireCount" : {
"r" : NumberLong(39170)
}
}
},
"nreturned" : 1,
"responseLength" : 191,
"protocol" : "op_command",
"millis" : 7010,
"planSummary" : "COLLSCAN",
"execStats" : {
"stage" : "SORT",
"nReturned" : 1,
"executionTimeMillisEstimate" : 6386,
"works" : 5000005,
"advanced" : 1,
"needTime" : 5000003,
"needYield" : 0,
"saveState" : 39169,
"restoreState" : 39169,
"isEOF" : 1,
"invalidates" : 0,
"sortPattern" : {
"ip" : -1.0
},
"memUsage" : 114,
"memLimit" : 33554432,
"limitAmount" : 1,
"inputStage" : {
"stage" : "SORT_KEY_GENERATOR",
"nReturned" : 1000696,
"executionTimeMillisEstimate" : 5824,
"works" : 5000003,
"advanced" : 1000696,
"needTime" : 3999306,
"needYield" : 0,
"saveState" : 39169,
"restoreState" : 39169,
"isEOF" : 1,
"invalidates" : 0,
"inputStage" : {
"stage" : "COLLSCAN",
"filter" : {
"type" : {
"$eq" : "fatal"
}
},
"nReturned" : 1000696,
"executionTimeMillisEstimate" : 4380,
"works" : 5000002,
"advanced" : 1000696,
"needTime" : 3999305,
"needYield" : 0,
"saveState" : 39169,
"restoreState" : 39169,
"isEOF" : 1,
"invalidates" : 0,
"direction" : "forward",
"docsExamined" : 5000000
}
}
},
"ts" : ISODate("2017-12-21T23:59:36.779Z"),
"client" : "127.0.0.1",
"appName" : "MongoDB Shell",
"allUsers" : [],
"user" : ""
}
这是非常有用的分析性能的文档,前面几个字段说明了,查询的基本信息,后面就是一些查询的分析信息,需要注意的是监控策略开启之后会自动监控所有的读操作和写操作,所以策略时间建议有一个渐进,如先开启100ms,然后慢慢过渡到90ms,不要一次性减少的间隔过大,这样有可能会找不到你想要的信息。解决慢查询最佳的时间应该是在集成测试阶段,如果在实际的运行环境中检测,发现问题和解决问题的成本会比较高,但在实际情况看,更多的问题都是在项目运行过程之中才会体现。另外需要注明的是system.profile里面内容存储得比较多的时候,会通过$natural进行自然排序,我们可以通过sort来获取最后的数据
db.system.profile.find().sort({$natural:-1})
已上介绍了发现慢查询的方法,发现很简单,但要处理就需要根据实际情况来考虑,出现慢查询的原因很多,有一部分是设计问题,一部分是硬件问题,还一部分是索引问题,我们首选的解决方案就是添加索引,通过合理的索引设置来解决部分问题。已上内容目前并没有详细的解释,请大家看完下一小节的内容再回过头来看看,这个信息,是不是就一目了然了。
explain()的运用
通过查询分析器和日志,可以检测到慢查询,这些在实际的项目运行中比较有效,但是在索引设计时,使用这种方式效率就比较低,MongoDB提供了explain()函数来找到原因。注意MongoDB2和3之后的explain的文档结构有很大区别,文中主要以3.4为例,使用如下查询
db.logs.find({type:"error"}).sort({data:-1}).limit(1).explain("executionStats")
在explain中加入executionStats之后可以根据运行的结果生成统计,先看看查询出来的结果
{
"queryPlanner" : {
"plannerVersion" : 1,
"namespace" : "demo.logs",
"indexFilterSet" : false,
"parsedQuery" : {
"type" : {
"$eq" : "error"
}
},
"winningPlan" : {
"stage" : "SORT",
"sortPattern" : {
"data" : -1.0
},
"limitAmount" : 1,
"inputStage" : {
"stage" : "SORT_KEY_GENERATOR",
"inputStage" : {
"stage" : "COLLSCAN",
"filter" : {
"type" : {
"$eq" : "error"
}
},
"direction" : "forward"
}
}
},
"rejectedPlans" : []
},
"executionStats" : {
"executionSuccess" : true,
"nReturned" : 1,
"executionTimeMillis" : 5698,
"totalKeysExamined" : 0,
"totalDocsExamined" : 5000000,
"executionStages" : {
"stage" : "SORT",
"nReturned" : 1,
"executionTimeMillisEstimate" : 5189,
"works" : 5000005,
"advanced" : 1,
"needTime" : 5000003,
"needYield" : 0,
"saveState" : 39157,
"restoreState" : 39157,
"isEOF" : 1,
"invalidates" : 0,
"sortPattern" : {
"data" : -1.0
},
"memUsage" : 122,
"memLimit" : 33554432,
"limitAmount" : 1,
"inputStage" : {
"stage" : "SORT_KEY_GENERATOR",
"nReturned" : 1000421,
"executionTimeMillisEstimate" : 4728,
"works" : 5000003,
"advanced" : 1000421,
"needTime" : 3999581,
"needYield" : 0,
"saveState" : 39157,
"restoreState" : 39157,
"isEOF" : 1,
"invalidates" : 0,
"inputStage" : {
"stage" : "COLLSCAN",
"filter" : {
"type" : {
"$eq" : "error"
}
},
"nReturned" : 1000421,
"executionTimeMillisEstimate" : 3048,
"works" : 5000002,
"advanced" : 1000421,
"needTime" : 3999580,
"needYield" : 0,
"saveState" : 39157,
"restoreState" : 39157,
"isEOF" : 1,
"invalidates" : 0,
"direction" : "forward",
"docsExamined" : 5000000
}
}
}
},
"serverInfo" : {
"host" : "SD-201709290948",
"port" : 27017,
"version" : "3.4.10-22-gb6132d8",
"gitVersion" : "b6132d87fe4c108dfb0c94980a49d97406b42dce"
},
"ok" : 1.0
}
首先queryPlan表示查询的基本信息,这个里面除了显示查询的基本操作外,有一个是值得大家注意的,那就是winning.Plans
中的stage,这里显示的SORT,说明是文档排序,这是严重影响效率的排序,马上就会详细介绍。
接下来关注executionStats中的内容,这个内容非常重要,个人先筛选如下几个重要的信息出来,我们需要慢慢来分析
"executionStats" : {
"executionSuccess" : true,
"nReturned" : 1, ##实际获取的文档数
"executionTimeMillis" : 5104, ##查询时间
"totalKeysExamined" : 0, ##扫描的索引总数
"totalDocsExamined" : 5000000,##扫描的总文档数
.....
},
通过已上信息,我们发现实际只获取了一个文档,但却花费了5秒的时间,并且没有去扫描索引,但文档却扫描了500W条,因为我们加入了排序,它会把所有文档读取到内存然后倒序得到最后一个结果,此时,我们不进行排序,看看结果
>db.logs.find({type:"error"}).limit(1).explain("executionStats")
"executionStats" : {
"executionSuccess" : true,
"nReturned" : 1,
"executionTimeMillis" : 0,
"totalKeysExamined" : 0,
"totalDocsExamined" : 4,##没有排序,仅仅扫描了4个文档
...
}
此时我们发现totalDocsExamined为4,由于查询的是type为error的信息,当从头扫描,当扫描到第4个文档的时候就发现了,然后就返回了,当然也没有执行索引。所以totalDocsExamined和nReturned是非常具有价值的两个数据,如果这两个悬殊太大肯定就是查询有问题,我们期望这两值越接近越好,说明检索的东西就是我们想要的内容
下面来分析executionStages中的信息,首先看原始查询的
"executionStages" : {
"stage" : "SORT",##这个非常重要
"nReturned" : 1,
"executionTimeMillisEstimate" : 5366,
....
}
stage是非常重要的一个信息,几种类型,SORT表示文档排序,这是我们比较害怕的操作,因为它没有进行索引,而是对文档进行排序,(就等于我们要读一本书,我们顺着内容去找内容而不是通过目录找信息),我们还会看到另外一个值COLLSCAN,这也是非常影响效率的操作,因为它属于全表扫描。下面我们再看一个操作
> db.logs.find({type:"error"}).skip(50000).limit(1).explain("executionStats")
"executionStats" : {
"executionSuccess" : true,
"nReturned" : 1,
"executionTimeMillis" : 129,
"totalKeysExamined" : 0,
"totalDocsExamined" : 249186,
...
"inputStage" : {
"stage" : "SKIP",
"nReturned" : 1,
"executionTimeMillisEstimate" : 103,
"works" : 249187,
....
此处我们没有排序,而是skip了50000条文档,虽然只查一条数据,但是却在文档中扫描了24w的数据,扫描这么多数据都是在SKIP操作上发生的,所以skip其实会做全表扫描。效率极不理想。所以stage我们一般都不希望出现“SORT”、“COLLSCAN”和不理想的“SKIP”。下面我们通过_id
进行一下检索,默认_id
都会加上唯一索引,看看结果
> db.logs.find({type:"error"}).sort({_id:-1}).limit(1).explain("executionStats")
/* 1 */
{
"queryPlanner" : {
"plannerVersion" : 1,
"namespace" : "demo.logs",
"indexFilterSet" : false,
"parsedQuery" : {
"type" : {
"$eq" : "error"
}
},
"winningPlan" : {
...
"inputStage" : {
"stage" : "IXSCAN", ##sort是基于索引的查询
"keyPattern" : {
"_id" : 1
},
"indexName" : "_id_", ##索引的名称,基于主键的查询
"isMultiKey" : false,
"multiKeyPaths" : {
"_id" : []
},
"isUnique" : true, ##唯一索引
"isSparse" : false, ##不是稀疏索引
....
}
}
}
},
"rejectedPlans" : []
},
"executionStats" : {
"executionSuccess" : true,
"nReturned" : 1, ##返回一个文档
"executionTimeMillis" : 2, ##花费了2毫秒
"totalKeysExamined" : 5, ##检索了5个索引
"totalDocsExamined" : 5, ##检索了5篇document
"executionStages" : {
。。。。
"inputStage" : {
"stage" : "FETCH", ##通过索引进行抓取
"filter" : {
"type" : {
"$eq" : "error"
}
},
"nReturned" : 1,
"executionTimeMillisEstimate" : 0,
"works" : 5,
"inputStage" : {
"stage" : "IXSCAN", ##索引检索
"nReturned" : 5,
....
}
}
}
},
}
这次查询虽然查询的字段没有增加索引,但排序时已经通过索引。所以仅仅检索了5个文档就得到了结果,效率从7秒减少到了2毫秒,大家看到检索的优势了吧。
下面我们为date增加索引,看看效果
> db.logs.createIndex({date:1})
> db.logs.find({type:"error"}).sort({date:-1}).limit(15).explain("executionStats")
{
"queryPlanner" : {
"plannerVersion" : 1,
"namespace" : "demo.logs",
"indexFilterSet" : false,
"parsedQuery" : {
"type" : {
"$eq" : "error"
}
},
"winningPlan" : {
"stage" : "LIMIT",
"limitAmount" : 15,
"inputStage" : {
"stage" : "FETCH",
"filter" : {
"type" : {
"$eq" : "error"
}
},
"inputStage" : {
"stage" : "IXSCAN",
"keyPattern" : {
"date" : 1.0
},
"indexName" : "date_1",
"isMultiKey" : false,
"multiKeyPaths" : {
"date" : []
},
"isUnique" : false,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 2,
"direction" : "backward",
"indexBounds" : {
"date" : [
"[MaxKey, MinKey]"
]
}
}
}
},
"rejectedPlans" : [
{
"stage" : "SORT",
"sortPattern" : {
"date" : -1.0
},
"limitAmount" : 15,
"inputStage" : {
"stage" : "SORT_KEY_GENERATOR",
"inputStage" : {
"stage" : "FETCH",
"inputStage" : {
"stage" : "IXSCAN",
"keyPattern" : {
"type" : 1.0
},
"indexName" : "type_1",
"isMultiKey" : false,
"multiKeyPaths" : {
"type" : []
},
"isUnique" : false,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 2,
"direction" : "forward",
"indexBounds" : {
"type" : [
"[\"error\", \"error\"]"
]
}
}
}
}
}
]
},
"executionStats" : {
"executionSuccess" : true,
"nReturned" : 15,
"executionTimeMillis" : 34,
"totalKeysExamined" : 68,
"totalDocsExamined" : 68,
"executionStages" : {
"stage" : "LIMIT",
"nReturned" : 15,
"executionTimeMillisEstimate" : 11,
"works" : 69,
"advanced" : 15,
"needTime" : 53,
"needYield" : 0,
"saveState" : 2,
"restoreState" : 2,
"isEOF" : 1,
"invalidates" : 0,
"limitAmount" : 15,
"inputStage" : {
"stage" : "FETCH",
"filter" : {
"type" : {
"$eq" : "error"
}
},
"nReturned" : 15,
"executionTimeMillisEstimate" : 11,
"works" : 68,
"advanced" : 15,
"needTime" : 53,
"needYield" : 0,
"saveState" : 2,
"restoreState" : 2,
"isEOF" : 0,
"invalidates" : 0,
"docsExamined" : 68,
"alreadyHasObj" : 0,
"inputStage" : {
"stage" : "IXSCAN",
"nReturned" : 68,
"executionTimeMillisEstimate" : 0,
"works" : 68,
"advanced" : 68,
"needTime" : 0,
"needYield" : 0,
"saveState" : 2,
"restoreState" : 2,
"isEOF" : 0,
"invalidates" : 0,
"keyPattern" : {
"date" : 1.0
},
"indexName" : "date_1",
"isMultiKey" : false,
"multiKeyPaths" : {
"date" : []
},
"isUnique" : false,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 2,
"direction" : "backward",
"indexBounds" : {
"date" : [
"[MaxKey, MinKey]"
]
},
"keysExamined" : 68,
"seeks" : 1,
"dupsTested" : 0,
"dupsDropped" : 0,
"seenInvalidated" : 0
}
}
}
},
"serverInfo" : {
"host" : "SD-201709290948",
"port" : 27017,
"version" : "3.4.10-22-gb6132d8",
"gitVersion" : "b6132d87fe4c108dfb0c94980a49d97406b42dce"
},
"ok" : 1.0
}
这个结果和_id
排序类似,效率提高了很多。
下面我们来看skip,在刚才的演示结果是,使用skip会在文档中检索,效率接近130ms,现在我们为type增加索引看看效果。
>db.logs.createIndex({type:1})
>db.logs.find({type:"error"}).skip(50000).limit(10).explain("executionStats")
{
"queryPlanner" : {
...
"winningPlan" : {
"stage" : "LIMIT",
"limitAmount" : 15,
"inputStage" : {
"stage" : "FETCH", ##查询都是基于FETCH和索引的
"filter" : {
"type" : {
"$eq" : "error"
}
},
"inputStage" : {
"stage" : "IXSCAN",
"keyPattern" : {
"date" : 1.0
},
"indexName" : "date_1",
...
}
}
}
},
"rejectedPlans" : [ ##其他可能的查询计划,但是被MongoDB否决的。
{
"stage" : "SORT",
"sortPattern" : {
"date" : -1.0
},
"limitAmount" : 15,
"inputStage" : {
"stage" : "SORT_KEY_GENERATOR",
"inputStage" : {
"stage" : "FETCH",
"inputStage" : {
"stage" : "IXSCAN",
"keyPattern" : {
"type" : 1.0
},
"indexName" : "type_1",
....
},
"executionStats" : {
"executionSuccess" : true,
"nReturned" : 15, ##返回15条
"executionTimeMillis" : 0, ##时间接近0ms
"totalKeysExamined" : 68, ##从索引里面查询
"totalDocsExamined" : 68,
...
}
}
}
}
这个里面我们看到了rejectedPlans这个值,这表示MongoDB的查询优化器找到了两种方案,一种是基于date的方案,但发现基于type的效率要高一些,所以基于sort的方案就放到了rejectedPlans中了。最后我们发现检索了68个文档,返回了15条记录,效率接近0ms。此时如果我们为type和date添加一个复合索引
>db.logs.createIndex({type:1,date:1})
>db.logs.find({type:"error"}).sort({date:-1}).limit(15).explain("executionStats")
{
"queryPlanner" : {
...
"winningPlan" : {
"stage" : "LIMIT",
"limitAmount" : 15,
"inputStage" : {
"stage" : "FETCH",
"inputStage" : {
"stage" : "IXSCAN",
"keyPattern" : {
"type" : 1.0,
"date" : 1.0
},
"indexName" : "type_1_date_1",
....
},
...
},
"executionStats" : {
"executionSuccess" : true,
"nReturned" : 15, ##返利15条信息
"executionTimeMillis" : 0,
"totalKeysExamined" : 15,
"totalDocsExamined" : 15, ##查找了15条信息
.....
},
...
"ok" : 1.0
}
这次得到的结果就更加了理想了,此时就可以把type的单键索引删除了,因为已经没有意义,通过这个复合索引就可以获取同样的值。
> db.logs.dropIndex({type:1})
> db.logs.getIndexes()
下面我们把所有复合索引删除,并且为type,date,operator分别创建三个单独索引
> db.logs.dropIndex("type_1")
> db.logs.dropIndex("type_1_data_1")
> db.logs.dropIndex("operator_1")
> db.logs.createIndex({type:1})
> db.logs.createIndex({date:1})
> db.logs.createIndex({operator:1})
下面我们运行如下查询
db.logs.find({type:"error",date:{$gt:new Date("2010-01-01")}}).explain(true)
通过explain(true)可以查询所有的计划
{
"queryPlanner" : {
"plannerVersion" : 1,
"namespace" : "demo.logs",
"indexFilterSet" : false,
"parsedQuery" : {
"$and" : [
{
"type" : {
"$eq" : "error"
}
},
{
"date" : {
"$gt" : ISODate("2010-01-01T00:00:00.000Z")
}
}
]
},
"winningPlan" : {
"stage" : "FETCH",
"filter" : {
"date" : {
"$gt" : ISODate("2010-01-01T00:00:00.000Z")
}
},
"inputStage" : {
"stage" : "IXSCAN",
"keyPattern" : {
"type" : 1.0
},
"indexName" : "type_1",
"isMultiKey" : false,
"multiKeyPaths" : {
"type" : []
},
"isUnique" : false,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 2,
"direction" : "forward",
"indexBounds" : {
"type" : [
"[\"error\", \"error\"]"
]
}
}
},
"rejectedPlans" : [
{
"stage" : "FETCH",
"filter" : {
"type" : {
"$eq" : "error"
}
},
"inputStage" : {
"stage" : "IXSCAN",
"keyPattern" : {
"date" : 1.0
},
"indexName" : "date_1",
"isMultiKey" : false,
"multiKeyPaths" : {
"date" : []
},
"isUnique" : false,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 2,
"direction" : "forward",
"indexBounds" : {
"date" : [
"(new Date(1262304000000), new Date(9223372036854775807)]"
]
}
}
}
]
},
"executionStats" : {
"executionSuccess" : true,
"nReturned" : 399346,
"executionTimeMillis" : 1675,
"totalKeysExamined" : 1000421,
"totalDocsExamined" : 1000421,
...
},
"allPlansExecution" : [
....
]
},
"serverInfo" : {
...
},
"ok" : 1.0
}
我们看到winningPlan是基于type的,而rejectedPlan是基于deat的,为什么会选择date而不是type呢?我们可以通过hint函数来指定执行的索引,这种查询totalDocsExamined为100W条数据,返回了39W多的数据,下面我们通过hint指定使用date
> var query = {type:"error",date:{$gt:new Date("2010-01-01")}}
> db.logs.find(query).hint({date:1}).explain(true)
"executionStats" : {
"executionSuccess" : true,
"nReturned" : 399346,
"executionTimeMillis" : 6506,
"totalKeysExamined" : 1995711,
"totalDocsExamined" : 1995711,
发现查询了190W才找到这些数据,所以查询优化器就会选择第一种方案,hint方法可以指定使用的索引,大家可以试一下hint({$natural:1})
这个表示使用自然搜索,而不使用索引。
到这里索引的内容就基本讲完了,这里仅仅提供了一个思路,很多情况需要实际问题,实际分析,现在大家再折回头去看看日志和profile分析器中的内容,应该就有一定的思路了!