MongoDB爱好者
垂直技术交流平台

谨防索引 seeks 的效率低下

背景

最近线上的一个工单分析服务一直不大稳定,监控平台时不时发出数据库操作超时的告警。
运维兄弟沟通后,发现在每天凌晨1点都会出现若干次的业务操作失败,而数据库监控上并没有发现明显的异常。
在该分析服务的日志中发现了某个数据库操作产生了 SocketTimeoutException

开发同学一开始希望通过调整 MongoDB Java Driver 的超时参数来规避这个问题。
但经过详细分析之后,这样是无法根治问题的,而且超时配置应该如何调整也难以评估。

下面是关于对这个问题的分析、调优的过程。

初步分析

从出错的信息上看,是数据库的操作响应超时了,此时客户端配置的 SocketReadTimeout 为 60s。
那么,是什么操作会导致数据库 60s 还没能返回呢?

业务操作

谨防索引seeks的效率低下-1

左边的数据库是一个工单数据表(t_work_order),其中记录了每张工单的信息,包括工单编号(oid)、最后修改时间(lastModifiedTime)
分析服务是Java实现的一个应用程序,在每天凌晨1:00 会拉取出前一天修改的工单信息(要求按工单号排序)进行处理。
由于工单表非常大(千万级),所以在处理时会采用分页的做法(每次取1000条),使用按工单号翻页的方式:

  • 第一次拉取
db.t_work_order.find({
   "lastModifiedTime":{
      $gt: new Date("2019-04-09T09:44:57.106Z"),
      $lt: new Date("2019-04-09T10:44:57.106Z")}, 
   "oid": {$exists: true}})
   .sort({"oid":1}).limit(1000)
  • 第二次拉取,以第一次拉取的最后一条记录的工单号作为起点
db.t_work_order.find({
   "lastModifiedTime":{
      $gt: new Date("2019-04-09T09:44:57.106Z"),
      $lt: new Date("2019-04-09T10:44:57.106Z")}, 
   "oid": {$exists: true, $gt: "VXZ190"}})
   .sort({"oid":1}).limit(1000)

..

根据这样的查询,开发人员给数据表使用的索引如下:

db.t_work_order.ensureIndexes({
   "oid" : 1,
   "lastModifiedTime" : -1
})

尽管该索引与查询字段基本是匹配的,但在实际执行时却表现出很低的效率:
第一次拉取时间非常的长,经常超过60s导致报错,而后面的拉取时间则会快一些

为了精确的模拟该场景,我们在测试环境中预置了小部分数据,对拉取记录的SQL执行Explain:

db.t_work_order.find({
   "lastModifiedTime":{
      $gt: new Date("2019-04-09T09:44:57.106Z"),
      $lt: new Date("2019-04-09T10:44:57.106Z")}
   "oid": {$exists: true}})
   .sort({"oid":1}).limit(1000)
   .explain("executionStats")

输出结果如下

"nReturned" : 1000,
"executionTimeMillis" : 589,
"totalKeysExamined" : 136661,
"totalDocsExamined" : 1000,

...

"indexBounds" : {
    "oid" : [ 
        "[MinKey, MaxKey]"
    ],
    "lastModifiedTime" : [ 
        "(new Date(1554806697106), new Date(1554803097106))"
    ]
},
"keysExamined" : 136661,
"seeks" : 135662,

在执行过程中发现,检索1000条记录,居然需要扫描 13.6 W条索引项!
其中,几乎所有的开销都花费在了 一个seeks操作上了。

索引seeks的原因

官方文档对于 seeks 的解释如下:
The number of times that we had to seek the index cursor to a new position in order to complete the index scan.

翻译过来就是:
seeks 是指为了完成索引扫描(stage),执行器必须将游标定位到新位置的次数。

我们都知道 MongoDB 的索引是B+树的实现(3.x以上),对于连续的叶子节点扫描来说是非常快的(只需要一次寻址),那么seeks操作太多则表示整个扫描过程中出现了大量的寻址(跳过非目标节点)。
而且,这个seeks指标是在3.4版本支持的,因此可以推测该操作对性能是存在影响的。

为了探究 seeks 是怎么产生的,我们对查询语句尝试做了一些变更:

去掉 exists 条件

exists 条件的存在是因为历史问题(一些旧记录并不包含工单号的字段),为了检查exists查询是否为关键问题,修改如下:

db.t_work_order.find({
   "lastModifiedTime":{
      $gt: new Date("2019-04-09T09:44:57.106Z"),
      $lt: new Date("2019-04-09T10:44:57.106Z")}
   })
   .sort({"oid":1}).limit(1000)
   .explain("executionStats")

执行后的结果为:

"nReturned" : 1000,
"executionTimeMillis" : 1533,
"totalKeysExamined" : 272322,
"totalDocsExamined" : 272322,

...

"inputStage" : {
  "stage" : "FETCH",
  "filter" : {
      "$and" : [ 
          {
              "lastModifiedTime" : {
                  "$lt" : ISODate("2019-04-09T10:44:57.106Z")
              }
          }, 
          {
              "lastModifiedTime" : {
                  "$gt" : ISODate("2019-04-09T09:44:57.106Z")
              }
          }
      ]
}, 

...

"indexBounds" : {
    "oid" : [ 
        "[MinKey, MaxKey]"
    ],
    "lastModifiedTime" : [ 
        "[MaxKey, MinKey]"
    ]
},
"keysExamined" : 272322,
"seeks" : 1,

这里发现,去掉 exists 之后,seeks 变成了1次,但整个查询扫描了 27.2W 条索引项! 刚好是去掉之前的2倍。
seeks 变为1次说明已经使用了叶节点顺序扫描的方式,然而由于扫描范围非常大,为了找到目标记录,会执行顺序扫描并过滤大量不符合条件的记录
在 FETCH 阶段出现了 filter可说明这一点。与此同时,我们检查了数据表的特征:同一个工单号是存在两条记录的!于是可以说明:

  • 在存在exists查询条件时,执行器会选择按工单号进行seeks跳跃式检索,如下图:

2

  • 在不存在exists条件的情况下,执行器选择了叶节点顺序扫描的方式,如下图:

3

gt 条件和反序

除了第一次查询之外,我们对后续的分页查询也进行了分析,如下:

db.t_work_order.find({
   "lastModifiedTime":{
      $gt: new Date("2019-04-09T09:44:57.106Z"),
      $lt: new Date("2019-04-09T10:44:57.106Z")}, 
   "oid": {$exists: true, $gt: "VXZ190"}})
   .sort({"oid":1}).limit(1000)
   .explain("executionStats")

上面的语句中,主要是增加了$gt: “VXZ190”这一个条件,执行过程如下:

"nReturned" : 1000,
"executionTimeMillis" : 6,
"totalKeysExamined" : 1004,
"totalDocsExamined" : 1000,

...

"indexBounds" : {
    "oid" : [ 
        "(\"VXZ190\", {})"
    ],
    "lastModifiedTime" : [ 
        "(new Date(1554806697106), new Date(1554803097106))"
    ]
},
"keysExamined" : 1004,
"seeks" : 5,

可以发现,seeks的数量非常少,而且检索过程只扫描了1004条记录,效率是很高的。
那么,是不是意味着在后面的数据中,满足查询的条件的记录非常密集呢?

为了验证这一点,我们将一开始第一次分页的查询做一下调整,改为按工单号降序的方式(从后往前扫描):

db.t_work_order.find({
   "lastModifiedTime":{
      $gt: new Date("2019-04-09T09:44:57.106Z"),
      $lt: new Date("2019-04-09T10:44:57.106Z")}, 
   "oid": {$exists: true}})
   .sort({"oid":-1}).limit(1000)
   .explain("executionStats")

新的”反序查询语句”的执行过程如下:

"nReturned" : 1000,
"executionTimeMillis" : 6,
"totalKeysExamined" : 1001,
"totalDocsExamined" : 1000,

...

"direction" : "backward",
"indexBounds" : {
    "oid" : [ 
        "[MaxKey, MinKey]"
    ],
    "lastModifiedTime" : [ 
        "(new Date(1554803097106), new Date(1554806697106))"
    ]
},
"keysExamined" : 1001,
"seeks" : 2,

可以看到,执行的效率更高了,几乎不需要什么 seeks 操作!
经过一番确认后,我们获知了在所有数据的分布中,工单号越大的记录其更新时间值也越大,基本上我们想查询的目标数据都集中在尾端

于是就会出现一开始提到的,第一次查询非常慢甚至超时,而后面的查询就快了。

上面提到的两个查询执行路线如图所示:

  • 加入$gt 条件,从中间开始检索

4

  • 反序,从后面开始检索

5

优化思路

通过分析,我们知道了问题的症结在于索引的扫描范围过大,那么如何优化,以避免扫描大量记录呢?
从现有的索引及条件来看,由于同时存在gt、exists以及叶子节点的时间范围限定,不可避免的会产生seeks操作,
而且查询的性能是不稳定的,跟数据分布、具体查询条件都有很大的关系
于是一开始所提到的仅仅是增加 socketTimeout 的阈值可能只是治标不治本,一旦数据的索引值分布变化或者数据量持续增大,可能会发生更严重的事情。

回到一开始的需求场景,定时器要求读取每天更新的工单(按工单号排序),再进行分批处理
那么,按照化零为整的思路,新增一个lastModifiedDay字段,这个存储的就是lastModifiedTime对应的日期值(低位取整),这样在同一天内更新的工单记录都有同样的值。

建立组合索引 {lastModifiedDay:1, oid:1},相应的查询条件改为:

{
  "lastModifiedDay": new Date("2019-04-09 00:00:00.000"),
  "oid": {$gt: "VXZ190"}
}  
-- limit 1000

执行结果如下:

"nReturned" : 1000,
"executionTimeMillis" : 6,
"totalKeysExamined" : 1000,
"totalDocsExamined" : 1000,

...

"indexBounds" : {
    "lastModifiedDay" : [ 
        "(new Date(1554803000000), new Date(1554803000000))"
    ],
    "oid" : [ 
        "(\"VXZ190\", {})"
    ]
},
"keysExamined" : 1000,
"seeks" : 1,

这样优化之后,每次查询最多只扫描1000条记录,查询速度是非常快的!

小结

本质上,这就是一种空间换时间的方法,即通过存储一个额外的索引字段来加速查询,通过增加少量的存储开销提升了整体的效能。
在对于许多问题进行优化时,经常是需要从应用场景触发,适当的转换思路。
比如在本文的问题中,是不是一定要增加字段呢?如果业务上可以接受不按工单号排序进行读取,那么仅使用更新时间字段进行分页拉取也是可以达到效果的,具体还是要由业务场景来定。

赞(2)
未经允许不得转载:MongoDB中文社区 » 谨防索引 seeks 的效率低下

评论 5

评论前必须登录!

 

  1. #1

    「查询的性能是不稳定的,跟数据分布、具体查询条件都有很大的关系。」

    感觉笔者的推论有些问题——

    你的索引顺序{"oid" : 1, "lastModifiedTime" : -1}

    第1次查询,因为你查询条件2个字段与索引相符,IXSCAN阶段就完成了“过滤”,所以你explain看FETCH阶段是不包含filter。
    而你索引应该不是稀疏索引,你也说了「因为历史问题(一些旧记录并不包含工单号的字段)」,遍历索引page所以seeks值大。
    db.t_work_order.find({
    "lastModifiedTime":{
    $gt: new Date("2019-04-09T09:44:57.106Z"),
    $lt: new Date("2019-04-09T10:44:57.106Z")},
    "oid": {$exists: true}})
    .sort({"oid":1}).limit(1000)

    第2次查询,比第1次去掉"oid": {$exists: true}条件,seeks变成1次是因为查询条件不满足最左匹配,但符合排序条件所以IXSCAN阶段keysExamined等于全量,FETCH阶段filter需要遍历的文档数和COLLSCAN一样。

    第3次查询,比第1次多了oid: {$gt: “VXZ190”}条件,seeks和keysExamined(比第一次)变少很多,不是因为「在后面的数据中,满足查询的条件的记录非常密集」,
    而是因为新加的oid查询条件在IXSCAN阶段已经过滤了大部分数据,换句话说符合$gt: “VXZ190”条件的数据就那么几条,从"totalKeysExamined" : 1004,"totalDocsExamined" : 1000就能看出来。

    第4次查询,建立组合索引 {lastModifiedDay:1, oid:1},查询条件变成"lastModifiedDay": new Date("2019-04-09 00:00:00.000"),"oid": {$gt: "VXZ190"}
    这个当然快啦,这个是(E)等值查询,lastModifiedDay相等的情况下二级oid字段索引内有序,所以使用索引排序,符合ESR原则。

    其中比较容易误导读者的我觉得是「查询的性能是不稳定的,跟数据分布、具体查询条件都有很大的关系」这句话,这句话本身没问题,但在你的上下文里不是同一个问题。

    Jhown_deng3个月前 (06-22)
    • 感谢关注!
      这篇文章讲述了此前的一次索引优化,更多的是从现象入手去分析数据库潜在的行为。
      你的解读也比较详细了,这里补充几点说明:
      1. “查询的性能是不稳定的”,这点不是推论,而是从业务接口上观测到分页性能是不稳定的。
      2. 回复中的第一、第二次查询和本次分析也是一致的。
      3. 第三次查询,oid: {$gt: “VXZ190”}这个条件下,seeks和keysExamined大幅度减少,
      是因为所增加的条件在IXSCAN阶段提供了锚点(相比第一次查询),而从锚点之后扫描到的数据都是目标数据,正如所描述的:”后面的数据中,满足查询的条件的记录非常密集”,最终在limit限定符的作用下,很快返回了结果。也就是说第一次、第三次查询的行为比较类似(主要都走的IXSCAN),而第三次得益于一个好的起点。

      zale3个月前 (06-24)
      • 感谢笔者的回复,看完反思我的评论,感觉之前没把问题描述清楚,这里再稍补充说明下:
        第1、2次查询我们的表述程度不一样,在文中“exists存在与否,会影响seeks的大小”本身没问题,但有些不完善,容易理解成问题只和$exists有关;
        对我之前评论补充下,我认为换任何查询条件都一样,应该是【基于最左匹配原则,看索引字段是否满足查询、排序条件】,如果满足查询条件seeks就有可能很大,如果只满足排序条件则seeks=1。
        第3次查询,关于「在后面的数据中,满足查询的条件的记录非常密集」笔者的原文和回复都没问题,是我没表述清楚我的出发点——“尽量把问题本质描述清楚,帮助他人理解”。
        个人总结文中的问题:"为什么加了 $gt: VXZ190后,seeks变少了?"
        我的思考是:
        "oid": {$exists:true}时seeks很大,"oid": {$exists: true, $gt: "VXZ190"}比之变少,换成第4次查询的"lastModifiedDay": new Date("2019-04-09 00:00:00.000")时seeks更少等于1了。
        本质原因是【多字段组合查询命中复合索引时,对应索引最左字段的过滤结果越准确,seeks值越小,也就是索引阶段性能越好】,原理其实还是"最左匹配原则"。
        ps: {$exists: true, $gt: "VXZ190"}在大于($gt/gte)的情况下与不写$exists条件是等价的,因为mongo中字段不存在的排在正序“最前面”。

        Jhown_deng3个月前 (06-24)
  2. #2

    第2次查询,比第1次去掉"oid": {$exists: true}条件,seeks变成1次是因为查询条件不满足最左匹配,但符合排序条件所以IXSCAN阶段keysExamined等于全量,FETCH阶段filter需要遍历的文档数和COLLSCAN一样。
    第3次查询,比第1次多了oid: {$gt: “VXZ190”}条件,seeks和keysExamined(比第一次)变少很多,不是因为「在后面的数据中,满足查询的条件的记录非常密集」,
    而是因为新加的oid查询条件在IXSCAN阶段已经过滤了大部分数据,换句话说符合$gt: “VXZ190”条件的数据就那么几条,从"totalKeysExamined" : 1004,"totalDocsExamined" : 1000就能看出来。
    第4次查询,建立组合索引 {lastModifiedDay:1, oid:1},查询条件变成"lastModifiedDay": new Date("2019-04-09 00:00:00.000"),"oid": {$gt: "VXZ190"}
    这个当然快啦,这个是(E)等值查询,lastModifiedDay相等的情况下二级oid字段索引内有序,所以使用索引排序,符合ESR原则。
    其中比较容易误导读者的我觉得是「查询的性能是不稳定的,跟数据分布、具体查询条件都有很大的关系」这句话,这句话本身没问题,但在你的上下文里不是同一个问题。

    Jhown_deng3个月前 (06-22)