Profiling Queries

注意

Profile API 提供的详细信息直接暴露了Lucene的类名和概念,这意味着对结果的完整解释需要Lucene相当高级的知识。本页试图对Lucene如何执行查询提供速成教程,以便您可以成功地使用Profile API诊断和调试查询,但它只是一个概述。如需完整的理解,请参考Lucene对应位置的文档和代码。

也就是说,处理一个缓慢的查询往往不需要完整理解Lucene。例如,我们普遍知道某个特定的查询组件很缓慢,但不一定理解为什么该查询的advance前阶段是诱因。

查询部分/query Section

查询部分(query)包含由Lucene在一个特定的分块执行生成的查询树的详细时序。这个查询树的整体结构类似于原来的Elasticsearch查询,但可能会略有不同(偶尔会差异很大)。它也将使用类似但不总是相同的命名。使用我们以前的匹配查询(match)示例,让我们分析查询部分(query):

"query": [
    {
       "type": "BooleanQuery",
       "description": "message:message message:number",
       "time": "1.873811000ms",
       "time_in_nanos": "1873811",
       "breakdown": {...},          (1)     
       "children": [
          {
             "type": "TermQuery",
             "description": "message:message",
             "time": "0.3919430000ms",
             "time_in_nanos": "391943",
             "breakdown": {...}
          },
          {
             "type": "TermQuery",
             "description": "message:number",
             "time": "0.2106820000ms",
             "time_in_nanos": "210682",
             "breakdown": {...}
          }
       ]
    }
]

(1)为简单起见,这里省略故障时间。

基于探查(profile)的结构,我们可以看到,我们的匹配查询(match)被Lucene重写为包含两个条款(均有术语查询(TermQuery))的布尔查询(BooleanQuery)。类型字段(type)显示Lucene类的名称,并经常与Elasticsearch中对应的名字相同。这个描述字段(description)显示Lucene查询的解析文本,并可用于帮助区分查询的各个部分。(如:message:search and message:test 都是术语查询(TermQuery),否则会出现相同的两个。)

时间字段(time)表明该查询了执行整个布尔查询(BooleanQuery)花费1.8ms,此记录时间包含了所有孩子节点。

time_in nanos字段显示一个精确的、机器可读格式的时间信息(以纳秒为单位)。

崩溃字段(breakdown)给出时间如何花费的详细数据,我们一眼可以看到它。最后,孩子(children)数组列出了所有可能出现的子查询。因为我们搜索了两个值(“search test”),布尔查询(BooleanQuery)有两个孩子术语查询(TermQueries)。它们有相同的信息(类型、时间、故障等)。孩子(children)可以嵌套自己的孩子(children)。

注意

时间字段(time)仅用于人类消费。如果你需要精确的定时值请使用time_in nanos字段。目前,默认打印时间字段(time),但这将在下一个主要版本 (6.0.0)的发生变化,将默认打印time_in_nanos字段。

定时故障/Timing Breakdown

崩溃组件(breakdown)列出底层Lucene执行的详细时序统计:

"breakdown": {
   "score": 51306,
   "score_count": 4,
   "build_scorer": 2935582,
   "build_scorer_count": 1,
   "match": 0,
   "match_count": 0,
   "create_weight": 919297,
   "create_weight_count": 1,
   "next_doc": 53876,
   "next_doc_count": 5,
   "advance": 0,
   "advance_count": 0
}

时间信息用网络挂钟的纳秒列出来,且不规范化。所有关于时间的警告均适用于这里。 Breakdown的意图是让你感觉到(A)Lucene的运转实际上耗费时间的,(B)各部件耗费时间的差异是非常大的。像所有的时间一样,breakdown包含所有孩子的时间。

统计数据的含义如下:

所有的参数:/All parameters:

| create_weight | Lucene的查询必须能够在复杂的IndexSearchers重用(它被看做是针对特定的Lucene索引执行搜索的引擎。)。这使得Lucene处于一个棘手的境地,因为许多查询(Query)需要积累与它正在使用的索引相关联的临时的状态/统计信息,但查询(Query)合同授权要求它必须不可变的。为了解决这个问题,Lucene要求每个查询生成一个权重对象(weight object)作为临时的上下文对象为这个特定的元组(IndexSearcher,Query)保持状态信息。weight的度量表明这个过程所需要的时间长短。 | | build_scorer | 此参数显示建立查询的记分器(Scorer)需要多长的时间。记分器(Scorer)是一种遍历所有匹配文档为每个文档生成得分的机制(例如,“foo”与文档的匹配程度是怎样的?)。注意,这记录了生成记分器(Scorer)对象而不是对文档进行评分所需的时间。不同查询初始化记分器(Scorer)有快有慢,取决于优化、复杂性等。这也可能说明计时与缓存(caching)是否被启用或缓存是否适用于查询(query)相关。 | | next_doc | Lucene的方法next_doc返回下一个匹配查询的文档ID。此统计数据显示确定哪个文档是下一个匹配需要的时间,这是根据查询的性质而变化很大的过程。next_doc是一种特殊形式的advance(),它使得Lucene的许多查询更便捷。这相当于函数advance(docId() + 1)。 | | advance | advance是next_doc的低版本:它的目的是找到下一个匹配的DOC,但需要调用查询执行额外任务,如识别和移动过去的跳跃。然而,不是所有的查询都可以使用next_doc,所以advance的目的是服务于那些查询。联合查询(Conjunctions)(如,布尔查询中有must)是advance的典型消费者。 | | matches | 一些查询,如短语查询,使用“两阶段”过程匹配文档。首先,“近似”匹配文档,如果文档大约匹配,它将用更严格的(和昂贵的)的方法进行第二次检查。第二阶段验证是匹配的统计测量。例如,短语查询首先通过确保所有术语都存在于文档中来大约检查文档。如果所有的术语都存在,那么它执行第二阶段验证,以确保条款按次序形成短语,相比检查条款是否存在这是更昂贵的。 由于这两过程仅被少数查询使用,统计度量结果往往是零。 | | score | 这记录了一个特定的文件通过评分器(Scorer)评分所需的时间。 | | *_count | 纪录调用特定方法的数量。例如, ”next_doc_count”:2,意味着nextDoc()在两个不同的文档中被调用。这可以通过比较不同查询组件之间的计数来帮助判断如何选择查询。 |

收集部分/collectors Section

响应的收集器(Collectors)部分显示高级执行细节。Lucene通过定义一个“收集器(Collector)”来工作,它负责协调匹配文档的遍历、得分和集合。收集器(Collectors)也有单个查询如何记录聚合结果、执行无作用域的“global”查询、执行post-query过滤,等功能。

看前面的例子:

"collector": [
   {
      "name": "CancellableCollector",
      "reason": "search_cancelled",
      "time": "0.3043110000ms",
      "time_in_nanos": "304311",
      "children": [
        {
          "name": "SimpleTopScoreDocCollector",
          "reason": "search_top_hits",
          "time": "0.03227300000ms",
          "time_in_nanos": "32273"
        }
      ]
   }
]

我们看到一个收集器(Collector)由SimpleTopScoreDocCollector包装成 CancellableCollector。SimpleTopScoreDocCollector是Elasticsearch使用的默认的“评分和排序”的收集器(Collector)。原因字段(reason)试图对类名进行简单的英文描述。时间字段(time)与查询树中的时间字段(time)相似:一个包括所有孩子节点的网络挂钟时间。同样的是,孩子(children)列出所有子收集器(Collector)。包装SimpleTopScoreDocCollector的CancellableCollector,被Elasticsearch用于检测当前搜索是否被取消,一旦发生取消搜索的行为则停止收集文件。

应该指出的是,Collector times与Query times相互独立。他们独立计算、合并和规范化!由于Lucene的执行的性质,它不可能把收集器(Collectors)的时间“合并“”到查询部分(Query),所以他们在不同的部分显示出来。

作为参考,各种收集器Collectors的原因是:

| search_sorted | 整理和分类文件的收集器(collector)。这是最常见的收集器,会最简单的搜索中出现。 | | search_count | 一个仅计算查询匹配的文档数的收集器(collector),但不能获取源代码。只有当参数size被指定为0,这个收集器才会出现。 | | search_terminate_after_count | 一个当N个匹配文档被发现就终止搜索的收集器(collector)。只有当terminate_after_count query参数被指定,这个收集器才会出现。 | | search_min_score | 一个只返回评分大于 N的匹配文档的收集器(collector)。只有当顶层参数min_score被指定,这个收集器才会出现。 | | search_multi | 包裹其他几个收集器的收集器(collector)。只有当组合搜索(combinations of search),聚合(aggregations),全局聚合(global aggs)和post_filters结合在一个搜索里,这个收集器才会出现。 | | search_timeout | 一个在特定时间中断执行的收集器(collector)。只有当顶层参数timeout被指定,这个收集器才会出现。 | | aggregation | 一个Elasticsearch在查询范围使用聚合的收集器(collector)。一个为所有聚合采集文件的聚合采集器,所以你会看到一个聚合名称的列表。 | | global_aggregation | 一个对全局查询(global query scope)而不是指定查询(specified query)执行聚合(aggregation)的收集器(Collector)。由于全局范围(global query)不同于执行普通查询(query),它必须执行它自己的match_all查询(这会被添加到查询部分(Query))来收集整个数据集。 |

重写部分/rewrite Section

Lucene中的所有查询都经过“重写”过程。一个查询(及其子查询)可以重写一次或多次,这过程继续进行,直到查询停止更改。这个过程让Lucene进行优化,如去除多余的条款,一个更有效的执行路径替换一个查询。例如Boolean → Boolean → TermQuery 可以改写为术语查询(TermQuery),因为在这种情况下所有的布尔值都是多余的。重写的过程是复杂的,难以显示,因为查询可以大幅改变。总改写时间不显示中间结果,只是显示为一个值(以纳秒为单位)。此值是累加的,包含所有被重写查询的总时间。

更复杂的例子/A more complex example

为了演示稍微复杂的查询和相关的结果,我们可以探查(profile)以下查询:

GET /test/_search
{
  "profile": true,
  "query": {
    "term": {
      "message": {
        "value": "search"
      }
    }
  },
  "aggs": {
    "non_global_term": {
      "terms": {
        "field": "agg"
      },
      "aggs": {
        "second_term": {
          "terms": {
            "field": "sub_agg"
          }
        }
      }
    },
    "another_agg": {
      "cardinality": {
        "field": "aggB"
      }
    },
    "global_agg": {
      "global": {},
      "aggs": {
        "my_agg2": {
          "terms": {
            "field": "globalAgg"
          }
        }
      }
    }
  },
  "post_filter": {
    "term": {
      "my_field": "foo"
    }
  }
}

这个例子有:

  • 一个查询(query)
  • 一个局部聚合(scoped aggregation)
  • 一个全局聚合(global aggregation)
  • 一个后过滤(post_filter)

响应:

{
   "profile": {
         "shards": [
            {
               "id": "[P6-vulHtQRWuD4YnubWb7A][test][0]",
               "searches": [
                  {
                     "query": [
                        {
                           "type": "TermQuery",
                           "description": "my_field:foo",
                           "time": "0.4094560000ms",
                           "time_in_nanos": "409456",
                           "breakdown": {
                              "score": 0,
                              "score_count": 1,
                              "next_doc": 0,
                              "next_doc_count": 2,
                              "match": 0,
                              "match_count": 0,
                              "create_weight": 31584,
                              "create_weight_count": 1,
                              "build_scorer": 377872,
                              "build_scorer_count": 1,
                              "advance": 0,
                              "advance_count": 0
                           }
                        },
                        {
                           "type": "TermQuery",
                           "description": "message:search",
                           "time": "0.3037020000ms",
                           "time_in_nanos": "303702",
                           "breakdown": {
                              "score": 0,
                              "score_count": 1,
                              "next_doc": 5936,
                              "next_doc_count": 2,
                              "match": 0,
                              "match_count": 0,
                              "create_weight": 185215,
                              "create_weight_count": 1,
                              "build_scorer": 112551,
                              "build_scorer_count": 1,
                              "advance": 0,
                              "advance_count": 0
                           }
                        }
                     ],
                     "rewrite_time": 7208,
                     "collector": [
                        {
                           "name": "MultiCollector",
                           "reason": "search_multi",
                           "time": "1.378943000ms",
                           "time_in_nanos": "1378943",
                           "children": [
                              {
                                 "name": "FilteredCollector",
                                 "reason": "search_post_filter",
                                 "time": "0.4036590000ms",
                                 "time_in_nanos": "403659",
                                 "children": [
                                    {
                                       "name": "SimpleTopScoreDocCollector",
                                       "reason": "search_top_hits",
                                       "time": "0.006391000000ms",
                                       "time_in_nanos": "6391"
                                    }
                                 ]
                              },
                              {
                                 "name": "BucketCollector: [[non_global_term, another_agg]]",
                                 "reason": "aggregation",
                                 "time": "0.9546020000ms",
                                 "time_in_nanos": "954602"
                              }
                           ]
                        }
                     ]
                  },
                  {
                     "query": [
                        {
                           "type": "MatchAllDocsQuery",
                           "description": "*:*",
                           "time": "0.04829300000ms",
                           "time_in_nanos": "48293",
                           "breakdown": {
                              "score": 0,
                              "score_count": 1,
                              "next_doc": 3672,
                              "next_doc_count": 2,
                              "match": 0,
                              "match_count": 0,
                              "create_weight": 6311,
                              "create_weight_count": 1,
                              "build_scorer": 38310,
                              "build_scorer_count": 1,
                              "advance": 0,
                              "advance_count": 0
                           }
                        }
                     ],
                     "rewrite_time": 1067,
                     "collector": [
                        {
                           "name": "GlobalAggregator: [global_agg]",
                           "reason": "aggregation_global",
                           "time": "0.1226310000ms",
                           "time_in_nanos": "122631"
                        }
                     ]
                  }
               ]
            }
         ]
      }
}

正如你所看到的,输出明显比前面冗长。查询的所有主要部分都表示:

  1. 第一个TermQuery (message:search) 代表主术语查询。

  2. 第二个TermQuery (my_field:foo) 代表后过滤(post_filter)查询。

  3. 有一个MatchAllDocsQuery ()查询,作为执行第二个不同的搜索。这不是由用户指定的查询的一部分,而是由全局聚合(global aggregation)为提供全局查询范围而自动生成的。

收集树是相当简单的,显示了一个MultiCollector如何包裹FilteredCollector去执行post_filter(反过来,包裹正常的评分SimpleCollector),和bucketcollector运行所有作用域的聚合。 In the MatchAll search, there is a single GlobalAggregator to run the global aggregation.在MatchAll搜索中,有一个全局聚合器(GlobalAggregator)运行全局的聚合。

了解MultiTermQuery的输出/Understanding MultiTermQuery output

这里需要对MultiTermQuery类查询做一个特别注释。这包括通配符(wildcards),正则表达式(regex)和模糊(fuzzy)查询。这些查询发出非常冗长的响应,并且不过度结构化。

从本质上讲,这些查询(query)在每一个段的基础上改写自己。如果你想象中的通配符查询为"b*",在技术上它可以匹配任何以字母“b”开头的标记。无法枚举所有可能的组合,所以Lucene重写查询中被评估的段落。例如,某段中可能包含标记 [bar, baz],所以查询query重写到布尔查询(BooleanQuery)中包含了"bar"和"baz"。另一段可能只有标记 [bakery],所以查询query重写成只包含"bakery"的术语查询(TermQuery)。

由于这种每段重写的动态,干净的树结构变得扭曲,并且不再有清晰的世系去显示一个查询如何被重写rewriter成下一个。目前,我们所能做的就是道歉,如果它太混乱,建议您检查该查询的孩子节点的崩溃的细节。幸运的是,所有的时间统计都是正确的,只是不在响应(response)的物理布局中,因此只需分析顶层的MultiTermQuery,如果你发现的细节很难解释请忽视的它的孩子节点。

希望在未来的迭代它会变成固定,但它是一个很难解决的、正在改善中的棘手问题 :)