Profile the fetch phase

This adds profiling to the fetch phase so we can tell when fetching is slower than we'd like and we can tell which portion of the fetch is slow. The output includes which stored fields were loaded, how long it took to load stored fields, which fetch sub-phases were run, and how long those fetch sub-phases took. Closes elastic#75892
nik9000 · Aug 31, 2021 · 8ef3af2 · 8ef3af2
1 parent 90d2899
commit 8ef3af2
Show file tree

Hide file tree

Showing 53 changed files with 1,295 additions and 394 deletions.
diff --git a/.../src/main/java/org/elasticsearch/plugin/noop/action/search/TransportNoopSearchAction.java b/.../src/main/java/org/elasticsearch/plugin/noop/action/search/TransportNoopSearchAction.java
@@ -20,7 +20,7 @@
 import org.elasticsearch.search.SearchHits;
 import org.elasticsearch.search.aggregations.InternalAggregations;
 import org.elasticsearch.search.internal.InternalSearchResponse;
-import org.elasticsearch.search.profile.SearchProfileShardResults;
+import org.elasticsearch.search.profile.SearchProfileResults;
 import org.elasticsearch.search.suggest.Suggest;
 import org.elasticsearch.tasks.Task;
 import org.elasticsearch.transport.TransportService;
@@ -40,7 +40,7 @@ protected void doExecute(Task task, SearchRequest request, ActionListener<Search
                 new SearchHit[0], new TotalHits(0L, TotalHits.Relation.EQUAL_TO), 0.0f),
             InternalAggregations.EMPTY,
             new Suggest(Collections.emptyList()),
-            new SearchProfileShardResults(Collections.emptyMap()), false, false, 1),
+            new SearchProfileResults(Collections.emptyMap()), false, false, 1),
             "", 1, 1, 0, 0, ShardSearchFailure.EMPTY_ARRAY, SearchResponse.Clusters.EMPTY));
     }
 }
diff --git a/...igh-level/src/test/java/org/elasticsearch/client/documentation/SearchDocumentationIT.java b/...igh-level/src/test/java/org/elasticsearch/client/documentation/SearchDocumentationIT.java
@@ -48,9 +48,9 @@
 import org.elasticsearch.common.document.DocumentField;
 import org.elasticsearch.common.text.Text;
 import org.elasticsearch.common.unit.Fuzziness;
-import org.elasticsearch.core.TimeValue;
 import org.elasticsearch.common.xcontent.XContentFactory;
 import org.elasticsearch.common.xcontent.XContentType;
+import org.elasticsearch.core.TimeValue;
 import org.elasticsearch.index.get.GetResult;
 import org.elasticsearch.index.query.MatchQueryBuilder;
 import org.elasticsearch.index.query.QueryBuilder;
@@ -89,7 +89,7 @@
 import org.elasticsearch.search.fetch.subphase.highlight.HighlightBuilder;
 import org.elasticsearch.search.fetch.subphase.highlight.HighlightField;
 import org.elasticsearch.search.profile.ProfileResult;
-import org.elasticsearch.search.profile.ProfileShardResult;
+import org.elasticsearch.search.profile.SearchProfileShardResult;
 import org.elasticsearch.search.profile.aggregation.AggregationProfileShardResult;
 import org.elasticsearch.search.profile.query.CollectorResult;
 import org.elasticsearch.search.profile.query.QueryProfileShardResult;
@@ -499,15 +499,15 @@ public void testSearchRequestProfiling() throws IOException {
 
             SearchResponse searchResponse = client.search(searchRequest, RequestOptions.DEFAULT);
             // tag::search-request-profiling-get
-            Map<String, ProfileShardResult> profilingResults =
+            Map<String, SearchProfileShardResult> profilingResults =
                     searchResponse.getProfileResults(); // <1>
-            for (Map.Entry<String, ProfileShardResult> profilingResult : profilingResults.entrySet()) { // <2>
+            for (Map.Entry<String, SearchProfileShardResult> profilingResult : profilingResults.entrySet()) { // <2>
                 String key = profilingResult.getKey(); // <3>
-                ProfileShardResult profileShardResult = profilingResult.getValue(); // <4>
+                SearchProfileShardResult profileShardResult = profilingResult.getValue(); // <4>
             }
             // end::search-request-profiling-get
 
-            ProfileShardResult profileShardResult = profilingResults.values().iterator().next();
+            SearchProfileShardResult profileShardResult = profilingResults.values().iterator().next();
             assertNotNull(profileShardResult);
 
             // tag::search-request-profiling-queries

diff --git a/docs/reference/search/profile.asciidoc b/docs/reference/search/profile.asciidoc
@@ -163,7 +163,38 @@ The API returns the following result:
             ]
           }
         ],
-        "aggregations": []
+        "aggregations": [],
+        "fetch": {
+          "type": "fetch",
+          "description": "fetch",
+          "time_in_nanos": 660555,
+          "breakdown": {
+            "next_reader": 7292,
+            "next_reader_count": 1,
+            "load_stored_fields": 299325,
+            "load_stored_fields_count": 5
+          },
+          "debug": {
+            "stored_fields": ["_id", "_routing", "_source"]
+          },
+          "children": [
+            {
+              "type": "source",
+              "description": "load _source",
+              "time_in_nanos": 20443,
+              "breakdown": {
+                "next_reader": 745,
+                "next_reader_count": 1,
+                "process": 19698,
+                "process_count": 5
+              },
+              "debug": {
+                "loaded_nested": 0,
+                "fast_path": 5
+              }
+            }
+          ]
+        }
       }
     ]
   }
@@ -196,7 +227,8 @@ The overall structure of the profile response is as follows:
                     "collector": [...]          <4>
                  }
               ],
-              "aggregations": [...]             <5>
+              "aggregations": [...],            <5>
+              "fetch": {...}                    <6>
            }
         ]
      }
@@ -208,15 +240,14 @@ The overall structure of the profile response is as follows:
 // TESTRESPONSE[s/"query": \[...\]/"query": $body.$_path/]
 // TESTRESPONSE[s/"collector": \[...\]/"collector": $body.$_path/]
 // TESTRESPONSE[s/"aggregations": \[...\]/"aggregations": []/]
+// TESTRESPONSE[s/"fetch": \{...\}/"fetch": $body.$_path/]
 <1> A profile is returned for each shard that participated in the response, and 
 is identified by a unique ID.
-<2> Each profile contains a section which holds details about the query 
-execution.
-<3> Each profile has a single time representing the cumulative rewrite time.
-<4> Each profile also contains a section about the Lucene Collectors which run 
-the search.
-<5> Each profile contains a section which holds the details about the 
-aggregation execution.
+<2> Query timings and other debugging information.
+<3> The cumulative rewrite time.
+<4> Names and invocation timings for each collector.
+<5> Aggregation timings, invocation counts, and debug information.
+<6> Fetch timing and debug information.
 
 Because a search request may be executed against one or more shards in an index, 
 and a search may cover one or more indices, the top level element in the profile 
@@ -295,7 +326,7 @@ Using our previous `match` query example, let's analyze the `query` section:
 ]
 --------------------------------------------------
 // TESTRESPONSE[s/^/{\n"took": $body.took,\n"timed_out": $body.timed_out,\n"_shards": $body._shards,\n"hits": $body.hits,\n"profile": {\n"shards": [ {\n"id": "$body.$_path",\n"searches": [{\n/]
-// TESTRESPONSE[s/]$/],"rewrite_time": $body.$_path, "collector": $body.$_path}], "aggregations": []}]}}/]
+// TESTRESPONSE[s/]$/],"rewrite_time": $body.$_path, "collector": $body.$_path}], "aggregations": [], "fetch": $body.$_path}]}}/]
 // TESTRESPONSE[s/(?<=[" ])\d+(\.\d+)?/$body.$_path/]
 // TESTRESPONSE[s/"breakdown": \{...\}/"breakdown": $body.$_path/]
 <1> The breakdown timings are omitted for simplicity.
@@ -347,7 +378,7 @@ Lucene execution:
 }
 --------------------------------------------------
 // TESTRESPONSE[s/^/{\n"took": $body.took,\n"timed_out": $body.timed_out,\n"_shards": $body._shards,\n"hits": $body.hits,\n"profile": {\n"shards": [ {\n"id": "$body.$_path",\n"searches": [{\n"query": [{\n"type": "BooleanQuery",\n"description": "message:get message:search",\n"time_in_nanos": $body.$_path,/]
-// TESTRESPONSE[s/}$/},\n"children": $body.$_path}],\n"rewrite_time": $body.$_path, "collector": $body.$_path}], "aggregations": []}]}}/]
+// TESTRESPONSE[s/}$/},\n"children": $body.$_path}],\n"rewrite_time": $body.$_path, "collector": $body.$_path}], "aggregations": [], "fetch": $body.$_path}]}}/]
 // TESTRESPONSE[s/(?<=[" ])\d+(\.\d+)?/$body.$_path/]
 
 Timings are listed in wall-clock nanoseconds and are not normalized at all. All 
@@ -448,7 +479,7 @@ Looking at the previous example:
 ]
 --------------------------------------------------
 // TESTRESPONSE[s/^/{\n"took": $body.took,\n"timed_out": $body.timed_out,\n"_shards": $body._shards,\n"hits": $body.hits,\n"profile": {\n"shards": [ {\n"id": "$body.$_path",\n"searches": [{\n"query": $body.$_path,\n"rewrite_time": $body.$_path,/]
-// TESTRESPONSE[s/]$/]}], "aggregations": []}]}}/]
+// TESTRESPONSE[s/]$/]}], "aggregations": [], "fetch": $body.$_path}]}}/]
 // TESTRESPONSE[s/(?<=[" ])\d+(\.\d+)?/$body.$_path/]
 
 
@@ -569,7 +600,7 @@ GET /my-index-000001/_search
 }
 --------------------------------------------------
 // TEST[setup:my_index]
-// TEST[s/_search/_search\?filter_path=profile.shards.id,profile.shards.searches,profile.shards.aggregations/]
+// TEST[s/_search/_search\?filter_path=profile.shards.id,profile.shards.searches,profile.shards.aggregations,profile.shards.fetch/]
 
 
 This example has:
@@ -673,13 +704,15 @@ The API returns the following result:
             ]
           }
         ],
-        "aggregations": [...] <1>
+        "aggregations": [...], <1>
+        "fetch": {...}
       }
     ]
   }
 }
 --------------------------------------------------
 // TESTRESPONSE[s/"aggregations": \[\.\.\.\]/"aggregations": $body.$_path/]
+// TESTRESPONSE[s/"fetch": \{\.\.\.\}/"fetch": $body.$_path/]
 // TESTRESPONSE[s/\.\.\.//]
 // TESTRESPONSE[s/(?<=[" ])\d+(\.\d+)?/$body.$_path/]
 // TESTRESPONSE[s/"id": "\[P6-vulHtQRWuD4YnubWb7A\]\[my-index-000001\]\[0\]"/"id": $body.profile.shards.0.id/]

diff --git a/...rcolator/src/main/java/org/elasticsearch/percolator/PercolatorHighlightSubFetchPhase.java b/...rcolator/src/main/java/org/elasticsearch/percolator/PercolatorHighlightSubFetchPhase.java
@@ -40,6 +40,16 @@ final class PercolatorHighlightSubFetchPhase implements FetchSubPhase {
         this.highlightPhase = new HighlightPhase(highlighters);
     }
 
+    @Override
+    public String name() {
+        return "percolator_highlight";
+    }
+
+    @Override
+    public String description() {
+        return "annotates text matching percolator queries";
+    }
+
     @Override
     public FetchSubPhaseProcessor getProcessor(FetchContext fetchContext) {
         if (fetchContext.highlight() == null) {

diff --git a/...olator/src/main/java/org/elasticsearch/percolator/PercolatorMatchedSlotSubFetchPhase.java b/...olator/src/main/java/org/elasticsearch/percolator/PercolatorMatchedSlotSubFetchPhase.java
@@ -44,6 +44,16 @@ final class PercolatorMatchedSlotSubFetchPhase implements FetchSubPhase {
 
     static final String FIELD_NAME_PREFIX = "_percolator_document_slot";
 
+    @Override
+    public String name() {
+        return "percolator_matched";
+    }
+
+    @Override
+    public String description() {
+        return "indicates which documents match a percolator query";
+    }
+
     @Override
     public FetchSubPhaseProcessor getProcessor(FetchContext fetchContext) throws IOException {
 

diff --git a/rest-api-spec/src/yamlRestTest/resources/rest-api-spec/test/search/330_fetch_fields.yml b/rest-api-spec/src/yamlRestTest/resources/rest-api-spec/test/search/330_fetch_fields.yml
@@ -892,3 +892,53 @@ Test token_count inside nested field doesn't fail:
            body:
               _source: false
               fields: [ "*" ]
+
+
+---
+profile:
+  - do:
+      indices.create:
+        index:  test
+        body:
+          mappings:
+            properties:
+              keyword:
+                type: keyword
+              integer_range:
+                type: integer_range
+
+  - do:
+      index:
+        index:   test
+        id:      1
+        refresh: true
+        body:
+          keyword: [ "a", "b" ]
+          integer_range:
+            gte: 0
+            lte: 42
+
+  - do:
+      search:
+        index: test
+        body:
+          _source: false
+          profile: true
+          fields: [keyword, integer_range]
+
+  - is_true: hits.hits.0._id
+  - match: { hits.hits.0.fields.keyword.0: a }
+  - match: { hits.hits.0.fields.keyword.1: b }
+  - match: { hits.hits.0.fields.integer_range.0.gte: 0 }
+  - match: { hits.hits.0.fields.integer_range.0.lte: 42 }
+  - gt: { profile.shards.0.fetch.time_in_nanos: 0 }
+  - gt: { profile.shards.0.fetch.breakdown.next_reader_count: 0 }
+  - gt: { profile.shards.0.fetch.breakdown.next_reader: 0 }
+  - gt: { profile.shards.0.fetch.breakdown.load_stored_fields_count: 0 }
+  - gt: { profile.shards.0.fetch.breakdown.load_stored_fields: 0 }
+  - match: { profile.shards.0.fetch.debug.stored_fields: [_id, _routing, _source] }
+  - match: { profile.shards.0.fetch.children.0.type: fields }
+  - gt: { profile.shards.0.fetch.children.0.breakdown.next_reader_count: 0 }
+  - gt: { profile.shards.0.fetch.children.0.breakdown.next_reader: 0 }
+  - gt: { profile.shards.0.fetch.children.0.breakdown.next_reader_count: 0 }
+  - gt: { profile.shards.0.fetch.children.0.breakdown.next_reader: 0 }
diff --git a/server/src/internalClusterTest/java/org/elasticsearch/action/search/TransportSearchIT.java b/server/src/internalClusterTest/java/org/elasticsearch/action/search/TransportSearchIT.java
@@ -24,10 +24,10 @@
 import org.elasticsearch.common.io.stream.StreamInput;
 import org.elasticsearch.common.io.stream.StreamOutput;
 import org.elasticsearch.common.settings.Settings;
-import org.elasticsearch.core.TimeValue;
 import org.elasticsearch.common.util.concurrent.AtomicArray;
 import org.elasticsearch.common.xcontent.ObjectParser;
 import org.elasticsearch.common.xcontent.XContentBuilder;
+import org.elasticsearch.core.TimeValue;
 import org.elasticsearch.index.IndexSettings;
 import org.elasticsearch.index.query.RangeQueryBuilder;
 import org.elasticsearch.index.shard.IndexShard;
@@ -53,6 +53,7 @@
 import org.elasticsearch.search.aggregations.support.AggregationContext;
 import org.elasticsearch.search.aggregations.support.ValueType;
 import org.elasticsearch.search.builder.SearchSourceBuilder;
+import org.elasticsearch.search.fetch.FetchContext;
 import org.elasticsearch.search.fetch.FetchSubPhase;
 import org.elasticsearch.search.fetch.FetchSubPhaseProcessor;
 import org.elasticsearch.tasks.TaskId;
@@ -81,19 +82,30 @@ public List<AggregationSpec> getAggregations() {
 
         @Override
         public List<FetchSubPhase> getFetchSubPhases(FetchPhaseConstructionContext context) {
-            /**
-             * Set up a fetch sub phase that throws an exception on indices whose name that start with "boom".
-             */
-            return Collections.singletonList(fetchContext -> new FetchSubPhaseProcessor() {
+            return Collections.singletonList(new FetchSubPhase() {
                 @Override
-                public void setNextReader(LeafReaderContext readerContext) {
+                public String name() {
+                    return "boom";
                 }
 
                 @Override
-                public void process(FetchSubPhase.HitContext hitContext) {
-                    if (fetchContext.getIndexName().startsWith("boom")) {
-                        throw new RuntimeException("boom");
-                    }
+                public String description() {
+                    return "throws an exception on indices whose name start with 'boom'";
+                }
+
+                @Override
+                public FetchSubPhaseProcessor getProcessor(FetchContext fetchContext) throws IOException {
+                    return new FetchSubPhaseProcessor() {
+                        @Override
+                        public void setNextReader(LeafReaderContext readerContext) {}
+
+                        @Override
+                        public void process(FetchSubPhase.HitContext hitContext) {
+                            if (fetchContext.getIndexName().startsWith("boom")) {
+                                throw new RuntimeException("boom");
+                            }
+                        }
+                    };
                 }
             });
         }

diff --git a/...er/src/internalClusterTest/java/org/elasticsearch/search/fetch/FetchSubPhasePluginIT.java b/...er/src/internalClusterTest/java/org/elasticsearch/search/fetch/FetchSubPhasePluginIT.java
@@ -98,6 +98,16 @@ public List<SearchExtSpec<?>> getSearchExts() {
     private static final class TermVectorsFetchSubPhase implements FetchSubPhase {
         private static final String NAME = "term_vectors_fetch";
 
+        @Override
+        public String name() {
+            return NAME;
+        }
+
+        @Override
+        public String description() {
+            return "test";
+        }
+
         @Override
         public FetchSubPhaseProcessor getProcessor(FetchContext searchContext) {
             return new FetchSubPhaseProcessor() {