Profile API

编辑

Profile API 是一种调试工具,会对搜索执行增加显著的开销。

提供有关搜索请求中各个组件执行的详细计时信息。

描述

编辑

Profile API 让用户深入了解搜索请求如何在底层执行,以便用户了解某些请求为何缓慢,并采取措施加以改进。请注意,Profile API,除此之外,不会测量网络延迟、请求在队列中花费的时间或在协调节点上合并分片响应所花费的时间。

Profile API 的输出 非常 冗长,特别是对于跨多个分片执行的复杂请求。建议对响应进行美化打印,以帮助理解输出。

示例

编辑

任何 _search 请求都可以通过添加顶层 profile 参数来分析

resp = client.search(
    index="my-index-000001",
    profile=True,
    query={
        "match": {
            "message": "GET /search"
        }
    },
)
print(resp)
response = client.search(
  index: 'my-index-000001',
  body: {
    profile: true,
    query: {
      match: {
        message: 'GET /search'
      }
    }
  }
)
puts response
const response = await client.search({
  index: "my-index-000001",
  profile: true,
  query: {
    match: {
      message: "GET /search",
    },
  },
});
console.log(response);
GET /my-index-000001/_search
{
  "profile": true,
  "query" : {
    "match" : { "message" : "GET /search" }
  }
}

将顶层 profile 参数设置为 true 将启用搜索的性能分析。

API 返回以下结果

{
  "took": 25,
  "timed_out": false,
  "_shards": {
    "total": 1,
    "successful": 1,
    "skipped": 0,
    "failed": 0
  },
  "hits": {
    "total": {
      "value": 5,
      "relation": "eq"
    },
    "max_score": 0.17402273,
    "hits": [...] 
  },
  "profile": {
    "shards": [
      {
        "id": "[q2aE02wS1R8qQFnYu6vDVQ][my-index-000001][0]",
        "node_id": "q2aE02wS1R8qQFnYu6vDVQ",
        "shard_id": 0,
        "index": "my-index-000001",
        "cluster": "(local)",
        "searches": [
          {
            "query": [
              {
                "type": "BooleanQuery",
                "description": "message:get message:search",
                "time_in_nanos" : 11972972,
                "breakdown" : {
                  "set_min_competitive_score_count": 0,
                  "match_count": 5,
                  "shallow_advance_count": 0,
                  "set_min_competitive_score": 0,
                  "next_doc": 39022,
                  "match": 4456,
                  "next_doc_count": 5,
                  "score_count": 5,
                  "compute_max_score_count": 0,
                  "compute_max_score": 0,
                  "advance": 84525,
                  "advance_count": 1,
                  "score": 37779,
                  "build_scorer_count": 2,
                  "create_weight": 4694895,
                  "shallow_advance": 0,
                  "create_weight_count": 1,
                  "build_scorer": 7112295,
                  "count_weight": 0,
                  "count_weight_count": 0
                },
                "children": [
                  {
                    "type": "TermQuery",
                    "description": "message:get",
                    "time_in_nanos": 3801935,
                    "breakdown": {
                      "set_min_competitive_score_count": 0,
                      "match_count": 0,
                      "shallow_advance_count": 3,
                      "set_min_competitive_score": 0,
                      "next_doc": 0,
                      "match": 0,
                      "next_doc_count": 0,
                      "score_count": 5,
                      "compute_max_score_count": 3,
                      "compute_max_score": 32487,
                      "advance": 5749,
                      "advance_count": 6,
                      "score": 16219,
                      "build_scorer_count": 3,
                      "create_weight": 2382719,
                      "shallow_advance": 9754,
                      "create_weight_count": 1,
                      "build_scorer": 1355007,
                      "count_weight": 0,
                      "count_weight_count": 0
                    }
                  },
                  {
                    "type": "TermQuery",
                    "description": "message:search",
                    "time_in_nanos": 205654,
                    "breakdown": {
                      "set_min_competitive_score_count": 0,
                      "match_count": 0,
                      "shallow_advance_count": 3,
                      "set_min_competitive_score": 0,
                      "next_doc": 0,
                      "match": 0,
                      "next_doc_count": 0,
                      "score_count": 5,
                      "compute_max_score_count": 3,
                      "compute_max_score": 6678,
                      "advance": 12733,
                      "advance_count": 6,
                      "score": 6627,
                      "build_scorer_count": 3,
                      "create_weight": 130951,
                      "shallow_advance": 2512,
                      "create_weight_count": 1,
                      "build_scorer": 46153,
                      "count_weight": 0,
                      "count_weight_count": 0
                    }
                  }
                ]
              }
            ],
            "rewrite_time": 451233,
            "collector": [
              {
                "name": "QueryPhaseCollector",
                "reason": "search_query_phase",
                "time_in_nanos": 775274,
                "children" : [
                  {
                    "name": "SimpleTopScoreDocCollector",
                    "reason": "search_top_hits",
                    "time_in_nanos": 775274
                  }
                ]
              }
            ]
          }
        ],
        "aggregations": [],
        "fetch": {
          "type": "fetch",
          "description": "",
          "time_in_nanos": 660555,
          "breakdown": {
            "next_reader": 7292,
            "next_reader_count": 1,
            "load_stored_fields": 299325,
            "load_stored_fields_count": 5,
            "load_source": 3863,
            "load_source_count": 5
          },
          "debug": {
            "stored_fields": ["_id", "_routing", "_source"]
          },
          "children": [
            {
              "type" : "FetchFieldsPhase",
              "description" : "",
              "time_in_nanos" : 238762,
              "breakdown" : {
                "process_count" : 5,
                "process" : 227914,
                "next_reader" : 10848,
                "next_reader_count" : 1
              }
            },
            {
              "type": "FetchSourcePhase",
              "description": "",
              "time_in_nanos": 20443,
              "breakdown": {
                "next_reader": 745,
                "next_reader_count": 1,
                "process": 19698,
                "process_count": 5
              },
              "debug": {
                "fast_path": 5
              }
            },
            {
              "type": "StoredFieldsPhase",
              "description": "",
              "time_in_nanos": 5310,
              "breakdown": {
                "next_reader": 745,
                "next_reader_count": 1,
                "process": 4445,
                "process_count": 5
              }
            }
          ]
        }
      }
    ]
  }
}

返回了搜索结果,但为了简洁起见,此处省略。

即使是简单的查询,响应也相对复杂。让我们在继续更复杂的示例之前,逐个分解它。

profile 响应的整体结构如下

{
   "profile": {
        "shards": [
           {
              "id": "[q2aE02wS1R8qQFnYu6vDVQ][my-index-000001][0]",  
              "node_id": "q2aE02wS1R8qQFnYu6vDVQ",
              "shard_id": 0,
              "index": "my-index-000001",
              "cluster": "(local)",             
              "searches": [
                 {
                    "query": [...],             
                    "rewrite_time": 51443,      
                    "collector": [...]          
                 }
              ],
              "aggregations": [...],            
              "fetch": {...}                    
           }
        ]
     }
}

为参与响应的每个分片返回一个 profile,并通过唯一 ID 标识。

如果查询是在本地集群上运行的,则集群名称将从复合 ID 中删除,并在此处标记为“(local)”。对于使用跨集群搜索在 remote_cluster 上运行的 profile,“id”值将类似于 [q2aE02wS1R8qQFnYu6vDVQ][remote1:my-index-000001][0],“cluster”值将为 remote1

查询计时和其他调试信息。

累积的重写时间。

每个收集器的名称和调用计时。

聚合计时、调用计数和调试信息。

获取计时和调试信息。

由于搜索请求可能会针对索引中的一个或多个分片执行,并且一个搜索可能覆盖一个或多个索引,因此 profile 响应中的顶级元素是一个 shard 对象数组。每个分片对象列出其 id,该 ID 唯一标识分片。ID 的格式为 [nodeID][clusterName:indexName][shardID]。如果搜索是针对本地集群运行的,则不添加 clusterName,格式为 [nodeID][indexName][shardID]

profile 本身可能包含一个或多个“搜索”,其中搜索是针对底层 Lucene 索引执行的查询。用户提交的大多数搜索请求将仅针对 Lucene 索引执行单个 search。但有时会执行多个搜索,例如包括全局聚合(需要为全局上下文执行辅助“match_all”查询)。

在每个 search 对象中,将有两个已分析信息的数组:query 数组和 collector 数组。与 search 对象一起,还有一个 aggregations 对象,其中包含聚合的性能分析信息。将来可能会添加更多部分,例如 suggesthighlight 等。

还会有一个 rewrite 指标,显示重写查询所花费的总时间(以纳秒为单位)。

与其他统计信息 API 一样,Profile API 支持人类可读的输出。可以通过将 ?human=true 添加到查询字符串来启用此功能。在这种情况下,输出包含额外的 time 字段,其中包含四舍五入的、人类可读的计时信息(例如 "time": "391,9ms""time": "123.3micros")。

分析查询

编辑

Profile API 提供的详细信息直接公开了 Lucene 类名称和概念,这意味着对结果的完整解释需要相当高级的 Lucene 知识。此页面试图简要介绍 Lucene 如何执行查询,以便你可以使用 Profile API 成功诊断和调试查询,但这只是一个概述。为了完全理解,请参阅 Lucene 的文档,在某些情况下,请参阅代码。

话虽如此,通常不需要完全理解即可修复缓慢的查询。通常,只需看到查询的特定组件速度较慢,而不必理解为什么例如该查询的 advance 阶段是原因,这就足够了。

query 部分

编辑

query 部分包含有关 Lucene 在特定分片上执行的查询树的详细计时。此查询树的整体结构将与你原始的 Elasticsearch 查询类似,但可能略有不同(有时差异很大)。它还将使用类似但不总是相同的命名。使用我们之前的 match 查询示例,让我们分析 query 部分

"query": [
    {
       "type": "BooleanQuery",
       "description": "message:get message:search",
       "time_in_nanos": "11972972",
       "breakdown": {...},               
       "children": [
          {
             "type": "TermQuery",
             "description": "message:get",
             "time_in_nanos": "3801935",
             "breakdown": {...}
          },
          {
             "type": "TermQuery",
             "description": "message:search",
             "time_in_nanos": "205654",
             "breakdown": {...}
          }
       ]
    }
]

为了简单起见,省略了分解计时。

基于 profile 结构,我们可以看到我们的 match 查询被 Lucene 重写为一个包含两个子句 (都包含 TermQuery) 的 BooleanQuery。type 字段显示 Lucene 类名称,并且通常与 Elasticsearch 中的等效名称对齐。description 字段显示查询的 Lucene 说明文本,并且可以用来帮助区分查询的各个部分(例如,message:getmessage:search 都是 TermQuery,否则它们看起来会相同)。

time_in_nanos 字段显示整个 BooleanQuery 的执行时间约为 11.9 毫秒。记录的时间包括所有子项。

breakdown 字段将提供有关时间如何花费的详细统计信息,我们稍后将对此进行研究。最后,children 数组列出可能存在的任何子查询。因为我们搜索了两个值 (“get search”),所以我们的 BooleanQuery 包含两个子 TermQuery。它们具有相同的信息(类型、时间、分解等)。允许子项拥有自己的子项。

计时分解

编辑

breakdown 组件列出有关底层 Lucene 执行的详细计时统计信息

"breakdown": {
  "set_min_competitive_score_count": 0,
  "match_count": 5,
  "shallow_advance_count": 0,
  "set_min_competitive_score": 0,
  "next_doc": 39022,
  "match": 4456,
  "next_doc_count": 5,
  "score_count": 5,
  "compute_max_score_count": 0,
  "compute_max_score": 0,
  "advance": 84525,
  "advance_count": 1,
  "score": 37779,
  "build_scorer_count": 2,
  "create_weight": 4694895,
  "shallow_advance": 0,
  "create_weight_count": 1,
  "build_scorer": 7112295,
  "count_weight": 0,
  "count_weight_count": 0
}

计时以挂钟纳秒为单位列出,并且根本没有标准化。关于整体 time_in_nanos 的所有注意事项都适用于此处。分解的目的是让你了解 A) Lucene 中哪些机制实际上占用了时间,以及 B) 各个组件之间的时间差异的大小。与整体时间一样,分解包括所有子项的时间。

统计信息的含义如下

所有参数
编辑

create_weight

Lucene 中的查询必须能够在多个 IndexSearcher 中重复使用(可以将其视为针对特定 Lucene 索引执行搜索的引擎)。这使 Lucene 处于棘手的位置,因为许多查询需要累积与它所使用的索引关联的临时状态/统计信息,但 Query 合约规定它必须是不可变的。

为了解决这个问题,Lucene 要求每个查询生成一个 Weight 对象,该对象充当临时上下文对象,以保存与此特定(IndexSearcher、Query)元组关联的状态。weight 指标显示此过程所花费的时间

build_scorer

此参数显示为查询构建 Scorer 所花费的时间。Scorer 是一种迭代匹配文档并生成每个文档得分的机制(例如,“foo”与文档的匹配程度如何?)。请注意,这会记录生成 Scorer 对象所需的时间,而不是实际为文档评分的时间。某些查询的 Scorer 初始化速度较快或较慢,具体取决于优化、复杂性等。

如果启用和/或适用于查询,这也可能会显示与缓存关联的计时

next_doc

Lucene 方法 next_doc 返回与查询匹配的下一个文档的文档 ID。此统计信息显示确定哪个文档是下一个匹配项所花费的时间,此过程因查询的性质而异。Next_doc 是 advance() 的一种特殊形式,对于 Lucene 中的许多查询更方便。它等效于 advance(docId() + 1)

advance

advance 是 next_doc 的“较低级别”版本:它用于查找下一个匹配文档的目的相同,但需要调用查询执行额外的任务,例如识别和跳过跳过等。但是,并非所有查询都可以使用 next_doc,因此也会为这些查询计时 advance

连词(例如,Boolean 中的 must 子句)是 advance 的典型使用者

match

某些查询(例如短语查询)使用“两阶段”过程来匹配文档。首先,文档被“近似”匹配,如果它近似匹配,则使用更严格(且成本更高)的过程再次检查它。第二阶段验证是 match 统计数据衡量的标准。

例如,短语查询首先通过确保短语中的所有术语都存在于文档中来近似检查文档。如果所有术语都存在,则它会执行第二阶段验证,以确保术语按顺序形成短语,这比仅检查术语的存在相对昂贵。

由于此两阶段过程仅由少数查询使用,因此 match 统计信息通常为零

score

这会记录通过 Scorer 为特定文档评分所花费的时间

*_count

记录特定方法的调用次数。例如,"next_doc_count": 2, 表示在两个不同的文档上调用了 nextDoc() 方法。这可以通过比较不同查询组件之间的计数来帮助判断查询的选择性。

collectors 部分

编辑

响应的收集器部分显示高级执行详细信息。Lucene 通过定义“收集器”来工作,该收集器负责协调匹配文档的遍历、评分和收集。收集器还是单个查询如何记录聚合结果、执行无范围的“全局”查询、执行查询后过滤器等的方式。

看一下之前的示例

"collector": [
  {
    "name": "QueryPhaseCollector",
    "reason": "search_query_phase",
    "time_in_nanos": 775274,
    "children" : [
      {
        "name": "SimpleTopScoreDocCollector",
        "reason": "search_top_hits",
        "time_in_nanos": 775274
      }
    ]
  }
]

我们看到一个名为 QueryPhaseCollector 的顶层收集器,它包含一个子收集器 SimpleTopScoreDocCollectorSimpleTopScoreDocCollector 是 Elasticsearch 使用的默认“评分和排序”收集器reason 字段尝试提供类名称的纯英文描述。time_in_nanos 与 Query 树中的时间类似:包括所有子项的挂钟时间。同样,children 列出所有子收集器。当请求聚合时,QueryPhaseCollector 将包含一个额外的子收集器,其原因 aggregation 是执行聚合的收集器。

需要注意的是,收集器时间与查询时间相互独立。它们是独立计算、组合和标准化的!由于 Lucene 执行的特性,无法将收集器的时间“合并”到查询部分,因此它们会分开显示。

作为参考,各种收集器的原因如下:

search_top_hits

一个对文档进行评分和排序的收集器。这是最常见的收集器,会在大多数简单搜索中看到。

search_count

一个仅计算与查询匹配的文档数量但不获取源的收集器。当指定 size: 0 时会看到此收集器。

search_query_phase

一个将收集热门结果以及聚合作为查询阶段一部分的收集器。它支持在找到 n 个匹配文档后终止搜索执行(当指定 terminate_after 时),以及仅返回得分大于 n 的匹配文档(当提供 min_score 时)。此外,它还能够根据提供的 post_filter 过滤匹配的热门结果。

search_timeout

一个在指定时间段后停止执行的收集器。当指定了顶层参数 timeout 时会看到此收集器。

aggregation

Elasticsearch 使用的一个收集器,用于对查询范围执行聚合。单个 aggregation 收集器用于收集 所有 聚合的文档,因此您会在名称中看到聚合列表。

global_aggregation

一个对全局查询范围(而不是指定的查询)执行聚合的收集器。由于全局范围与执行的查询必然不同,它必须执行自己的 match_all 查询(您将在查询部分看到添加的此查询)来收集您的整个数据集。

rewrite 部分

编辑

Lucene 中的所有查询都会经历一个“重写”过程。一个查询(及其子查询)可能会被重写一次或多次,并且该过程会一直持续到查询停止更改为止。此过程允许 Lucene 执行优化,例如删除冗余子句、用更高效的执行路径替换一个查询等。例如,Boolean → Boolean → TermQuery 可以重写为 TermQuery,因为在这种情况下所有 Boolean 都是不必要的。

重写过程是复杂且难以显示的,因为查询可能会发生巨大变化。与其显示中间结果,不如简单地将总重写时间显示为一个值(以纳秒为单位)。此值为累积值,包含所有正在重写的查询的总时间。

一个更复杂的示例

编辑

为了演示稍微复杂一些的查询和关联的结果,我们可以分析以下查询

resp = client.search(
    index="my-index-000001",
    profile=True,
    query={
        "term": {
            "user.id": {
                "value": "elkbee"
            }
        }
    },
    aggs={
        "my_scoped_agg": {
            "terms": {
                "field": "http.response.status_code"
            }
        },
        "my_global_agg": {
            "global": {},
            "aggs": {
                "my_level_agg": {
                    "terms": {
                        "field": "http.response.status_code"
                    }
                }
            }
        }
    },
    post_filter={
        "match": {
            "message": "search"
        }
    },
)
print(resp)
response = client.search(
  index: 'my-index-000001',
  body: {
    profile: true,
    query: {
      term: {
        'user.id' => {
          value: 'elkbee'
        }
      }
    },
    aggregations: {
      my_scoped_agg: {
        terms: {
          field: 'http.response.status_code'
        }
      },
      my_global_agg: {
        global: {},
        aggregations: {
          my_level_agg: {
            terms: {
              field: 'http.response.status_code'
            }
          }
        }
      }
    },
    post_filter: {
      match: {
        message: 'search'
      }
    }
  }
)
puts response
const response = await client.search({
  index: "my-index-000001",
  profile: true,
  query: {
    term: {
      "user.id": {
        value: "elkbee",
      },
    },
  },
  aggs: {
    my_scoped_agg: {
      terms: {
        field: "http.response.status_code",
      },
    },
    my_global_agg: {
      global: {},
      aggs: {
        my_level_agg: {
          terms: {
            field: "http.response.status_code",
          },
        },
      },
    },
  },
  post_filter: {
    match: {
      message: "search",
    },
  },
});
console.log(response);
GET /my-index-000001/_search
{
  "profile": true,
  "query": {
    "term": {
      "user.id": {
        "value": "elkbee"
      }
    }
  },
  "aggs": {
    "my_scoped_agg": {
      "terms": {
        "field": "http.response.status_code"
      }
    },
    "my_global_agg": {
      "global": {},
      "aggs": {
        "my_level_agg": {
          "terms": {
            "field": "http.response.status_code"
          }
        }
      }
    }
  },
  "post_filter": {
    "match": {
      "message": "search"
    }
  }
}

此示例具有

  • 一个查询
  • 一个范围聚合
  • 一个全局聚合
  • 一个 post_filter

API 返回以下结果

{
  ...
  "profile": {
    "shards": [
      {
        "id": "[P6xvulHtQRWuD4YnubWb7A][my-index-000001][0]",
        "node_id": "P6xvulHtQRWuD4YnubWb7A",
        "shard_id": 0,
        "index": "my-index-000001",
        "cluster": "(local)",
        "searches": [
          {
            "query": [
              {
                "type": "TermQuery",
                "description": "message:search",
                "time_in_nanos": 141618,
                "breakdown": {
                  "set_min_competitive_score_count": 0,
                  "match_count": 0,
                  "shallow_advance_count": 0,
                  "set_min_competitive_score": 0,
                  "next_doc": 0,
                  "match": 0,
                  "next_doc_count": 0,
                  "score_count": 0,
                  "compute_max_score_count": 0,
                  "compute_max_score": 0,
                  "advance": 3942,
                  "advance_count": 4,
                  "count_weight_count": 0,
                  "score": 0,
                  "build_scorer_count": 2,
                  "create_weight": 38380,
                  "shallow_advance": 0,
                  "count_weight": 0,
                  "create_weight_count": 1,
                  "build_scorer": 99296
                }
              },
              {
                "type": "TermQuery",
                "description": "user.id:elkbee",
                "time_in_nanos": 163081,
                "breakdown": {
                  "set_min_competitive_score_count": 0,
                  "match_count": 0,
                  "shallow_advance_count": 0,
                  "set_min_competitive_score": 0,
                  "next_doc": 2447,
                  "match": 0,
                  "next_doc_count": 4,
                  "score_count": 4,
                  "compute_max_score_count": 0,
                  "compute_max_score": 0,
                  "advance": 3552,
                  "advance_count": 1,
                  "score": 5027,
                  "count_weight_count": 0,
                  "build_scorer_count": 2,
                  "create_weight": 107840,
                  "shallow_advance": 0,
                  "count_weight": 0,
                  "create_weight_count": 1,
                  "build_scorer": 44215
                }
              }
            ],
            "rewrite_time": 4769,
            "collector": [
              {
                "name": "QueryPhaseCollector",
                "reason": "search_query_phase",
                "time_in_nanos": 1945072,
                "children": [
                  {
                    "name": "SimpleTopScoreDocCollector",
                    "reason": "search_top_hits",
                    "time_in_nanos": 22577
                  },
                  {
                    "name": "AggregatorCollector: [my_scoped_agg, my_global_agg]",
                    "reason": "aggregation",
                    "time_in_nanos": 867617
                  }
                ]
              }
            ]
          }
        ],
        "aggregations": [...], 
        "fetch": {...}
      }
    ]
  }
}

已省略 "aggregations" 部分,因为它将在下一节中介绍。

如您所见,输出比以前详细得多。查询的所有主要部分都已表示出来

  1. 第一个 TermQuery (user.id:elkbee) 表示主要的 term 查询。
  2. 第二个 TermQuery (message:search) 表示 post_filter 查询。

收集器树非常简单,显示了单个 QueryPhaseCollector 如何保存用于收集热门结果的普通评分 SimpleTopScoreDocCollector,以及用于运行所有范围聚合的 BucketCollectorWrapper。

了解 MultiTermQuery 输出

编辑

需要特别注意 MultiTermQuery 查询类。这包括通配符、正则表达式和模糊查询。这些查询会发出非常详细的响应,并且结构不够清晰。

本质上,这些查询会根据每个段重写自身。如果您想象通配符查询 b*,它在技术上可以匹配任何以字母“b”开头的标记。枚举所有可能的组合是不可能的,因此 Lucene 会在被评估的段的上下文中重写查询,例如,一个段可能包含标记 [bar, baz],因此查询会重写为“bar”和“baz”的 BooleanQuery 组合。另一个段可能只有标记 [bakery],因此查询会重写为“bakery”的单个 TermQuery。

由于这种动态的、基于每个段的重写,干净的树结构会失真,不再遵循清晰的“血统”来显示一个查询如何重写为下一个查询。目前,我们只能抱歉,并建议您如果觉得该查询的子项太令人困惑,请折叠该查询的详细信息。幸运的是,所有计时统计数据都是正确的,只是响应中的物理布局不正确,因此只需分析顶级的 MultiTermQuery,如果您发现详细信息太难理解,则忽略其子项就足够了。

希望这在未来的迭代中得到修复,但这仍然是一个棘手的问题,仍在进行中。:)

分析聚合

编辑
aggregations 部分
编辑

aggregations 部分包含特定分片执行的聚合树的详细计时。此聚合树的整体结构将类似于您原始的 Elasticsearch 请求。让我们再次执行之前的查询,这次看看聚合分析

resp = client.search(
    index="my-index-000001",
    profile=True,
    query={
        "term": {
            "user.id": {
                "value": "elkbee"
            }
        }
    },
    aggs={
        "my_scoped_agg": {
            "terms": {
                "field": "http.response.status_code"
            }
        },
        "my_global_agg": {
            "global": {},
            "aggs": {
                "my_level_agg": {
                    "terms": {
                        "field": "http.response.status_code"
                    }
                }
            }
        }
    },
    post_filter={
        "match": {
            "message": "search"
        }
    },
)
print(resp)
response = client.search(
  index: 'my-index-000001',
  body: {
    profile: true,
    query: {
      term: {
        'user.id' => {
          value: 'elkbee'
        }
      }
    },
    aggregations: {
      my_scoped_agg: {
        terms: {
          field: 'http.response.status_code'
        }
      },
      my_global_agg: {
        global: {},
        aggregations: {
          my_level_agg: {
            terms: {
              field: 'http.response.status_code'
            }
          }
        }
      }
    },
    post_filter: {
      match: {
        message: 'search'
      }
    }
  }
)
puts response
const response = await client.search({
  index: "my-index-000001",
  profile: true,
  query: {
    term: {
      "user.id": {
        value: "elkbee",
      },
    },
  },
  aggs: {
    my_scoped_agg: {
      terms: {
        field: "http.response.status_code",
      },
    },
    my_global_agg: {
      global: {},
      aggs: {
        my_level_agg: {
          terms: {
            field: "http.response.status_code",
          },
        },
      },
    },
  },
  post_filter: {
    match: {
      message: "search",
    },
  },
});
console.log(response);
GET /my-index-000001/_search
{
  "profile": true,
  "query": {
    "term": {
      "user.id": {
        "value": "elkbee"
      }
    }
  },
  "aggs": {
    "my_scoped_agg": {
      "terms": {
        "field": "http.response.status_code"
      }
    },
    "my_global_agg": {
      "global": {},
      "aggs": {
        "my_level_agg": {
          "terms": {
            "field": "http.response.status_code"
          }
        }
      }
    }
  },
  "post_filter": {
    "match": {
      "message": "search"
    }
  }
}

这将产生以下聚合分析输出

{
  "profile": {
    "shards": [
      {
        "aggregations": [
          {
            "type": "NumericTermsAggregator",
            "description": "my_scoped_agg",
            "time_in_nanos": 79294,
            "breakdown": {
              "reduce": 0,
              "build_aggregation": 30885,
              "build_aggregation_count": 1,
              "initialize": 2623,
              "initialize_count": 1,
              "reduce_count": 0,
              "collect": 45786,
              "collect_count": 4,
              "build_leaf_collector": 18211,
              "build_leaf_collector_count": 1,
              "post_collection": 929,
              "post_collection_count": 1
            },
            "debug": {
              "total_buckets": 1,
              "result_strategy": "long_terms",
              "built_buckets": 1
            }
          },
          {
            "type": "GlobalAggregator",
            "description": "my_global_agg",
            "time_in_nanos": 104325,
            "breakdown": {
              "reduce": 0,
              "build_aggregation": 22470,
              "build_aggregation_count": 1,
              "initialize": 12454,
              "initialize_count": 1,
              "reduce_count": 0,
              "collect": 69401,
              "collect_count": 4,
              "build_leaf_collector": 8150,
              "build_leaf_collector_count": 1,
              "post_collection": 1584,
              "post_collection_count": 1
            },
            "debug": {
              "built_buckets": 1
            },
            "children": [
              {
                "type": "NumericTermsAggregator",
                "description": "my_level_agg",
                "time_in_nanos": 76876,
                "breakdown": {
                  "reduce": 0,
                  "build_aggregation": 13824,
                  "build_aggregation_count": 1,
                  "initialize": 1441,
                  "initialize_count": 1,
                  "reduce_count": 0,
                  "collect": 61611,
                  "collect_count": 4,
                  "build_leaf_collector": 5564,
                  "build_leaf_collector_count": 1,
                  "post_collection": 471,
                  "post_collection_count": 1
                },
                "debug": {
                  "total_buckets": 1,
                  "result_strategy": "long_terms",
                  "built_buckets": 1
                }
              }
            ]
          }
        ]
      }
    ]
  }
}

从分析结构中我们可以看到,my_scoped_agg 在内部作为 NumericTermsAggregator 运行(因为它正在聚合的字段 http.response.status_code 是一个数字字段)。在同一级别,我们看到一个来自 my_global_aggGlobalAggregator。该聚合然后有一个子项 NumericTermsAggregator,它来自 http.response.status_code 的第二个词项的聚合。

time_in_nanos 字段显示每个聚合执行的时间,并且包括所有子项。虽然总时间很有用,但 breakdown 字段将提供有关时间如何花费的详细统计信息。

一些聚合可能会返回专家 debug 信息,这些信息描述了聚合底层执行的特性,“对于那些处理聚合的人员很有用,但我们不希望对其他人有用。它们在版本、聚合和聚合执行策略之间可能会有很大差异。

计时细分

编辑

breakdown 组件列出了有关底层执行的详细统计信息

"breakdown": {
  "reduce": 0,
  "build_aggregation": 30885,
  "build_aggregation_count": 1,
  "initialize": 2623,
  "initialize_count": 1,
  "reduce_count": 0,
  "collect": 45786,
  "collect_count": 4,
  "build_leaf_collector": 18211,
  "build_leaf_collector_count": 1
}

breakdown 组件中的每个属性都对应于聚合的内部方法。例如,build_leaf_collector 属性测量运行聚合的 getLeafCollector() 方法所花费的纳秒数。以 _count 结尾的属性记录特定方法的调用次数。例如,"collect_count": 2 表示聚合在两个不同的文档上调用了 collect()reduce 属性保留供将来使用,并且始终返回 0

计时以挂钟纳秒为单位列出,并且根本没有标准化。有关总体 time 的所有警告都适用于此处。细分的目的是让您了解 A) Elasticsearch 中哪些机制实际上占用了时间,以及 B) 各个组件之间的时间差异幅度。与总时间一样,细分包括所有子项的时间。

分析获取

编辑

所有获取文档的分片都将在分析中有一个 fetch 部分。让我们执行一个小搜索并查看获取分析

resp = client.search(
    index="my-index-000001",
    filter_path="profile.shards.fetch",
    profile=True,
    query={
        "term": {
            "user.id": {
                "value": "elkbee"
            }
        }
    },
)
print(resp)
response = client.search(
  index: 'my-index-000001',
  filter_path: 'profile.shards.fetch',
  body: {
    profile: true,
    query: {
      term: {
        'user.id' => {
          value: 'elkbee'
        }
      }
    }
  }
)
puts response
const response = await client.search({
  index: "my-index-000001",
  filter_path: "profile.shards.fetch",
  profile: true,
  query: {
    term: {
      "user.id": {
        value: "elkbee",
      },
    },
  },
});
console.log(response);
GET /my-index-000001/_search?filter_path=profile.shards.fetch
{
  "profile": true,
  "query": {
    "term": {
      "user.id": {
        "value": "elkbee"
      }
    }
  }
}

这是获取分析

{
  "profile": {
    "shards": [
      {
        "fetch": {
          "type": "fetch",
          "description": "",
          "time_in_nanos": 660555,
          "breakdown": {
            "next_reader": 7292,
            "next_reader_count": 1,
            "load_stored_fields": 299325,
            "load_stored_fields_count": 5,
            "load_source": 3863,
            "load_source_count": 5
          },
          "debug": {
            "stored_fields": ["_id", "_routing", "_source"]
          },
          "children": [
            {
              "type" : "FetchFieldsPhase",
              "description" : "",
              "time_in_nanos" : 238762,
              "breakdown" : {
                "process_count" : 5,
                "process" : 227914,
                "next_reader" : 10848,
                "next_reader_count" : 1
              }
            },
            {
              "type": "FetchSourcePhase",
              "description": "",
              "time_in_nanos": 20443,
              "breakdown": {
                "next_reader": 745,
                "next_reader_count": 1,
                "process": 19698,
                "process_count": 5
              },
              "debug": {
                "fast_path": 4
              }
            },
            {
              "type": "StoredFieldsPhase",
              "description": "",
              "time_in_nanos": 5310,
              "breakdown": {
                "next_reader": 745,
                "next_reader_count": 1,
                "process": 4445,
                "process_count": 5
              }
            }
          ]
        }
      }
    ]
  }
}

由于这是有关 Elasticsearch 执行获取方式的调试信息,因此它可能会根据请求和版本的不同而更改。即使是补丁版本也可能会更改此处的输出。这种缺乏一致性使其对于调试很有用。

无论如何!time_in_nanos 测量获取阶段的总时间。breakdown 计算并计时我们在 next_reader 中的每个准备,以及在 load_stored_fields 中加载存储字段所花费的时间。Debug 包含各种非计时信息,特别是 stored_fields 列出了获取必须加载的存储字段。如果它是一个空列表,则获取将完全跳过加载存储字段。

children 部分列出了执行实际获取工作的子阶段,并且 breakdown 具有 next_reader 中每个准备以及 process 中每个文档获取的计数和计时。

我们努力提前加载获取所需的所有存储字段。这往往会使 _source 阶段每次命中花费几微秒。在这种情况下,_source 阶段的真正成本隐藏在细分的 load_stored_fields 组件中。可以通过设置 "_source": false, "stored_fields": ["_none_"] 来完全跳过加载存储字段。

分析 DFS

编辑

DFS 阶段在查询阶段之前运行,以收集与查询相关的全局信息。它目前用于两种情况

  1. search_type 设置为 dfs_query_then_fetch 并且索引具有多个分片时。
  2. 当搜索请求包含 knn 部分时。

可以通过将 profile 设置为搜索请求的一部分的 true 来分析这两种情况。

分析 DFS 统计信息
编辑

search_type 设置为 dfs_query_then_fetch 并且索引具有多个分片时,dfs 阶段会收集词项统计信息以提高搜索结果的相关性。

以下是在使用 dfs_query_then_fetch 的搜索中将 profile 设置为 true 的示例

让我们首先设置一个具有多个分片的索引,并在 keyword 字段上索引一对具有不同值的文档。

resp = client.indices.create(
    index="my-dfs-index",
    settings={
        "number_of_shards": 2,
        "number_of_replicas": 1
    },
    mappings={
        "properties": {
            "my-keyword": {
                "type": "keyword"
            }
        }
    },
)
print(resp)

resp1 = client.bulk(
    index="my-dfs-index",
    refresh=True,
    operations=[
        {
            "index": {
                "_id": "1"
            }
        },
        {
            "my-keyword": "a"
        },
        {
            "index": {
                "_id": "2"
            }
        },
        {
            "my-keyword": "b"
        }
    ],
)
print(resp1)
response = client.indices.create(
  index: 'my-dfs-index',
  body: {
    settings: {
      number_of_shards: 2,
      number_of_replicas: 1
    },
    mappings: {
      properties: {
        "my-keyword": {
          type: 'keyword'
        }
      }
    }
  }
)
puts response

response = client.bulk(
  index: 'my-dfs-index',
  refresh: true,
  body: [
    {
      index: {
        _id: '1'
      }
    },
    {
      "my-keyword": 'a'
    },
    {
      index: {
        _id: '2'
      }
    },
    {
      "my-keyword": 'b'
    }
  ]
)
puts response
const response = await client.indices.create({
  index: "my-dfs-index",
  settings: {
    number_of_shards: 2,
    number_of_replicas: 1,
  },
  mappings: {
    properties: {
      "my-keyword": {
        type: "keyword",
      },
    },
  },
});
console.log(response);

const response1 = await client.bulk({
  index: "my-dfs-index",
  refresh: "true",
  operations: [
    {
      index: {
        _id: "1",
      },
    },
    {
      "my-keyword": "a",
    },
    {
      index: {
        _id: "2",
      },
    },
    {
      "my-keyword": "b",
    },
  ],
});
console.log(response1);
PUT my-dfs-index
{
  "settings": {
    "number_of_shards": 2, 
    "number_of_replicas": 1
  },
  "mappings": {
      "properties": {
        "my-keyword": { "type": "keyword" }
      }
    }
}

POST my-dfs-index/_bulk?refresh=true
{ "index" : { "_id" : "1" } }
{ "my-keyword" : "a" }
{ "index" : { "_id" : "2" } }
{ "my-keyword" : "b" }

创建的 my-dfs-index 具有多个分片。

设置索引后,我们现在可以分析搜索查询的 dfs 阶段。对于此示例,我们使用词项查询。

resp = client.search(
    index="my-dfs-index",
    search_type="dfs_query_then_fetch",
    pretty=True,
    size="0",
    profile=True,
    query={
        "term": {
            "my-keyword": {
                "value": "a"
            }
        }
    },
)
print(resp)
response = client.search(
  index: 'my-dfs-index',
  search_type: 'dfs_query_then_fetch',
  pretty: true,
  size: 0,
  body: {
    profile: true,
    query: {
      term: {
        "my-keyword": {
          value: 'a'
        }
      }
    }
  }
)
puts response
const response = await client.search({
  index: "my-dfs-index",
  search_type: "dfs_query_then_fetch",
  pretty: "true",
  size: 0,
  profile: true,
  query: {
    term: {
      "my-keyword": {
        value: "a",
      },
    },
  },
});
console.log(response);
GET /my-dfs-index/_search?search_type=dfs_query_then_fetch&pretty&size=0 
{
  "profile": true, 
  "query": {
    "term": {
      "my-keyword": {
        "value": "a"
      }
    }
  }
}

search_type url 参数设置为 dfs_query_then_fetch 以确保运行 dfs 阶段。

profile 参数设置为 true

在响应中,我们看到一个分析,其中包含每个分片的 dfs 部分以及搜索阶段其余部分的分析输出。一个分片的 dfs 部分如下所示

"dfs" : {
    "statistics" : {
        "type" : "statistics",
        "description" : "collect term statistics",
        "time_in_nanos" : 236955,
        "breakdown" : {
            "term_statistics" : 4815,
            "collection_statistics" : 27081,
            "collection_statistics_count" : 1,
            "create_weight" : 153278,
            "term_statistics_count" : 1,
            "rewrite_count" : 0,
            "create_weight_count" : 1,
            "rewrite" : 0
        }
    }
}

在此响应的 dfs.statistics 部分,我们可以看到 time_in_nanos,它是收集此分片术语统计信息的总耗时,以及各个部分的进一步细分。

分析 kNN 搜索
编辑

k 最近邻 (kNN) 搜索在 dfs 阶段运行。

以下是在具有 knn 部分的搜索中将 profile 设置为 true 的示例

首先,让我们设置一个包含多个密集向量的索引。

resp = client.indices.create(
    index="my-knn-index",
    mappings={
        "properties": {
            "my-vector": {
                "type": "dense_vector",
                "dims": 3,
                "index": True,
                "similarity": "l2_norm"
            }
        }
    },
)
print(resp)

resp1 = client.bulk(
    index="my-knn-index",
    refresh=True,
    operations=[
        {
            "index": {
                "_id": "1"
            }
        },
        {
            "my-vector": [
                1,
                5,
                -20
            ]
        },
        {
            "index": {
                "_id": "2"
            }
        },
        {
            "my-vector": [
                42,
                8,
                -15
            ]
        },
        {
            "index": {
                "_id": "3"
            }
        },
        {
            "my-vector": [
                15,
                11,
                23
            ]
        }
    ],
)
print(resp1)
response = client.indices.create(
  index: 'my-knn-index',
  body: {
    mappings: {
      properties: {
        "my-vector": {
          type: 'dense_vector',
          dims: 3,
          index: true,
          similarity: 'l2_norm'
        }
      }
    }
  }
)
puts response

response = client.bulk(
  index: 'my-knn-index',
  refresh: true,
  body: [
    {
      index: {
        _id: '1'
      }
    },
    {
      "my-vector": [
        1,
        5,
        -20
      ]
    },
    {
      index: {
        _id: '2'
      }
    },
    {
      "my-vector": [
        42,
        8,
        -15
      ]
    },
    {
      index: {
        _id: '3'
      }
    },
    {
      "my-vector": [
        15,
        11,
        23
      ]
    }
  ]
)
puts response
const response = await client.indices.create({
  index: "my-knn-index",
  mappings: {
    properties: {
      "my-vector": {
        type: "dense_vector",
        dims: 3,
        index: true,
        similarity: "l2_norm",
      },
    },
  },
});
console.log(response);

const response1 = await client.bulk({
  index: "my-knn-index",
  refresh: "true",
  operations: [
    {
      index: {
        _id: "1",
      },
    },
    {
      "my-vector": [1, 5, -20],
    },
    {
      index: {
        _id: "2",
      },
    },
    {
      "my-vector": [42, 8, -15],
    },
    {
      index: {
        _id: "3",
      },
    },
    {
      "my-vector": [15, 11, 23],
    },
  ],
});
console.log(response1);
PUT my-knn-index
{
  "mappings": {
    "properties": {
      "my-vector": {
        "type": "dense_vector",
        "dims": 3,
        "index": true,
        "similarity": "l2_norm"
      }
    }
  }
}

POST my-knn-index/_bulk?refresh=true
{ "index": { "_id": "1" } }
{ "my-vector": [1, 5, -20] }
{ "index": { "_id": "2" } }
{ "my-vector": [42, 8, -15] }
{ "index": { "_id": "3" } }
{ "my-vector": [15, 11, 23] }

完成索引设置后,我们现在可以分析 kNN 搜索查询。

resp = client.search(
    index="my-knn-index",
    profile=True,
    knn={
        "field": "my-vector",
        "query_vector": [
            -5,
            9,
            -12
        ],
        "k": 3,
        "num_candidates": 100
    },
)
print(resp)
response = client.search(
  index: 'my-knn-index',
  body: {
    profile: true,
    knn: {
      field: 'my-vector',
      query_vector: [
        -5,
        9,
        -12
      ],
      k: 3,
      num_candidates: 100
    }
  }
)
puts response
const response = await client.search({
  index: "my-knn-index",
  profile: true,
  knn: {
    field: "my-vector",
    query_vector: [-5, 9, -12],
    k: 3,
    num_candidates: 100,
  },
});
console.log(response);
POST my-knn-index/_search
{
  "profile": true, 
  "knn": {
    "field": "my-vector",
    "query_vector": [-5, 9, -12],
    "k": 3,
    "num_candidates": 100
  }
}

profile 参数设置为 true

在响应中,我们看到一个配置文件,其中包括每个分片的 dfs 部分中的 knn 部分,以及其余搜索阶段的配置文件输出。

分片的其中一个 dfs.knn 部分如下所示

"dfs" : {
    "knn" : [
        {
        "vector_operations_count" : 4,
        "query" : [
            {
                "type" : "DocAndScoreQuery",
                "description" : "DocAndScore[100]",
                "time_in_nanos" : 444414,
                "breakdown" : {
                  "set_min_competitive_score_count" : 0,
                  "match_count" : 0,
                  "shallow_advance_count" : 0,
                  "set_min_competitive_score" : 0,
                  "next_doc" : 1688,
                  "match" : 0,
                  "next_doc_count" : 3,
                  "score_count" : 3,
                  "compute_max_score_count" : 0,
                  "compute_max_score" : 0,
                  "advance" : 4153,
                  "advance_count" : 1,
                  "score" : 2099,
                  "build_scorer_count" : 2,
                  "create_weight" : 128879,
                  "shallow_advance" : 0,
                  "create_weight_count" : 1,
                  "build_scorer" : 307595,
                  "count_weight": 0,
                  "count_weight_count": 0
                }
            }
        ],
        "rewrite_time" : 1275732,
        "collector" : [
            {
                "name" : "SimpleTopScoreDocCollector",
                "reason" : "search_top_hits",
                "time_in_nanos" : 17163
            }
        ]
    }   ]
}

在响应的 dfs.knn 部分,我们可以看到 queryrewritecollector 的计时输出。与许多其他查询不同,kNN 搜索在查询重写期间完成大部分工作。这意味着 rewrite_time 表示在 kNN 搜索上花费的时间。属性 vector_operations_count 表示 kNN 搜索期间执行的向量操作的总计数。

分析注意事项

编辑

与任何分析器一样,Profile API 会给搜索执行引入不可忽略的开销。对诸如 collectadvancenext_doc 之类的低级方法调用进行检测可能相当昂贵,因为这些方法是在紧密循环中调用的。因此,默认情况下不应在生产环境中启用分析,并且不应与未分析的查询时间进行比较。分析只是一种诊断工具。

在某些情况下,特殊的 Lucene 优化会被禁用,因为它们不适合进行分析。这可能会导致某些查询报告的相对时间比未分析的查询时间长,但通常与分析查询中的其他组件相比,不应产生剧烈的影响。

局限性

编辑
  • 分析当前不测量网络开销。
  • 分析也不考虑在队列中花费的时间、在协调节点上合并分片响应,或者诸如构建全局序号(用于加速搜索的内部数据结构)之类的其他工作。
  • 建议当前不提供分析统计信息。
  • 当前不提供聚合的 reduce 阶段的分析。
  • 分析器正在检测内部结构,这些内部结构可能会因版本而异。生成的 json 应被视为大部分不稳定,特别是 debug 部分中的内容。