三人行必有我师

一例Query Cache引起的性能问题分析

Elasticsearch | 作者 kennywu76 | 发布于2017年09月29日 | | 阅读数:8258

【携程旅行网 吴晓刚】

注:本文是针对Elastic中文社区问题question#2484 的分析和总结。

问题概述

一个线上集群,执行的Query DSL都是一样的,只是参数不同。 统计数据显示98-99%的查询响应速度都很快,只需要4 -6ms, 但有1%左右的查询响应时间在100ms - 200ms。 集群硬件配置较高,使用的SSD,系统可用内存远高于索引文件大小总和,并且线上已经运行有一段时间,数据应该已经充分预热。


诊断过程及结论

比较巧的是,问题提出者刚好是我们自家公司的开发者,因此内部联系沟通了下,为问题的快速诊断提供了不少便利。

首先用公司的监控系统排查了一遍集群所有关键数据,未发现任何可能引起查询耗时高的性能瓶颈问题。 因此初步怀疑就是有查询本身比较慢。 幸好公司有应用埋点系统和日志系统,因此很方便的拿到了应用端发出的一些慢查询样例,包括请求体以及耗时。

以下是埋点系统里记录的一个耗时150ms的查询 (隐去了敏感信息,去掉了非关键部分):

POST /xxxindex/xxxdb/_search?routing=Mxxxxxxx
{
  "from": 0,
  "size": 100,
  "query": {
    "bool": {
      "filter": [
        {
          "bool": {
            "must": [
              {
                "bool": {
                  "must": [
                    {
                      "bool": {
                        "should": [
                          {
                            "match_phrase": {
                              "ord_orders_uid": {
                                "query": "Mxxxxxxx",
                                "slop": 0,
                                "boost": 1
                              }
                            }
                          }
                        ],
                        "disable_coord": false,
                        "adjust_pure_negative": true,
                        "boost": 1
                      }
                    },
                    {
                      "range": {
                        "ord_orders_orderdate": {
                          "from": "1405032032",
                          "to":   "1504014193",
                          "include_lower": true,
                          "include_upper": true,
                          "boost": 1
                        }
                      }
                    },
                    {
                      "term": {
                        "ord_orders_ispackageorder": {
                          "value": 0,
                          "boost": 1
                        }
                      }
                    },
                    {
                      "bool": {
                        "must_not": [
                          {
                            "exists": {
                              "field": "ord_hideorder_orderid",
                              "boost": 1
                            }
                          }
                        ],
                        "disable_coord": false,
                        "adjust_pure_negative": true,
                        "boost": 1
                      }
                    }
                  ],
                  "disable_coord": false,
                  "adjust_pure_negative": true,
                  "boost": 1
                }
              }
            ],
            "disable_coord": false,
            "adjust_pure_negative": true,
            "boost": 1
          }
        }
      ],
      "disable_coord": false,
      "adjust_pure_negative": true,
      "boost": 1
    }
  }
}

拿到查询后,自己手动执行了一下,0 hits,耗时1ms。  心里明白,命中了Query Cache,所以才会这么快。 

于是用clear api清掉Query Cache,然后再执行几次,有以下发现:

  • 头两次查询耗时38ms左右。 这是因为没有cache,需要访问倒排索引,耗时符合预期。 之所以两次同样耗时,是因为索引有1个复制片,两次查询分别分配到主和副片上。
  • 接下来两次查询耗时150ms左右。  这里要打一个大大的问号???
  • 之后不管再查询多少次, 耗时全部是1ms,因为又开始命中Cache。

至此,大致明白,埋点系统里记录到的高耗时查询,是步骤2的两次操作。 什么操作耗时这么久呢? 根据经验,我判断主要是用于为range filter生成缓存,也就生成生成文档列表的bitmap,然后存放到Query Cache里。 

这个集群版本是5.1.1, 而我记得ES某个5版本开始,去掉了对term filter的cache,理由是term filter速度足够快,缓存term filter往往得不偿失。 查了官方release notes,证实这个改变正好是从5.1.1开始的#21566,因此上面查询里的term filters被排除掉,注意力集中到了查询里唯一的一个range filter。 

单独执行了一下这个range filter,match的文档是千万数量级的。 询问用户,为何这个range filter会hit这么多文档,得知用户主要就是查询从当前时间开始至过去1年的数据,类似于做了一个now-1y  TO now这样的过滤。至此初步得出结论,因为这个range filter匹配的文档太多了,在Query Cache里为这个filter构建bitmap耗时会有些高,应该就是它带来了那额外的100多个ms。

但是还有一个待解释的问题,这种高耗时查询比例为何这么高? 再仔细想想也就明白了:因为这个集群的搜索并发量还是有点高,300 -400/s的样子,加上时间字段的精度是秒,所以,在某一秒刚开始的时候,头2次查询因为没有cache,耗时可能在38ms左右,之后会有2次查询因为需要缓存range filter,耗时会增加到150-200ms的样子,之后这1秒里剩余的查询都会命中cache,全部是几个ms, 直到下一秒开始, 周而复始。 因为每秒钟都产生2个这样需要构建缓存的查询,耗时较高,对比每秒几百次的查询量,换算成百分比就有点高了。

那么怎么解决这个问题? 对于大量含有从now-xxx TO now这样的range查询,实际上官方的文档有对应的加速技巧介绍:tune-for-search-speed.html#_search_rounded_dates 。也就是说,将查询时间的上下限round到整分钟,或者整小时,让range filter可以缓存得更久,避免出现这种过于频繁重建cache的情况。

{
   "range": {
       "my_date": {
       "gte": "now-1y/h",
        "lte": "now-1y/h"
      }
    }
}

在原始Query里,将range filter写成上述形式,手动测试证实可行,range filter有效期延长到1小时,从而每个小时里,只需要为range filter重建2次Cache,至此问题解决。


总结:

  1. Cache并非建得越多越好,因为Cache的生成和Evict会带来额外的开销。特别是结果集非常大的filter,缓存的代价相对查询本身可能非常高。
  2. ES 5.1.1开始取消了Terms filter Cache,因为Terms filter执行非常快,取消缓存多数情况下反而可以提高性能。
  3. 大量用到Now-xxxd To Now这样的Range filter时,可以借助round date技巧,提高Cache的有效期,减轻频繁重建Cache带来的性能问题。

[尊重社区原创,转载请保留或注明出处]
本文地址:http://elasticsearch.cn/article/304


6 个评论

大拿的文章真是受益匪浅啊
受益匪浅啊!
想请教一下,filter过滤的话,还需要内嵌must吗?
filter内部可以用数组定义一组过滤条件,不需要内嵌must。
是的,看上去这个查询must比较多余,thks
这里讨论的 query cache 所消耗的内存空间 应该是由属于ES进程的堆内内存吧?就是说:如果这些缓存失效了,会由gc线程回收掉。
那像这种按时间范围查询,如果没有 采用 "将查询时间的上下限round到整分钟" 优化,过于频繁的重建query cache 就会导致 young gc 次数增多吧(假设是CMS垃圾回收器)。
请教,我的理解有错吗?

要回复文章请先登录注册