线上一个数组查询遇到的坑

背景

中午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、务必分析到位，这难道没有道理？

原文地址：https://www.cnblogs.com/littleatp/p/10686892.html

时间： 2024-08-19 09:07:04

线上一个数组查询遇到的坑的相关文章

线上一个简单检测Ping状态的邮件报警脚本

Step1.安装sendmail来发邮件 # yum -y install sendmail # /etc/init.d/sendmail start # chkconfig sendmail on Step2.安装邮件客户端 # yum -y install mutt 2.1添加发件人信息,如下 # vim /etc/Muttrc set charset="utf-8"           #设置发邮件编码 set envelope_from=yes set rfc2047_para

mysql线上一些隐患查询sql

开发写了几个语句,觉得查询结果跟逻辑有点不相符,就拿到这里一起分析了下. 语句如下: select tp.title, tp.amount, ifnull(sum(case when tu.type = 1 then ti.invest_amount else 0 end),0) as aInvestAmount, ifnull(sum(case when tu.type = 2 then ti.invest_amount else 0 end),0) as bInvestAmount, ifn

mysql线上一个定时备份脚本

mysql数据库远程备份的数据最好打包压缩 [[email protected] crontab]# pwd/Data/Mysql_Bakup/crontab[[email protected] crontab]# cat backup_db_wangshibo.sh#!/bin/bashMYSQL="/usr/bin/mysql"MYSQLDUMP="/usr/bin/mysqldump"BACKUP_DIR="/Data/Mysql_Bakup&quo

一次线上nohup.out日志丢失的问题

今天有小伙伴求助,线上一个应用的nohup.out日志不更新了,但进程还是正常的.此时需要查看这个日志排查一些问题,这可怎么办呢? nohup.out文件的更新时间停留在了昨天9点36,日志也刚好打到这个时间点. 但后面的日志去哪里了呢?这个问题就优点难办了,原因可能很多.比如不小心把文件删除了,或者重命名了. 那现在没时间找原因,能不能紧急把日志恢复呢?或者说在不重启进程的情况下,把日志找回来呢? 方法是有的,不过得从linux的/proc目录说起. 先来看看/proc目录的作用: /proc

Linux基础命令：（6）线上查询与文件阅读的命令

6.线上查询的命令:(1)man命令:用来查询和解释一个命令的使用方法以及这个命令的说明事项.[man 命令的名称](2)locate命令:定位文件和目录.(3)whatis命令:用来查询某个命令的含义[whatis 命令的名称]:比较适用 7.文件阅读的命令:(1)head命令:用来查看文件的开头部分.[head 文件名,默认是10行](2)tail命令:与head命令相反.有助于查看日志文件结尾的最后10行来阅读重要的系统信息. Linux基础命令:(6)线上查询与文件阅读的命令

一个SQL注释引发的线上问题

最近开始服务拆分,时间将近半个月.测试阶段也非常顺利,没有什么问题. 但上线之后的第二天,产品就风风火火的来找我们了,一看就是线上有什么问题.我们也不敢说,我们也不敢问,线上的后台商品忽然无法上架了,导致运营的同学删除商品后无法上架新的商品,导致APP的部分商品暂时不可见. 线上有问题,那么大家就开始迅速排查起来了.这里有一点要说一下,在上线前夕,产品临时添加一个新的需求,商品的搜索状态不可判断这个条件去掉,这个由于紧急而且对于我们来说也就是SQL中的一个条件的问题,也就没有经过测试,直接上线了

一个Flume线上问题的排查

最近在做一个分布式调用链跟踪系统, 在两个地方采用了flume ,一个是宿主系统 ,用flume agent进行日志搜集. 一个是从kafka拉日志分析后写入hbase. 后面这个flume(从kafka拉日志分析后写入flume)用了3台  , 系统上线以后 ,线上抛了一个这样的异常: Caused by: org.apache.flume.ChannelException: Put queue for MemoryTransaction of capacity 100 full, consi

创建一个数组，数组中保存一批量的学生信息，把该数组信息储存到磁盘上，并能解归档出来

/*2.创建一个数组,数组中保存一批量的学生信息,把该数组信息储存到磁盘上,并能解归档出来*/ #import <Foundation/Foundation.h>#define path @"/Users/qianfeng/Desktop/hehe/5.plist"int main(int argc, const char * argv[]) {    @autoreleasepool {                NSMutableArray *marray = [[

PHP 获取数组任意下标key的上一个prev和下一个next下标值

PHP 获取数组任意下标key的上一个prev和下一个next下标值 <?php $xoops[1] = '小'; $xoops[2] = '孩'; $xoops[3] = '子'; $xoops[4] = '气'; $steps = new Steps(); foreach($xoops as $key=>$value){ $steps->add($key); } $steps->setCurrent(3);//参数为key值 echo '上一个下标:'.$steps->g