Tooktime

server/src/main/java/org/opensearch/search/query/QueryPhase.java

@@ -131,13 +131,15 @@ public void preProcess(SearchContext context) {
     }
 
     public void execute(SearchContext searchContext) throws QueryPhaseExecutionException {
+        long startTime = System.nanoTime();
         if (searchContext.hasOnlySuggest()) {
             suggestProcessor.process(searchContext);
             searchContext.queryResult()
                 .topDocs(
                     new TopDocsAndMaxScore(new TopDocs(new TotalHits(0, TotalHits.Relation.EQUAL_TO), Lucene.EMPTY_SCORE_DOCS), Float.NaN),
                     new DocValueFormat[0]
                 );
+            searchContext.queryResult().setTookTimeNanos(System.nanoTime() - startTime);
             return;
         }
 
@@ -165,6 +167,7 @@ public void execute(SearchContext searchContext) throws QueryPhaseExecutionExcep
             );
             searchContext.queryResult().profileResults(shardResults);
         }
+        searchContext.queryResult().setTookTimeNanos(System.nanoTime() - startTime);
     }
 
     // making public for testing
@@ -292,7 +295,6 @@ static boolean executeInternal(SearchContext searchContext, QueryPhaseSearcher q
                     queryResult.nodeQueueSize(rExecutor.getCurrentQueueSize());
                     queryResult.serviceTimeEWMA((long) rExecutor.getTaskExecutionEWMA());
                 }
-
                 return shouldRescore;
             } finally {
                 // Search phase has finished, no longer need to check for timeout

server/src/main/java/org/opensearch/search/query/QuerySearchResult.java

@@ -87,6 +87,7 @@ public final class QuerySearchResult extends SearchPhaseResult {
     private int nodeQueueSize = -1;
 
     private final boolean isNull;
+    private long tookTimeNanos;
 
     public QuerySearchResult() {
         this(false);
@@ -364,6 +365,7 @@ public void readFromWithId(ShardSearchContextId id, StreamInput in) throws IOExc
         nodeQueueSize = in.readInt();
         setShardSearchRequest(in.readOptionalWriteable(ShardSearchRequest::new));
         setRescoreDocIds(new RescoreDocIds(in));
+        tookTimeNanos = in.readVLong();
     }
 
     @Override
@@ -406,6 +408,7 @@ public void writeToNoId(StreamOutput out) throws IOException {
         out.writeInt(nodeQueueSize);
         out.writeOptionalWriteable(getShardSearchRequest());
         getRescoreDocIds().writeTo(out);
+        out.writeVLong(tookTimeNanos); // VLong as took time should always be positive
     }
 
     public TotalHits getTotalHits() {
@@ -415,4 +418,12 @@ public TotalHits getTotalHits() {
     public float getMaxScore() {
         return maxScore;
     }
+
+    public long getTookTimeNanos() {
+        return tookTimeNanos;
+    }
+
+    public void setTookTimeNanos(long tookTime) {
+        tookTimeNanos = tookTime;
+    }
 }

server/src/test/java/org/opensearch/search/SearchServiceTests.java

@@ -121,6 +121,7 @@
 import java.util.List;
 import java.util.Locale;
 import java.util.Map;
+import java.util.concurrent.CompletableFuture;
 import java.util.concurrent.CountDownLatch;
 import java.util.concurrent.ExecutionException;
 import java.util.concurrent.Semaphore;
@@ -823,6 +824,118 @@ public Scroll scroll() {
         }
     }
 
+    public void testQuerySearchResultTookTime() throws Exception {
+        // I wasn't able to introduce a delay in these tests as everything between creation and usage of the QuerySearchResult object
+        // happen in a single line - we would have to modify QueryPhase.execute() to take a delay parameter
+        // However this was tested manually
+        createIndex("index");
+        final SearchService service = getInstanceFromNode(SearchService.class);
+        final IndicesService indicesService = getInstanceFromNode(IndicesService.class);
+        final IndexService indexService = indicesService.indexServiceSafe(resolveIndex("index"));
+        final IndexShard indexShard = indexService.getShard(0);
+        SearchRequest searchRequest = new SearchRequest().allowPartialSearchResults(true);
+        searchRequest.source(new SearchSourceBuilder().query(new MatchAllQueryBuilder()));
+
+        ShardSearchRequest request = new ShardSearchRequest(
+            OriginalIndices.NONE,
+            searchRequest,
+            indexShard.shardId(),
+            2, // must have >1 shards for executeQueryPhase to return the QuerySearchResult
+            new AliasFilter(null, Strings.EMPTY_ARRAY),
+            1.0f,
+            -1,
+            null,
+            null
+        );
+
+        SearchShardTask task = new SearchShardTask(123L, "", "", "", null, Collections.emptyMap());
+        service.executeQueryPhase(request, randomBoolean(), task, new ActionListener<SearchPhaseResult>() {
+            @Override
+            public void onResponse(SearchPhaseResult searchPhaseResult) {
+                assertEquals(QuerySearchResult.class, searchPhaseResult.getClass()); // 2+ shards -> QuerySearchResult returned
+                QuerySearchResult qsr = (QuerySearchResult) searchPhaseResult;
+                assertTrue(qsr.getTookTimeNanos() > 0); // Above zero means it's been set at some point
+            }
+
+            @Override
+            public void onFailure(Exception e) {
+                throw new AssertionError(e);
+            }
+        });
+    }
+
+    public void testQuerySearchResultTookTimeCacheableRequest() throws Exception {
+        // Test 2 identical cacheable requests and assert both have the same tookTime
+        // Similarly, no delay could be added
+        createIndex("index");
+        final SearchService service = getInstanceFromNode(SearchService.class);
+        final IndicesService indicesService = getInstanceFromNode(IndicesService.class);
+        final IndexService indexService = indicesService.indexServiceSafe(resolveIndex("index"));
+        final IndexShard indexShard = indexService.getShard(0);
+        SearchRequest searchRequest = new SearchRequest().allowPartialSearchResults(true);
+        SearchSourceBuilder searchSourceBuilder = new SearchSourceBuilder();
+
+        searchRequest.source(searchSourceBuilder);
+        searchSourceBuilder.scriptField(
+            "field" + 0,
+            new Script(ScriptType.INLINE, MockScriptEngine.NAME, CustomScriptPlugin.DUMMY_SCRIPT, Collections.emptyMap())
+        );
+        searchSourceBuilder.size(0); // from testIgnoreScriptfieldIfSizeZero
+
+        String[] dummyRoutings = new String[] {};
+        OriginalIndices dummyOriginalIndices = new OriginalIndices(new String[] { "index'" }, IndicesOptions.LENIENT_EXPAND_OPEN);
+
+        ShardSearchRequest request = new ShardSearchRequest(
+            dummyOriginalIndices,
+            searchRequest,
+            indexShard.shardId(),
+            2, // must have >1 shards for executeQueryPhase to return the QuerySearchResult
+            new AliasFilter(null, Strings.EMPTY_ARRAY),
+            1.0f,
+            0L,
+            // if nowInMillis is negative, it fails when trying to write the shardSearchRequest to cache as it uses WriteVLong which only
+            // takes positive longs
+            null,
+            dummyRoutings // similar for routings
+        );
+
+        final CompletableFuture<Long> firstResult = new CompletableFuture<>();
+        final CompletableFuture<Long> secondResult = new CompletableFuture<>();
+        SearchShardTask task = new SearchShardTask(123L, "", "", "", null, Collections.emptyMap());
+        service.executeQueryPhase(request, randomBoolean(), task, new ActionListener<SearchPhaseResult>() {
+            @Override
+            public void onResponse(SearchPhaseResult searchPhaseResult) {
+                assertEquals(QuerySearchResult.class, searchPhaseResult.getClass()); // 2+ shards -> QuerySearchResult returned
+                QuerySearchResult qsr = (QuerySearchResult) searchPhaseResult;
+                firstResult.complete(qsr.getTookTimeNanos());
+            }
+
+            @Override
+            public void onFailure(Exception e) {
+                throw new AssertionError(e);
+            }
+        });
+
+        service.executeQueryPhase(request, randomBoolean(), task, new ActionListener<SearchPhaseResult>() {
+            @Override
+            public void onResponse(SearchPhaseResult searchPhaseResult) {
+                assertEquals(QuerySearchResult.class, searchPhaseResult.getClass()); // 2+ shards -> QuerySearchResult returned
+                QuerySearchResult qsr = (QuerySearchResult) searchPhaseResult;
+                secondResult.complete(qsr.getTookTimeNanos());
+            }
+
+            @Override
+            public void onFailure(Exception e) {
+                throw new AssertionError(e);
+            }
+        });
+
+        long firstResultVal = firstResult.get();
+        long secondResultVal = secondResult.get();
+        assertEquals(firstResultVal, secondResultVal);
+        assertTrue(firstResultVal > 0);
+    }
+
     public void testCanMatch() throws Exception {
         createIndex("index");
         final SearchService service = getInstanceFromNode(SearchService.class);
@@ -1010,6 +1123,7 @@ public void onFailure(Exception e) {
                 }
             }
         });
+
         latch.await();
     }
 

server/src/test/java/org/opensearch/search/query/QuerySearchResultTests.java

@@ -99,6 +99,7 @@ private static QuerySearchResult createTestInstance() throws Exception {
         if (randomBoolean()) {
             result.aggregations(InternalAggregationsTests.createTestInstance());
         }
+        assertEquals(0, result.getTookTimeNanos());
         return result;
     }
 
@@ -118,6 +119,7 @@ public void testSerialization() throws Exception {
             assertEquals(aggs.asList(), deserializedAggs.asList());
         }
         assertEquals(querySearchResult.terminatedEarly(), deserialized.terminatedEarly());
+        assertEquals(querySearchResult.getTookTimeNanos(), deserialized.getTookTimeNanos());
     }
 
     public void testNullResponse() throws Exception {