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

心已赠人 2023-06-28 11:27 21阅读 0赞

> 注：本文是针对Elastic中文社区问题[question\#2484][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][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][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带来的性能问题。

文章来源：[https://elasticsearch.cn/article/304][https_elasticsearch.cn_article_304]

[question_2484]: https://elasticsearch.cn/question/2484
[21566]: https://github.com/elastic/elasticsearch/pull/21566
[tune-for-search-speed.html_search_rounded_dates]: https://www.elastic.co/guide/en/elasticsearch/reference/current/tune-for-search-speed.html#_search_rounded_dates
[https_elasticsearch.cn_article_304]: https://elasticsearch.cn/article/304