# 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，如果你發現的細節很難解釋請忽視的它的孩子節點。 希望在未來的迭代它會變成固定，但它是一個很難解決的、正在改善中的棘手問題 :)