背景
中午12点半,接到了线上MongoDB 数据库异常的告警通报:
“CPU不间断飙升到百分百,业务也相应出现了抖动现象。”
通过排查数据库主节点的日志,发现了这样的一个慢语句:
2019-03-07T10:56:43.470+0000 I COMMAND [conn2544772] command nlp.ApplicationDevice appName: "nlp" command:
find { find: "ApplicationDevice", filter: { appId: "Gf93VvCfOdttrxSOemt_03ff", tags.tagName: "pipeline",
tags.tagValue: "multi", _id: { $gt: ObjectId('000000000000000000000000') } }, projection: { $sortKey: { $meta: "sortKey" } },
sort: { _id: 1 }, limit: 10, shardVersion: [ Timestamp 1000|1000, ObjectId('5c64f941c81e2b922e48e347') ] }
planSummary: IXSCAN { appId: 1, tags.tagName: 1, tags.tagValue: 1, _id: 1 }
keysExamined:1000002 docsExamined:1000001 hasSortStage:1 cursorExhausted:1 numYields:7829
nreturned:10 reslen:7102 locks:{ Global: { acquireCount: { r: 15660 } },
Database: { acquireCount: { r: 7830 } }, Collection: { acquireCount: { r: 7830 } } } protocol:op_command 4008ms
从语句中初步判断,“keysExamined”和docsExamined 显示扫描了100W 条记录,其中也用到了下面的索引:
{ appId: 1, tags.tagName: 1, tags.tagValue: 1, _id: 1 }
跟研发兄弟确认过后,该查询的目的是 找到某些应用下带指定标签的设备信息,按ID分段去获取,每次只查询10条。
关于索引的设计也已经确认过是最优的了,而且此前在开发环境中一直没有出现过问题,不知道为什么这次就出问题了。
详细分析
接下来,看了下该集合的模型,大致是长下面的样子:
/* 1 */
{
"appId" : "Gf93VvCfOdttrxSOemt_03ff",
"deviceId" : "bbc-lmc-03991933",
"nodeType" : "FACTORY",
"creationTime" : ISODate("2019-03-01T10:11:39.852Z"),
"lastModifiedTime" : ISODate("2019-03-03T10:45:40.249Z"),
"tags" : [
{
"tagName" : "pipeline",
"tagValue" : "multi",
"tagType" : 1
}
],
...
}
说明
除了其他的属性之外,tags字段采用了嵌套文档数组的结构;
每一个元素都对应了一个tag对象,包含 tagName/tagValue/tagType几个字段。
然后是查询的模式:
//过滤条件
{
appId: "Gf93VvCfOdttrxSOemt_03ff",
tags.tagName: "pipeline",
tags.tagValue: "multi",
_id: { $gt: ObjectId('000000000000000000000000')
}
//排序
sort: { _id: 1 }
//限制条数
limit: 10
这从索引的前缀匹配来看,是应该没有问题的,索引的定义如下所示:
{ appId: 1, tags.tagName: 1, tags.tagValue: 1, _id: 1 }
为了避免对线上环境造成影响,我们找了一个测试环境来做了尝试复现,执行:
db.ApplicationDevice.find({
"appId":"Gf93VvCfOdttrxSOemt_03ff",
"tags.tagName":"pipeline",
"tags.tagValue":"multi",
_id:{$gt:ObjectId("000000000000000000000000")}})
.sort({"_id" : 1})
.explain()
结果却跟线上的情况不大一样,这次选中的是_id索引!
"winningPlan" : {
"stage" : "LIMIT",
"limitAmount" : 10,
"inputStage" : {
"stage" : "SHARDING_FILTER",
"inputStage" : {
"stage" : "FETCH",
"filter" : {
"$and" : [
{
"appId" : {
"$eq" : "Gf93VvCfOdttrxSOemt_03ff"
}
},
{
"tags.tagName" : {
"$eq" : "pipeline"
}
},
{
"tags.tagValue" : {
"$eq" : "multi"
}
}
]
},
"inputStage" : {
"stage" : "IXSCAN",
"keyPattern" : {
"_id" : 1
},
"indexName" : "_id_",
"isMultiKey" : false,
"multiKeyPaths" : {
"_id" : [ ]
},
"isUnique" : true,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 2,
"direction" : "forward",
"indexBounds" : {
"_id" : [
"(ObjectId('000000000000000000000000'), ObjectId('ffffffffffffffffffffffff')]"
]
}
}
}
}
而同样的是也扫描了100W+的记录数,于是大家认为可能索引的选择器出了问题,但就算是选择器的问题也仍然没办法解释线上出现的现象(线上的索引可是命中的)
为了一探究竟,我们使用 hint 强制让查询命中 appId_1_tags.tagName_1_tags.tagValue_1__id_1这个索引:
db.ApplicationDevice.find({
"appId":"Gf93VvCfOdttrxSOemt_03ff",
"tags.tagName":"pipeline","tags.tagValue":"multi",
_id:{$gt:ObjectId("000000000000000000000000")}})
.sort({"_id" : 1}).limit(10)
.hint("appId_1_tags.tagName_1_tags.tagValue_1__id_1")
.explain("executionStats")
这一次的结果显示确实命中了对应的索引:
"winningPlan" : {
"stage" : "SORT",
"sortPattern" : {
"_id" : 1.0
},
"limitAmount" : 10,
"inputStage" : {
"stage" : "SORT_KEY_GENERATOR",
"inputStage" : {
"stage" : "FETCH",
"filter" : {
"tags.tagValue" : {
"$eq" : "multi"
}
},
"inputStage" : {
"stage" : "IXSCAN",
"keyPattern" : {
"appId" : 1.0,
"tags.tagName" : 1.0,
"tags.tagValue" : 1.0,
"_id" : 1.0
},
"indexName" : "appId_1_tags.tagName_1_tags.tagValue_1__id_1"
...
"executionStats" : {
"executionSuccess" : true,
"nReturned" : 10,
"executionTimeMillis" : 3665,
"totalKeysExamined" : 1000002,
"totalDocsExamined" : 1000001,
"executionStages" : {
"stage" : "SORT",
"nReturned" : 10,
"executionTimeMillisEstimate" : 3513,
"works" : 1000014,
"sortPattern" : {
"_id" : 1.0
},
"memUsage" : 6660,
"memLimit" : 33554432,
"limitAmount" : 10,
"inputStage" : {
"stage" : "SORT_KEY_GENERATOR",
"nReturned" : 500001,
"executionTimeMillisEstimate" : 3333,
"works" : 1000003,
"advanced" : 500001,
"needTime" : 500001,
"inputStage" : {
"stage" : "FETCH",
"filter" : {
"tags.tagValue" : {
"$eq" : "multi"
}
},
"nReturned" : 500001,
"executionTimeMillisEstimate" : 3087,
"works" : 1000002,
"advanced" : 500001,
"needTime" : 500000,
"docsExamined" : 1000001,
"alreadyHasObj" : 0,
"inputStage" : {
"stage" : "IXSCAN",
"nReturned" : 1000001,
"executionTimeMillisEstimate" : 1117,
"works" : 1000002,
"advanced" : 1000001,
"keyPattern" : {
"appId" : 1.0,
"tags.tagName" : 1.0,
"tags.tagValue" : 1.0,
"_id" : 1.0
},
"indexName" : "appId_1_tags.tagName_1_tags.tagValue_1__id_1",
"isMultiKey" : true,
"multiKeyPaths" : {
"appId" : [],
"tags.tagName" : [
"tags"
],
"tags.tagValue" : [
"tags"
],
"_id" : []
},
"indexBounds" : {
"appId" : [
"[\"Gf93VvCfOdttrxSOemt_03ff\", \"Gf93VvCfOdttrxSOemt_03ff\"]"
],
"tags.tagName" : [
"[\"pipeline\", \"pipeline\"]"
],
"tags.tagValue" : [
"[MinKey, MaxKey]"
],
"_id" : [
"(ObjectId('000000000000000000000000'), ObjectId('ffffffffffffffffffffffff')]"
]
},
"keysExamined" : 1000002,
"dupsTested" : 1000001,
}
}
}
然而,在整个执行过程中(executionStats),出现了内存排序(SORT)。
而且,从一开始命中** appId_1_tags.tagName_1_tags.tagValue_1__id_1 **这个索引的阶段中,就已经扫描了100W条记录,简直不可思议!
但同时,我们也从indexBounds的指示中找到了端倪:
appId、tags.tagName 都命中了单值,在 tags.tagValue 的路径节点上却覆盖了全部范围!
由于中间索引节点出现了大范围覆盖,导致最终需要在内存中对大量的数据做 _id字段的排序,这个就是导致慢操作的原因!
解决问题
既然从前面的分析中找到了问题的来源,我们的推论如下:
- 既然索引的命中没有问题,那么导致大范围扫描的只可能是查询模式的问题。
再次拿出前面的查询条件:
{
appId: "Gf93VvCfOdttrxSOemt_03ff",
tags.tagName: "pipeline",
tags.tagValue: "multi",
_id: { $gt: ObjectId('000000000000000000000000')
}
在索引的匹配中,只能单键命中tags.tagName: “pipeline” 这一个条件,那么由于 tags是一个嵌套文档的数组,
对于上面的查询,语义上是指那些 包含某个元素 可命中tagName,且包含某个元素 可命中 tagValue的文档,这里面并不要求 同一个元素同时命中tagName和tagValue。
但 MongoDB 在嵌套数组索引的构建上是按照同一个元素的字段组合去构建的。 关于这点,可以参考下面的地址:
https://docs.mongodb.com/manual/core/index-multikey/#multikey-embedded-documents
对于数组元素的条件匹配,应该使用 $elemMatch,其用法可参考这里
为此,我们构建了下面的查询:
db.ApplicationDevice.find({
"appId":"Gf93VvCfOdttrxSOemt_03ff",
"tags": {$elemMatch: { "tagName":"pipeline","tagValue":"multi" }},
_id:{$gt:ObjectId("000000000000000000000000")}})
.sort({"_id" : 1}).limit(10)
.explain("executionStats")
执行后输出如下:
"winningPlan" : {
"stage" : "LIMIT",
"limitAmount" : 10,
"inputStage" : {
"stage" : "IXSCAN",
"keyPattern" : {
"appId" : 1.0,
"tags.tagName" : 1.0,
"tags.tagValue" : 1.0,
"_id" : 1.0
},
"indexName" : "appId_1_tags.tagName_1_tags.tagValue_1__id_1",
}
},
"executionStats" : {
"executionSuccess" : true,
"nReturned" : 10,
"executionTimeMillis" : 3,
"totalKeysExamined" : 10,
"totalDocsExamined" : 10,
"executionStages" : {
"stage" : "LIMIT",
"nReturned" : 10,
"inputStage" : {
"stage" : "FETCH",
"filter" : {...},
"nReturned" : 10,,
"inputStage" : {
"stage" : "IXSCAN",
"nReturned" : 10,
"executionTimeMillisEstimate" : 0,
"works" : 10,
"advanced" : 10,
"isEOF" : 0,
"indexName" : "appId_1_tags.tagName_1_tags.tagValue_1__id_1",
"isMultiKey" : true,
"indexBounds" : {
"appId" : [
"[\"Gf93VvCfOdttrxSOemt_03ff\", \"Gf93VvCfOdttrxSOemt_03ff\"]"
],
"tags.tagName" : [
"[\"pipeline\", \"pipeline\"]"
],
"tags.tagValue" : [
"[\"multi\", \"multi\"]"
],
"_id" : [
"(ObjectId('000000000000000000000000'), ObjectId('ffffffffffffffffffffffff')]"
]
}
...
这个结果是令人满意的,除了自动命中合适的索引之外,这个查询过程也达到了最优的路径匹配,扫描记录数才10条!
最后,根据该方案调整了查询模式,线上的问题得到恢复。
小结
看似很简单的一个查询语句,没想到会出现这么大的坑,其实无论是作为开发人员还是DBA,都应当谨慎对待你的SQL。
重要的事情说三遍!!! SQl查询上线前务必 explain、务必分析到位,这难道没有道理?
评论前必须登录!
注册