MongoDB使用profile分析慢查询的步骤
在mongodb中，如果发生了慢查询，我们如何得到这些慢查询的语句，并优化呢？今天来看这块儿的一些心得。
01 如何收集慢查询？
在mongodb中，通常可以开启profile来收集慢日志，查看当前profile状态的语句如下：
test1:primary> db.getprofilingstatus()
{
"was" : 2,
"slowms" : 0,
"samplerate" : 1,
"$glestats" : {
"lastoptime" : timestamp(0, 0),
"electionid" : objectid("7fffffff0000000000000005")
},
"lastcommittedoptime" : timestamp(1619186976, 2),
"$configserverstate" : {
"optime" : {
"ts" : timestamp(1619186976, 1),
"t" : numberlong(2)
}
},
"$clustertime" : {
"clustertime" : timestamp(1619186976, 2),
"signature" : {
"hash" : bindata(0,"zvwfpgc0kfxiempj7mbpdrononi="),
"keyid" : numberlong("6904838687771590657")
}
},
"operationtime" : timestamp(1619186976, 2)
}
这里我们可以看到2个关键参数，分别是was和slowms，其中：
was=0,代表不记录任何的语句；
was=1,代表记录执行时间超过slowms的语句
was=2,代表记录所有的语句
slowms代表语句的阈值，单位是ms
上图中的结果代表我们的实例会收集所有的查询语句。profile收集的查询语句结果存放在admin数据库中的system.profile集合中，可以通过下面的方法进行访问：
test1:primary> use admin
switched to db admin
test1:primary> db.system.profile.find({'op':'query'},{'op':1,'ns':1,'millis':1,'ts':1})
{ "op" : "query", "ns" : "admin.system.users", "millis" : 0, "ts" : isodate("2020-08-27t07:22:14.815z") }
{ "op" : "query", "ns" : "admin.system.users", "millis" : 0, "ts" : isodate("2020-08-27t07:22:15.139z") }
{ "op" : "query", "ns" : "admin.system.users", "millis" : 0, "ts" : isodate("2020-08-27t07:22:15.141z") }
{ "op" : "query", "ns" : "admin.system.users", "millis" : 0, "ts" : isodate("2020-08-27t07:22:15.239z") }
{ "op" : "query", "ns" : "admin.system.version", "millis" : 0, "ts" : isodate("2020-08-27t07:22:16.155z") }
{ "op" : "query", "ns" : "admin.system.version", "millis" : 0, "ts" : isodate("2020-08-27t07:22:16.192z") }
{ "op" : "query", "ns" : "admin.system.users", "millis" : 0, "ts" : isodate("2020-08-27t07:22:16.225z") }
{ "op" : "query", "ns" : "admin.system.users", "millis" : 0, "ts" : isodate("2020-08-27t07:22:16.273z") }
{ "op" : "query", "ns" : "admin.system.version", "millis" : 0, "ts" : isodate("2020-08-27t07:22:16.276z") }
02 system.profile慢查询集合分析
admin数据库中的system.profile是一个固定集合，保存着超过设置的慢查询的结果。我们来看里面的一条慢查询。
利用下面的方法，来拿到一条数据，并对其中的关键字段进行注释说明：
test1:primary> db.system.profile.findone({'op':'query'})
{
"op" : "query", # 操作类型
"ns" : "admin.system.users", # 命名空间
"command" : {
"find" : "system.users",
"filter" : {
"_id" : "admin.root" # 过滤的字段
},
"limit" : 1,
"singlebatch" : true,
"lsid" : {
"id" : uuid("a6034f5e-77c1-4b19-9669-60e1253edf4b")
},
"$readpreference" : {
"mode" : "secondarypreferred"
},
"$db" : "admin"
},
"keysexamined" : 1, # 扫描的索引数
"docsexamined" : 1, # 扫描的行数
"cursorexhausted" : true,
"numyield" : 0,
"nreturned" : 1, # 返回的值的行数
"locks" : {
xxxx # 锁信息
},
"flowcontrol" : {
},
"storage" : {
},
"responselength" : 647,
"protocol" : "op_query",
"millis" : 0, # 这个查询的执行时间，因为我们设置的profilestatus是0，因此所有操作都被记录了。
"plansummary" : "idhack", # 针对_id进行查询
"execstats" : { # 查询执行状态
"stage" : "idhack",
"nreturned" : 1,
"executiontimemillisestimate" : 0,
"works" : 2,
"advanced" : 1,
"needtime" : 0,
"needyield" : 0,
"savestate" : 0,
"restorestate" : 0,
"iseof" : 1,
"keysexamined" : 1,
"docsexamined" : 1
},
"ts" : isodate("2020-08-27t07:22:14.815z"),
"client" : "xx.xx.xx.xx", # 查询的客户端ip地址
"allusers" : [ # 所有的用户信息
{
"user" : "root",
"db" : "admin"
}
],
"user" : "root@admin" # 使用的用户信息
}
03 慢查询分析利器---explain
通常情况下，我们可以使用mongodb的explain语法来分析一个语句的查询性能，包含是否用到索引、扫描行数等信息，explain语法的基本用法:
后置写法
db.system.profile.find({'op':'query'}).explain()
前置写法
db.system.profile.explain().find({'op':'query'})
其中，explain可以放在查询语句的后面或者前面，当然find语法也可以是update、remove、insert
explain语法的输出分为3种不同的详细程度，分别如下：
三种清晰度模式，清晰度越高，则输出的信息越全，默认情况下是queryplanner：
1、queryplanner模式(默认)
db.products.explain().count( { quantity: { $gt: 50 } } )2、executionstats模式
db.products.explain("executionstats").count( { quantity: { $gt: 50 } } )3、allplansexecution模式
db.products.explain("allplansexecution").count( { quantity: { $gt: 50 } } )
其中，allplansexecution模式输出的信息最多。
下面是一个explain语法的输出内容，查询的sql如下：
db.getcollection('files').find(
{"ctime":{
"$gte":isodate("2021-04-18"),
"$lt":isodate("2021-04-19")
}}).limit(1000).explain("allplansexecution")
输出的结果如下：
{
"queryplanner" : { # 代表查询的执行计划
"plannerversion" : 1, # 版本号
"namespace" : "fs.files", # 查询的命名空间，也就是集合名称
"indexfilterset" : false, # 是否使用了索引过滤，注意，它并不能判定是否使用了索引
"parsedquery" : { # 查询语法解析树
"$and" : [
{
"ctime" : {
"$lt" : isodate("2021-04-19t00:00:00z")
}
},
{
"ctime" : {
"$gte" : isodate("2021-04-18t00:00:00z")
}
}
]
},
"winningplan" : { # 最终选择的查询计划
"stage" : "limit", # 查询的阶段，很重要，下面详细介绍
"limitamount" : 1000, # 查询结果的limit值
"inputstage" : {
"stage" : "fetch",
"inputstage" : {
"stage" : "ixscan", # 代表索引扫描
"keypattern" : {
"ctime" : 1
},
"indexname" : "ctime_1", # 索引名称
"ismultikey" : false, # 下面4个字段都是索引类型分析
"isunique" : false,
"issparse" : false,
"ispartial" : false,
"indexversion" : 1,
"direction" : "forward",
"indexbounds" : {
"ctime" : [
"[new date(1618704000000), new date(1618790400000))"
]
}
}
}
},
"rejectedplans" : [ ] # 候选的没被选中的查询计划
},
"serverinfo" : {
"host" : "xxxx",
"port" : 24999,
"version" : "3.2.8",
"gitversion" : "ed70e33130c977bda0024c125b56d159573dbaf0"
},
"ok" : 1
}
首先解释下stage的几个阶段：
- collscan---全表扫描
- ixscan---索引扫描
- fetch---根据索引去检索文档
- shard_merge---合并分片结果
- idhack---针对id进行查询
- limit---执行limit
了解了这些stage的阶段之后，我们可以看到，一个查询的过程是一层一层解析的，所以可以看到，stage这个字段有嵌套的情况。winningplan中的执行计划也是按照一层一层的顺序去执行：
1、先执行最内层的索引扫描(ixscan)；
2、再执行外面的fetch，根据索引去拿文档
3、执行最后一步的limit，取指定数目个结果返回给客户端
以上就是mongodb profile分析慢查询的示例的详细内容，更多关于mongodb profile分析慢查询的资料请关注其它相关文章！