性能差

性能差

Elasticsearch took和实测的耗时差异大,qps低

Elasticsearchcwn1986 回复了问题 • 3 人关注 • 3 个回复 • 294 次浏览 • 2018-06-04 15:43 • 来自相关话题

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

Elasticsearchkennywu76 发表了文章 • 2 个评论 • 1679 次浏览 • 2017-09-29 19:18 • 来自相关话题

【携程旅行网 吴晓刚】

注:本文是针对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带来的性能问题。

ES 5.4+ 引起的Kibana性能问题

Elasticsearchkennywu76 发表了文章 • 7 个评论 • 1490 次浏览 • 2017-09-11 18:22 • 来自相关话题

【携程旅行网  吴晓刚】

上周有用户在社区发了一例Kibana读取超时的问题:question#2319 。周末找时间帮其调查了下,发现某些较新的ES版本和Kibana搭配,会产生意想不到的缓慢问题。 考虑到这个问题比较普遍,因此在这里总结一下问题的根源和解决办法,希望用到问题版本的用户不要踩到坑。

首先问题的现象在上面的问题链接里有描述,简而言之就是对于一个硬件配置比较高的集群,每天写入一个20亿左右数据的索引,通过kibana的discovery面板查看数据会一直超时。即使时间范围放到最近半小时,超时依旧,有些蹊跷。

周末拿到用户给的测试账号,登陆集群看了下状态。 从机器的硬件配置,集群和索引的配置看,没找到什么特别不对劲的地方。然而点击到Discovery面板,的确数据显示不出来。  集群监控数据看,并没有其他用户在做查询,cpu利用率和集群负载都比较低。因此初步可以判定,就是查询本身比较缓慢所致。

对于诊断查询缓慢问题,我通常的做法,就是将对应面板下的查询拷贝出来,在Kibana Dev Console里手动执行,然后再加上"profile":true选项,看看查询是如何解析和执行的。对应的查询形如下面这样:

{
  "profile": true,
  "query": {
    "bool": {
      "must": [
        {
          "query_string": {
            "analyze_wildcard": true,
            "query": "*"
          }
        },
        {
          "range": {
            "@timestamp": {
              "gte": "now-1h",
              "lte": "now",
              "format": "epoch_millis"
            }
          }
        }
      ]
    }
  }
}

因为用户query框什么都没有输入,因此默认查询串被Kibana设置为*, 然后根据选择的时间范围加了一个range查询。  profile的输出让我稍微有些吃惊,其中 query_string的里的*居然被解析成非常复杂的DisjunctionMaxQuery,主要查询耗时都在这里了。

{
                    "type": "DisjunctionMaxQuery",
                    "description": "(ConstantScore(_field_names:remote_addr.keyword) | ConstantScore(_field_names:geoip.country_isocode) | ConstantScore(_field_names:geoip.country_name.keyword) | ConstantScore(_field_names:via) | ConstantScore(_field_names:domain.keyword) | ConstantScore(_field_names:request_method.keyword) | ConstantScore(_field_names:protocol) | ConstantScore(_field_names:xff.keyword) | ConstantScore(_field_names:host) | ConstantScore(_field_names:geoip.city_name.keyword) | ConstantScore(_field_names:client_ip) | ConstantScore(_field_names:host.keyword) | ConstantScore(_field_names:geoip.longitude) | ConstantScore(_field_names:geoip.subdivision_name.keyword) | ConstantScore(_field_names:geoip.country_code) | ConstantScore(_field_names:upstream_addr.keyword) | ConstantScore(_field_names:@version.keyword) | ConstantScore(_field_names:request_uri) | ConstantScore(_field_names:tags) | ConstantScore(_field_names:idc_tag) | ConstantScore(_field_names:size) | ConstantScore(_field_names:http_referer) | ConstantScore(_field_names:message.keyword) | ConstantScore(_field_names:domain) | ConstantScore(_field_names:geoip.latitude) | ConstantScore(_field_names:xff) | ConstantScore(_field_names:protocol.keyword) | ConstantScore(_field_names:geoip.country_code.keyword) | ConstantScore(_field_names:status) | ConstantScore(_field_names:upstream_addr) | ConstantScore(_field_names:http_referer.keyword) | ConstantScore(_field_names:tags.keyword) | ConstantScore(_field_names:client_ip.keyword) | ConstantScore(_field_names:request_method) | ConstantScore(_field_names:upstream_status) | ConstantScore(_field_names:request_time) | ConstantScore(_field_names:geoip.location) | ConstantScore(_field_names:@version) | ConstantScore(_field_names:geoip.country_name) | ConstantScore(_field_names:user_agent) | ConstantScore(_field_names:idc_tag.keyword) | ConstantScore(_field_names:remote_addr) | ConstantScore(_field_names:geoip.country_isocode.keyword) | ConstantScore(_field_names:geoip.city_name) | ConstantScore(_field_names:via.keyword) | ConstantScore(_field_names:message) | ConstantScore(_field_names:user_agent.keyword) | ConstantScore(_field_names:request_uri.keyword) | ConstantScore(_field_names:@timestamp) | ConstantScore(_field_names:upstream_response_time) | ConstantScore(_field_names:geoip.subdivision_name))",
                    "time": "5535.127008ms",
                    "time_in_nanos": 5535127008

也就是说, ES将只含一个*query_string query解析成了针对mapping里能找到的所有字段的field:*查询,然后合并所有的查询结果。  可想而知,对于比较大,字段比较多的索引这个查询是非常耗时的。而我对于*的认知,是其应该被rewrite成一个match_all query即可,这样几乎没有什么开销。

为什么会这样? 查询了一下ES官方关于Query String Query的文档,其中的default_field和all_fields起到了一定作用:  elasticsearch/reference/5.5/query-dsl-query-string-query.html

default_field

The default field for query terms if no prefix field is specified. Defaults to the index.query.default_field index settings, which in turn defaults to _all.

all_fields

Perform the query on all fields detected in the mapping that can be queried. Will be used by default when the _all field is disabled and no default_field is specified (either in the index settings or in the request body) and no fields are specified.

根据解释,查询的时候可以带一个default_field选项,其默认值为索引级别设置index.query.default_field,如果这个设置没有设置,则默认为_all。  但一般用户索引日志的时候,都会关掉_all字段,用于节省磁盘空间,提升索引速率。那么这时候default_field是什么呢?  答案是all_fields,也就是ES会将查询转换为对所有字段的查询。

为了验证这个是问题所在,我在索引里加了一个default_field的设置,随意挑选了一个字段。 果然问题就解决了,discovery面板渲染速度快了差不多有10倍。

但仔细想想,这也只是绕过了问题。 问题的根源,为什么*不被rewrite成match_all呢? 

这时候想到我们自己生产的集群似乎没有这个问题,于是用我们自己的集群测试了一下,*果然是正常解析成match_all了。 于是对比了一下集群ES的版本,我们正常工作的是5.3.2,用户的集群是5.5.0

接下来,我想找到这些版本之间,ES对于query string的解析源码层面做了什么改动。经过一番探查,找到了下面这个变更历史:

1.png
2.png

可以看到,在pull/23433里,为了修复一个foo:*解析歧义的问题,对于field为空,类似光一个*的Query string查询,不再被解析成match_all了,而是扩展成全部字段的DisjunctionMaxQuery查询。 由此Kibana默认的*,会引起非常严重的性能问题。

这个问题会影响5.4和5.5两个小版本的ES/Kibana。

顺着这个issue里的链接摸下去,找到了对应Kibana相关问题讨论:issues#12097,以及对应的修复: pull/13047,修复版本默认发出的查询串是match all

修复的版本则是5.5.25.6.0, 因此有用到5.4.05.5.1之间版本的ELK用户一定要安排升级!

elasticSearch用PHP加载vendor开发接口 压测报异常

回复

Elasticsearchinnervision 发起了问题 • 1 人关注 • 0 个回复 • 2082 次浏览 • 2017-04-12 13:25 • 来自相关话题

elasticsearch小文件入库

回复

Elasticsearchlinyongzhi 发起了问题 • 1 人关注 • 0 个回复 • 2323 次浏览 • 2017-02-14 17:58 • 来自相关话题

Elasticsearch took和实测的耗时差异大,qps低

回复

Elasticsearchcwn1986 回复了问题 • 3 人关注 • 3 个回复 • 294 次浏览 • 2018-06-04 15:43 • 来自相关话题

elasticSearch用PHP加载vendor开发接口 压测报异常

回复

Elasticsearchinnervision 发起了问题 • 1 人关注 • 0 个回复 • 2082 次浏览 • 2017-04-12 13:25 • 来自相关话题

elasticsearch小文件入库

回复

Elasticsearchlinyongzhi 发起了问题 • 1 人关注 • 0 个回复 • 2323 次浏览 • 2017-02-14 17:58 • 来自相关话题

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

Elasticsearchkennywu76 发表了文章 • 2 个评论 • 1679 次浏览 • 2017-09-29 19:18 • 来自相关话题

【携程旅行网 吴晓刚】

注:本文是针对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带来的性能问题。

ES 5.4+ 引起的Kibana性能问题

Elasticsearchkennywu76 发表了文章 • 7 个评论 • 1490 次浏览 • 2017-09-11 18:22 • 来自相关话题

【携程旅行网  吴晓刚】

上周有用户在社区发了一例Kibana读取超时的问题:question#2319 。周末找时间帮其调查了下,发现某些较新的ES版本和Kibana搭配,会产生意想不到的缓慢问题。 考虑到这个问题比较普遍,因此在这里总结一下问题的根源和解决办法,希望用到问题版本的用户不要踩到坑。

首先问题的现象在上面的问题链接里有描述,简而言之就是对于一个硬件配置比较高的集群,每天写入一个20亿左右数据的索引,通过kibana的discovery面板查看数据会一直超时。即使时间范围放到最近半小时,超时依旧,有些蹊跷。

周末拿到用户给的测试账号,登陆集群看了下状态。 从机器的硬件配置,集群和索引的配置看,没找到什么特别不对劲的地方。然而点击到Discovery面板,的确数据显示不出来。  集群监控数据看,并没有其他用户在做查询,cpu利用率和集群负载都比较低。因此初步可以判定,就是查询本身比较缓慢所致。

对于诊断查询缓慢问题,我通常的做法,就是将对应面板下的查询拷贝出来,在Kibana Dev Console里手动执行,然后再加上"profile":true选项,看看查询是如何解析和执行的。对应的查询形如下面这样:

{
  "profile": true,
  "query": {
    "bool": {
      "must": [
        {
          "query_string": {
            "analyze_wildcard": true,
            "query": "*"
          }
        },
        {
          "range": {
            "@timestamp": {
              "gte": "now-1h",
              "lte": "now",
              "format": "epoch_millis"
            }
          }
        }
      ]
    }
  }
}

因为用户query框什么都没有输入,因此默认查询串被Kibana设置为*, 然后根据选择的时间范围加了一个range查询。  profile的输出让我稍微有些吃惊,其中 query_string的里的*居然被解析成非常复杂的DisjunctionMaxQuery,主要查询耗时都在这里了。

{
                    "type": "DisjunctionMaxQuery",
                    "description": "(ConstantScore(_field_names:remote_addr.keyword) | ConstantScore(_field_names:geoip.country_isocode) | ConstantScore(_field_names:geoip.country_name.keyword) | ConstantScore(_field_names:via) | ConstantScore(_field_names:domain.keyword) | ConstantScore(_field_names:request_method.keyword) | ConstantScore(_field_names:protocol) | ConstantScore(_field_names:xff.keyword) | ConstantScore(_field_names:host) | ConstantScore(_field_names:geoip.city_name.keyword) | ConstantScore(_field_names:client_ip) | ConstantScore(_field_names:host.keyword) | ConstantScore(_field_names:geoip.longitude) | ConstantScore(_field_names:geoip.subdivision_name.keyword) | ConstantScore(_field_names:geoip.country_code) | ConstantScore(_field_names:upstream_addr.keyword) | ConstantScore(_field_names:@version.keyword) | ConstantScore(_field_names:request_uri) | ConstantScore(_field_names:tags) | ConstantScore(_field_names:idc_tag) | ConstantScore(_field_names:size) | ConstantScore(_field_names:http_referer) | ConstantScore(_field_names:message.keyword) | ConstantScore(_field_names:domain) | ConstantScore(_field_names:geoip.latitude) | ConstantScore(_field_names:xff) | ConstantScore(_field_names:protocol.keyword) | ConstantScore(_field_names:geoip.country_code.keyword) | ConstantScore(_field_names:status) | ConstantScore(_field_names:upstream_addr) | ConstantScore(_field_names:http_referer.keyword) | ConstantScore(_field_names:tags.keyword) | ConstantScore(_field_names:client_ip.keyword) | ConstantScore(_field_names:request_method) | ConstantScore(_field_names:upstream_status) | ConstantScore(_field_names:request_time) | ConstantScore(_field_names:geoip.location) | ConstantScore(_field_names:@version) | ConstantScore(_field_names:geoip.country_name) | ConstantScore(_field_names:user_agent) | ConstantScore(_field_names:idc_tag.keyword) | ConstantScore(_field_names:remote_addr) | ConstantScore(_field_names:geoip.country_isocode.keyword) | ConstantScore(_field_names:geoip.city_name) | ConstantScore(_field_names:via.keyword) | ConstantScore(_field_names:message) | ConstantScore(_field_names:user_agent.keyword) | ConstantScore(_field_names:request_uri.keyword) | ConstantScore(_field_names:@timestamp) | ConstantScore(_field_names:upstream_response_time) | ConstantScore(_field_names:geoip.subdivision_name))",
                    "time": "5535.127008ms",
                    "time_in_nanos": 5535127008

也就是说, ES将只含一个*query_string query解析成了针对mapping里能找到的所有字段的field:*查询,然后合并所有的查询结果。  可想而知,对于比较大,字段比较多的索引这个查询是非常耗时的。而我对于*的认知,是其应该被rewrite成一个match_all query即可,这样几乎没有什么开销。

为什么会这样? 查询了一下ES官方关于Query String Query的文档,其中的default_field和all_fields起到了一定作用:  elasticsearch/reference/5.5/query-dsl-query-string-query.html

default_field

The default field for query terms if no prefix field is specified. Defaults to the index.query.default_field index settings, which in turn defaults to _all.

all_fields

Perform the query on all fields detected in the mapping that can be queried. Will be used by default when the _all field is disabled and no default_field is specified (either in the index settings or in the request body) and no fields are specified.

根据解释,查询的时候可以带一个default_field选项,其默认值为索引级别设置index.query.default_field,如果这个设置没有设置,则默认为_all。  但一般用户索引日志的时候,都会关掉_all字段,用于节省磁盘空间,提升索引速率。那么这时候default_field是什么呢?  答案是all_fields,也就是ES会将查询转换为对所有字段的查询。

为了验证这个是问题所在,我在索引里加了一个default_field的设置,随意挑选了一个字段。 果然问题就解决了,discovery面板渲染速度快了差不多有10倍。

但仔细想想,这也只是绕过了问题。 问题的根源,为什么*不被rewrite成match_all呢? 

这时候想到我们自己生产的集群似乎没有这个问题,于是用我们自己的集群测试了一下,*果然是正常解析成match_all了。 于是对比了一下集群ES的版本,我们正常工作的是5.3.2,用户的集群是5.5.0

接下来,我想找到这些版本之间,ES对于query string的解析源码层面做了什么改动。经过一番探查,找到了下面这个变更历史:

1.png
2.png

可以看到,在pull/23433里,为了修复一个foo:*解析歧义的问题,对于field为空,类似光一个*的Query string查询,不再被解析成match_all了,而是扩展成全部字段的DisjunctionMaxQuery查询。 由此Kibana默认的*,会引起非常严重的性能问题。

这个问题会影响5.4和5.5两个小版本的ES/Kibana。

顺着这个issue里的链接摸下去,找到了对应Kibana相关问题讨论:issues#12097,以及对应的修复: pull/13047,修复版本默认发出的查询串是match all

修复的版本则是5.5.25.6.0, 因此有用到5.4.05.5.1之间版本的ELK用户一定要安排升级!