本文深入解析了Elasticsearch的ProfileAPI，介绍了如何使用该工具诊断和优化搜索查询的性能。ProfileAPI能够提供搜索请求中各组件执行的详细时间信息，帮助用户理解搜索请求的底层执行流程，从而找出慢查询的原因并采取措施进行优化。
Profile API
警告: Profile API是一个调试工具，为搜索执行增加了大量开销。
Profile API提供了关于搜索请求中各个组件执行的详细时间信息。它让用户了解如何在较低的级别执行搜索请求，以便用户能够理解为什么某些请求很慢，并采取步骤改进它们。请注意，Profile API并不测量网络延迟、搜索获取阶段花费的时间、请求在队列中花费的时间或在协调节点上合并分片响应时花费的时间。
概要文件API的输出非常冗长，特别是对于跨多个分片执行的复杂请求。建议对响应进行漂亮的打印，以帮助理解输出
Usage
任何_search请求都可以通过添加顶级概要参数进行概要分析:
GET /twitter/_search
{
"profile": true, ------------1
"query" : {
"match" : { "message" : "some number" }
}
}
1: 将顶级概要参数设置为true将启用搜索的概要分析
这将产生以下结果:
{
"took": 25,
"timed_out": false,
"_shards": {
"total": 1,
"successful": 1,
"skipped" : 0,
"failed": 0
},
"hits": {
"total" : {
"value": 4,
"relation": "eq"
},
"max_score": 0.5093388,
"hits": [...] ---------------1
},
"profile": {
"shards": [
{
"id": "[2aE02wS1R8q_QFnYu6vDVQ][twitter][0]",
"searches": [
{
"query": [
{
"type": "BooleanQuery",
"description": "message:some message:number",
"time_in_nanos": "1873811",
"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,
"compute_max_score": 0,
"compute_max_score_count": 0,
"shallow_advance": 0,
"shallow_advance_count": 0,
"set_min_competitive_score": 0,
"set_min_competitive_score_count": 0
},
"children": [
{
"type": "TermQuery",
"description": "message:some",
"time_in_nanos": "391943",
"breakdown": {
"score": 28776,
"score_count": 4,
"build_scorer": 784451,
"build_scorer_count": 1,
"match": 0,
"match_count": 0,
"create_weight": 1669564,
"create_weight_count": 1,
"next_doc": 10111,
"next_doc_count": 5,
"advance": 0,
"advance_count": 0,
"compute_max_score": 0,
"compute_max_score_count": 0,
"shallow_advance": 0,
"shallow_advance_count": 0,
"set_min_competitive_score": 0,
"set_min_competitive_score_count": 0
}
},
{
"type": "TermQuery",
"description": "message:number",
"time_in_nanos": "210682",
"breakdown": {
"score": 4552,
"score_count": 4,
"build_scorer": 42602,
"build_scorer_count": 1,
"match": 0,
"match_count": 0,
"create_weight": 89323,
"create_weight_count": 1,
"next_doc": 2852,
"next_doc_count": 5,
"advance": 0,
"advance_count": 0,
"compute_max_score": 0,
"compute_max_score_count": 0,
"shallow_advance": 0,
"shallow_advance_count": 0,
"set_min_competitive_score": 0,
"set_min_competitive_score_count": 0
}
}
]
}
],
"rewrite_time": 51443,
"collector": [
{
"name": "CancellableCollector",
"reason": "search_cancelled",
"time_in_nanos": "304311",
"children": [
{
"name": "SimpleTopScoreDocCollector",
"reason": "search_top_hits",
"time_in_nanos": "32273"
}
]
}
]
}
],
"aggregations": []
}
]
}
}
1: 返回搜索结果，但是为了简洁起见，这里省略了搜索结果
即使对于一个简单的查询，响应也相对复杂。在开始更复杂的示例之前，让我们将其逐个分解。
首先，概要响应的总体结构如下:
{
"profile": {
"shards": [
{
"id": "[2aE02wS1R8q_QFnYu6vDVQ][twitter][0]", -------------1
"searches": [
{
"query": [...], -------------2
"rewrite_time": 51443, -----------------3
"collector": [...] ---------------4
}
],
"aggregations": [...] --------------5
}
]
}
}
1: 将为参与响应的每个分片返回一个概要文件，并由一个惟一ID标识
2: 每个概要文件都包含一个部分，其中包含关于查询执行的详细信息
3: 每个概要文件都有一个表示累计重写时间的时间
4: 每个概要文件还包含一个关于运行搜索的Lucene收集器的部分
5: 每个概要文件都包含一个部分，其中包含关于聚合执行的详细信息
由于搜索请求可能针对索引中的一个或多个分片执行，而搜索可能覆盖一个或多个索引，所以配置文件响应中的顶层元素是切分对象数组。每个分片对象列出其id，该id惟一标识分片。ID的格式是[nodeID][indexName][shardID]。
概要文件本身可能包含一个或多个“搜索”，其中搜索是对基础Lucene索引执行的查询。用户提交的大多数搜索请求只对Lucene索引执行一次搜索。但是偶尔会执行多个搜索，比如包含一个全局聚合(它需要为全局上下文执行一个次要的“match_all”查询)。
在每个搜索对象中都有两个已配置信息数组:查询数组和收集器数组。搜索对象旁边是一个aggregations对象，其中包含聚合的概要信息。在将来，可能会添加更多的部分，如建议、突出显示等。
还将有一个重写度量，显示重写查询花费的总时间(以纳秒为单位)。
与其他统计API一样，Profile API支持人类可读的输出。这可以通过在查询字符串中添加?human=true来打开。在这种情况下，输出包含额外的时间字段，其中包含整数的、人类可读的计时信息(例如。"time": "391,9ms", "time": "123.3micros")。
Profiling Queries
注意: Profile API提供的详细信息直接公开了Lucene类名和概念，这意味着对结果的完整解释需要相当高级的Lucene知识。本页面试图提供一个关于Lucene如何执行查询的紧急课程，以便您可以使用Profile API成功地诊断和调试查询，但这只是一个概述。要获得完整的理解，请参考Lucene的文档和代码。
话虽如此，要修复慢速查询通常不需要完全理解。通常，只要看到查询的某个特定组件比较慢就足够了，而且不一定能理解为什么该查询的高级阶段是原因，例如。
query Section
查询部分包含Lucene在特定分片上执行查询树的详细时间。这个查询树的整体结构将类似于您最初的Elasticsearch查询，但可能略有不同(有时非常不同)。它还将使用类似但并不总是相同的命名。使用我们前面的匹配查询示例，让我们分析查询部分:
"query": [
{
"type": "BooleanQuery",
"description": "message:some message:number",
"time_in_nanos": "1873811",
"breakdown": {...}, ---------------1
"children": [
{
"type": "TermQuery",
"description": "message:some",
"time_in_nanos": "391943",
"breakdown": {...}
},
{
"type": "TermQuery",
"description": "message:number",
"time_in_nanos": "210682",
"breakdown": {...}
}
]
}
]
1: 为了简单起见，省略了故障时间
根据概要文件结构，我们可以看到我们的匹配查询被Lucene重写为一个带有两个子句(都包含TermQuery)的BooleanQuery。type字段显示Lucene类名，并经常与Elasticsearch中的等价名称对齐。description字段显示查询的Lucene解释文本，并可用来帮助区分查询的各个部分(例如message:search和message:test都是TermQuery的，否则它们看起来是相同的。
time_in_nanos字段显示，执行整个布尔查询花费了约1.8ms。所记录的时间包括所有儿童。
细分字段将提供关于时间如何使用的详细统计信息，我们稍后将对此进行研究。最后，子数组列出可能出现的所有子查询。因为我们搜索了两个值(“search test”)，所以我们的BooleanQuery包含两个子TermQueries。它们有相同的信息(类型、时间、细目等等)。孩子们被允许有自己的孩子。
Timing 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,
"compute_max_score": 0,
"compute_max_score_count": 0,
"shallow_advance": 0,
"shallow_advance_count": 0,
"set_min_competitive_score": 0,
"set_min_competitive_score_count": 0
}
计时是以挂钟纳秒为单位列出的，根本没有标准化。所有关于总时间_in_nanos的警告都适用于这里。分解的目的是让你对A: Lucene中的机器实际上消耗时间是什么，B: 不同组件在时间上的差异的大小有一个感觉。和总时间一样，这个细分包括了所有的儿童时间。
统计数字的意义如下:
All parameters:
|
|
Lucene中的查询必须能够跨多个索引搜索器重用(可以将其视为针对特定Lucene索引执行搜索的引擎)。这将Lucene置于一个棘手的位置，因为许多查询需要积累与它所针对的索引相关联的临时状态/统计信息，但是查询契约要求它必须是不可变的。为了解决这个问题，Lucene要求每个查询生成一个Weight对象，它作为一个临时上下文对象来保存与这个特定元组(IndexSearcher, query)关联的状态。权重指标显示了这个过程需要多长时间 |
|
|
此参数显示为查询构建记分器所需的时间。记分员是一种机制，它遍历匹配的文档并为每个文档生成一个分数(例如，“foo”与文档的匹配程度如何?)注意，这记录了生成得分器对象所需的时间，而不是实际为文档打分。有些查询的初始化速度更快或更慢，这取决于优化、复杂性等。如果启用和/或适用于查询，这还可能显示与缓存相关的计时 |
|
|
Lucene方法next_doc返回与查询匹配的下一个文档的Doc ID。这个统计数据显示了确定下一个匹配文档所需的时间，这个过程会根据查询的性质发生很大的变化。Next_doc是advance()的一种特殊形式，它对于Lucene中的许多查询更加方便。它相当于advance(docId() + 1) |
|
|
advance是next_doc的“低级”版本:它的作用与查找下一个匹配的doc相同，但是需要调用查询来执行额外的任务，比如识别和移动过去的跳过，等等。但是，并不是所有查询都可以使用next_doc，所以对这些查询也要计时。连词(例如boolean中的must子句)是高级语句的典型消费者 |
|
|
有些查询，如短语查询，使用“两阶段”流程匹配文档。首先，文档是“近似”匹配的，如果匹配近似，则使用更严格(且更昂贵)的过程对其进行第二次检查。第二阶段验证是与统计量匹配的部分。例如，短语查询首先大致检查文档，确保短语中的所有term都出现在doc中。如果所有的term都存在，那么它将执行第二个阶段的验证，以确保term是为了形成phrase而存在的，这比仅仅检查term的存在要昂贵得多。因为这个两阶段的过程只被少数几个查询使用，度量统计量通常为零 |
|
|
这记录了通过记分员为特定文档打分所花费的时间 |
|
|
记录特定方法的调用次数。例如，“next_doc_count”:2，表示nextDoc()方法是在两个不同的文档上调用的。这可以通过比较不同查询组件之间的计数来帮助判断查询的选择性。 |
collectors Section
响应的收集器部分显示高级执行细节。Lucene通过定义一个“收集器”来工作，它负责协调遍历、评分和匹配文档的收集。收集器也是单个查询如何记录聚合结果、执行无范围的“全局”查询、执行查询后过滤器等。
看看前面的例子:
"collector": [
{
"name": "CancellableCollector",
"reason": "search_cancelled",
"time_in_nanos": "304311",
"children": [
{
"name": "SimpleTopScoreDocCollector",
"reason": "search_top_hits",
"time_in_nanos": "32273"
}
]
}
]
我们看到一个名为SimpleTopScoreDocCollector的收集器被封装到CancellableCollector中。SimpleTopScoreDocCollector是Elasticsearch使用的默认“计分和排序”收集器。reason字段试图用简单的英语描述类名。time_in_nanos类似于查询树中的时间:包含所有子节点的壁钟时间。类似地，子收集器列出所有子收集器。Elasticsearch使用包装SimpleTopScoreDocCollector的CancellableCollector来检测当前搜索是否被取消，并在发生时立即停止收集文档。
应该注意，收集器时间独立于查询时间。它们是独立计算、组合和标准化的!由于Lucene执行的性质，不可能将收集器中的时间“合并”到查询部分，因此它们以单独的部分显示。
可供参考的原因有:
|
|
对文档进行评分和分类的收集器。这是最常见的收集器，在大多数简单的搜索中都可以看到 |
|
|
一个收集器，它只计算与查询匹配的文档数量，但不获取源。这可以在指定size: 0时看到 |
|
|
在找到n个匹配的文档后终止搜索执行的收集器。这可以在指定terminate_after_count查询参数时看到 |
|
|
只返回得分大于n的匹配文档的收集器。这可以在指定顶级参数min_score时看到。 |
|
|
一个封装其他几个收集器的收集器。当搜索、聚合、全局aggs和post_filters组合在一个搜索中时，可以看到这一点。 |
|
|
一种收集器，它在指定的时间之后停止执行。这可以在指定超时顶级参数时看到。 |
|
|
Elasticsearch用于对查询范围运行聚合的收集器。一个聚合收集器用于为所有聚合收集文档，因此您将在名称中看到一个聚合列表。 |
|
|
针对全局查询范围(而不是指定的查询)执行聚合的收集器。因为全局范围必然与执行的查询不同，所以它必须执行自己的match_all查询(您将看到它被添加到query部分)来收集整个数据集 |
rewrite Section
Lucene中的所有查询都经历一个“重写”过程。一个查询(及其子查询)可能被重写一次或多次，这个过程将继续，直到查询停止更改为止。这个过程允许Lucene执行优化，例如删除冗余子句，替换一个查询以获得更有效的执行路径，等等。例如，可以将Boolean→Boolean→TermQuery重写为TermQuery，因为在这种情况下，所有布尔值都是不必要的。
重写过程复杂且难以显示，因为查询可能会发生剧烈变化。总重写时间不是显示中间结果，而是简单地显示为一个值(以纳秒为单位)。此值是累积的，包含所有重写查询的总时间。
A more complex example
为了演示一个稍微复杂一点的查询和相关的结果，我们可以分析以下查询:
GET /twitter/_search
{
"profile": true,
"query": {
"term": {
"user": {
"value": "test"
}
}
},
"aggs": {
"my_scoped_agg": {
"terms": {
"field": "likes"
}
},
"my_global_agg": {
"global": {},
"aggs": {
"my_level_agg": {
"terms": {
"field": "likes"
}
}
}
}
},
"post_filter": {
"match": {
"message": "some"
}
}
}
这个例子有:
- 一个查询
- 作用域聚合
- 一个全球性的聚合
- 一个post_filter
响应:
{
...
"profile": {
"shards": [
{
"id": "[P6-vulHtQRWuD4YnubWb7A][test][0]",
"searches": [
{
"query": [
{
"type": "TermQuery",
"description": "message:some",
"time_in_nanos": "409456",
"breakdown": {
"score": 0,
"build_scorer_count": 1,
"match_count": 0,
"create_weight": 31584,
"next_doc": 0,
"match": 0,
"create_weight_count": 1,
"next_doc_count": 2,
"score_count": 1,
"build_scorer": 377872,
"advance": 0,
"advance_count": 0,
"compute_max_score": 0,
"compute_max_score_count": 0,
"shallow_advance": 0,
"shallow_advance_count": 0,
"set_min_competitive_score": 0,
"set_min_competitive_score_count": 0
}
},
{
"type": "TermQuery",
"description": "user:test",
"time_in_nanos": "303702",
"breakdown": {
"score": 0,
"build_scorer_count": 1,
"match_count": 0,
"create_weight": 185215,
"next_doc": 5936,
"match": 0,
"create_weight_count": 1,
"next_doc_count": 2,
"score_count": 1,
"build_scorer": 112551,
"advance": 0,
"advance_count": 0,
"compute_max_score": 0,
"compute_max_score_count": 0,
"shallow_advance": 0,
"shallow_advance_count": 0,
"set_min_competitive_score": 0,
"set_min_competitive_score_count": 0
}
}
],
"rewrite_time": 7208,
"collector": [
{
"name": "CancellableCollector",
"reason": "search_cancelled",
"time_in_nanos": 2390,
"children": [
{
"name": "MultiCollector",
"reason": "search_multi",
"time_in_nanos": 1820,
"children": [
{
"name": "FilteredCollector",
"reason": "search_post_filter",
"time_in_nanos": 7735,
"children": [
{
"name": "SimpleTopScoreDocCollector",
"reason": "search_top_hits",
"time_in_nanos": 1328
}
]
},
{
"name": "MultiBucketCollector: [[my_scoped_agg, my_global_agg]]",
"reason": "aggregation",
"time_in_nanos": 8273
}
]
}
]
}
]
}
],
"aggregations": [...] ------------------1
}
]
}
}
1: “聚合”部分被省略了，因为它将在下一节中讨论
如您所见，输出比以前要详细得多。查询的所有主要部分如下:
- 第一个TermQuery (user:test)表示主要的term查询
- 第二个TermQuery (message:some)表示post_filter查询
Collector tree 相当简单，展示了一个CancellableCollector如何包装一个多ollector，该多ollector也包装一个FilteredCollector来执行post_filter(然后包装一个普通的计分SimpleCollector)，一个BucketCollector来运行所有范围的聚合。
Understanding MultiTermQuery output
需要特别注意查询的MultiTermQuery类。这包括通配符、正则表达式和模糊查询。这些查询发出非常详细的响应，并且没有过度结构化。
本质上，这些查询在每个段的基础上重写它们自己。如果您设想通配符查询b*，它在技术上可以匹配任何以字母“b”开头的令牌。要枚举所有可能的组合是不可能的，因此Lucene在被计算的段的上下文中重写了查询，例如，一个段可能包含令牌[bar, baz]，因此查询重写为“bar”和“baz”的BooleanQuery组合。另一个段可能只有令牌[面包房]，因此查询重写为“面包房”的单个TermQuery。
由于这种动态的、每段重写，干净的树结构变得扭曲，不再遵循一个干净的“lineage”来显示如何将一个查询重写到下一个查询。目前，我们所能做的就是道歉，并建议您将该查询的子查询的详细信息折叠起来(如果太混乱的话)。幸运的是，所有的计时统计数据都是正确的，只是响应中的物理布局不正确，因此，如果您发现细节难以解释，那么只分析顶级MultiTermQuery并忽略它的子查询就足够了。
希望在未来的迭代中能够修复这个问题，但是这是一个棘手的问题，而且仍然在进行中:)
Profiling Aggregations
aggregations Section
aggregations部分包含由特定分片执行的aggregation tree的详细时间。这个aggregation tree的整体结构将类似于您最初的Elasticsearch请求。让我们再次执行前面的查询，这次查看聚合概要文件:
GET /twitter/_search
{
"profile": true,
"query": {
"term": {
"user": {
"value": "test"
}
}
},
"aggs": {
"my_scoped_agg": {
"terms": {
"field": "likes"
}
},
"my_global_agg": {
"global": {},
"aggs": {
"my_level_agg": {
"terms": {
"field": "likes"
}
}
}
}
},
"post_filter": {
"match": {
"message": "some"
}
}
}
这将生成以下聚合概要文件输出:
{
"profile" : {
"shards" : [
{
"aggregations" : [
{
"type" : "LongTermsAggregator",
"description" : "my_scoped_agg",
"time_in_nanos" : 195386,
"breakdown" : {
"reduce" : 0,
"build_aggregation" : 81171,
"build_aggregation_count" : 1,
"initialize" : 22753,
"initialize_count" : 1,
"reduce_count" : 0,
"collect" : 91456,
"collect_count" : 4
}
},
{
"type" : "GlobalAggregator",
"description" : "my_global_agg",
"time_in_nanos" : 190430,
"breakdown" : {
"reduce" : 0,
"build_aggregation" : 59990,
"build_aggregation_count" : 1,
"initialize" : 29619,
"initialize_count" : 1,
"reduce_count" : 0,
"collect" : 100815,
"collect_count" : 4
},
"children" : [
{
"type" : "LongTermsAggregator",
"description" : "my_level_agg",
"time_in_nanos" : 160329,
"breakdown" : {
"reduce" : 0,
"build_aggregation" : 55712,
"build_aggregation_count" : 1,
"initialize" : 10559,
"initialize_count" : 1,
"reduce_count" : 0,
"collect" : 94052,
"collect_count" : 4
}
}
]
}
]
}
]
}
}
从概要文件结构中，我们可以看到my_scoped_agg在内部作为一个LongTermsAggregator运行(因为它聚合的字段是一个数值字段，比如like)。在同一层，我们看到一个来自my_global_agg的GlobalAggregator。然后，该聚合有一个子长期聚合器，它来自第二项对like的聚合。
time_in_nanos字段显示每个聚合执行的时间，并包含所有子节点。虽然总体时间是有用的，但是breakdown字段将提供关于时间如何使用的详细统计信息。
Timing Breakdown
细分组件列出了底层Lucene执行的详细时间统计:
"breakdown": {
"reduce": 0,
"reduce_count": 0,
"build_aggregation": 49765,
"build_aggregation_count": 300,
"initialize": 52785,
"initialize_count": 300,
"reduce_count": 0,
"collect": 3155490036,
"collect_count": 1800
}
计时是以挂钟纳秒为单位列出的，根本没有标准化。所有关于总时间的警告都适用于这里。分析的目的是让你了解A: 弹性搜索中的机械实际上在消耗时间，B: 不同组件之间的时间差异的大小。和总时间一样，这个细分包括了所有的儿童时间。
统计数字的意义如下:
All parameters:
|
|
这是在开始收集文档之前创建和初始化聚合所需的时间。 |
|
| 这表示在聚合的collect阶段花费的累计时间。这是将匹配的文档传递给聚合的地方，聚合器的状态将根据文档中包含的信息进行更新。 |
|
| 这表示创建聚合的分片级结果所花费的时间，准备在文档收集完成后返回到reduce节点。 |
|
|
这不是目前使用的，总是报告0。当前聚合分析仅乘以聚合执行的分片级部分。稍后将添加reduce阶段的时间。 |
|
|
记录特定方法的调用次数。例如，“collect_count”:2表示对两个不同的文档调用collect()方法。 |
Profiling Considerations
Performance Notes
与任何分析器一样，Profile API为搜索执行引入了不可忽略的开销。检测底层方法调用(如collect、advance和next_doc)的开销可能相当大，因为这些方法是在紧密循环中调用的。因此，在默认情况下，不应该在生产设置中启用概要分析，也不应该与非概要分析的查询时间进行比较。剖析只是一个诊断工具。
还有一些情况禁用了特殊的Lucene优化，因为它们不适合进行概要分析。这可能会导致一些查询报告的相对时间比非概要化的查询报告的相对时间要长，但是与概要化查询中的其他组件相比，通常不应该有太大的影响。
Limitations
- 分析目前不测量搜索获取阶段和网络开销
- 分析也不考虑在队列中花费的时间、在协调节点上合并碎片响应，或者其他工作，比如构建全局序号(用于加速搜索的内部数据结构)
- 分析统计数据目前无法用于建议、高亮显示、dfs_query_then_fetch
- 聚合的reduce阶段的概要分析目前不可用
- 分析器仍然是高度实验性的。分析器检测了Lucene中从未设计成以这种方式公开的部分，因此所有结果都应该被视为提供详细诊断的最佳努力。我们希望随着时间的推移能改善这一点。如果您发现明显错误的数字、奇怪的查询结构或其他错误，请报告!
扫一扫
1万+
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
