释放双眼，带上耳机，听听看~！
背景
中午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、务必分析到位，这难道没有道理？
