Profiling Queries · Elasticsearch 5.4 中文文档

# Profiling Queries 注意 Profile API 提供的详细信息直接暴露了Lucene的类名和概念，这意味着对结果的完整解释需要Lucene相当高级的知识。本页试图对Lucene如何执行查询提供速成教程，以便您可以成功地使用Profile API诊断和调试查询，但它只是一个概述。如需完整的理解，请参考Lucene对应位置的文档和代码。也就是说，处理一个缓慢的查询往往不需要完整理解Lucene。例如，我们普遍知道某个特定的查询组件很缓慢，但不一定理解为什么该查询的advance前阶段是诱因。原文链接 : [https://www.elastic.co/guide/en/elasticsearch/reference/5.4/_profiling_queries.html](https://www.elastic.co/guide/en/elasticsearch/reference/5.4/_profiling_queries.html) 译文链接 : [http://www.apache.wiki/display/Elasticsearch/Profiling+Queries](http://www.apache.wiki/display/Elasticsearch/Profiling+Queries) 贡献者 : [王晗](/display/~wanghan),[岑晓燕](/display/~cenxiaoyan) ## 查询部分/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，如果你发现的细节很难解释请忽视的它的孩子节点。希望在未来的迭代它会变成固定，但它是一个很难解决的、正在改善中的棘手问题 :)