Fix calculation of time of term vectors request

This commit addresses an issue in the calculation of the time to execute
a term vectors request. The underlying issue was due to measuring the
took time by passing the starting wall clock time along with the request
and calculating the total time using the ending wall clock time on the
responding node. The fix is to use a relative time source on a single
node.


Relates #17817

core/src/main/java/org/elasticsearch/action/termvectors/TermVectorsRequest.java

@@ -133,8 +133,6 @@ public class TermVectorsRequest extends SingleShardRequest<TermVectorsRequest> i
     private EnumSet<Flag> flagsEnum = EnumSet.of(Flag.Positions, Flag.Offsets, Flag.Payloads,
             Flag.FieldStatistics);
 
-    long startTime;
-
     public TermVectorsRequest() {
     }
 
@@ -174,7 +172,6 @@ public class TermVectorsRequest extends SingleShardRequest<TermVectorsRequest> i
         this.realtime = other.realtime();
         this.version = other.version();
         this.versionType = VersionType.fromValue(other.versionType().getValue());
-        this.startTime = other.startTime();
         this.filterSettings = other.filterSettings();
     }
 
@@ -460,10 +457,6 @@ public class TermVectorsRequest extends SingleShardRequest<TermVectorsRequest> i
         }
     }
 
-    public long startTime() {
-        return this.startTime;
-    }
-
     @Override
     public ActionRequestValidationException validate() {
         ActionRequestValidationException validationException = super.validateNonNullIndex();

core/src/main/java/org/elasticsearch/action/termvectors/TermVectorsResponse.java

@@ -325,8 +325,8 @@ public class TermVectorsResponse extends ActionResponse implements ToXContent {
         }
     }
 
-    public void updateTookInMillis(long startTime) {
-        this.tookInMillis = Math.max(1, System.currentTimeMillis() - startTime);
+    public void setTookInMillis(long tookInMillis) {
+        this.tookInMillis = tookInMillis;
     }
 
     public TimeValue getTook() {

core/src/main/java/org/elasticsearch/action/termvectors/TransportMultiTermVectorsAction.java

@@ -64,7 +64,6 @@ public class TransportMultiTermVectorsAction extends HandledTransportAction<Mult
         Map<ShardId, MultiTermVectorsShardRequest> shardRequests = new HashMap<>();
         for (int i = 0; i < request.requests.size(); i++) {
             TermVectorsRequest termVectorsRequest = request.requests.get(i);
-            termVectorsRequest.startTime = System.currentTimeMillis();
             termVectorsRequest.routing(clusterState.metaData().resolveIndexRouting(termVectorsRequest.parent(), termVectorsRequest.routing(), termVectorsRequest.index()));
             if (!clusterState.metaData().hasConcreteIndex(termVectorsRequest.index())) {
                 responses.set(i, new MultiTermVectorsItemResponse(null, new MultiTermVectorsResponse.Failure(termVectorsRequest.index(),

core/src/main/java/org/elasticsearch/action/termvectors/TransportShardMultiTermsVectorAction.java

@@ -82,7 +82,6 @@ public class TransportShardMultiTermsVectorAction extends TransportSingleShardAc
             TermVectorsRequest termVectorsRequest = request.requests.get(i);
             try {
                 TermVectorsResponse termVectorsResponse = TermVectorsService.getTermVectors(indexShard, termVectorsRequest);
-                termVectorsResponse.updateTookInMillis(termVectorsRequest.startTime());
                 response.add(request.locations.get(i), termVectorsResponse);
             } catch (Throwable t) {
                 if (TransportActions.isShardNotAvailableException(t)) {

core/src/main/java/org/elasticsearch/action/termvectors/TransportTermVectorsAction.java

@@ -44,12 +44,6 @@ public class TransportTermVectorsAction extends TransportSingleShardAction<TermV
 
     private final IndicesService indicesService;
 
-    @Override
-    protected void doExecute(TermVectorsRequest request, ActionListener<TermVectorsResponse> listener) {
-        request.startTime = System.currentTimeMillis();
-        super.doExecute(request, listener);
-    }
-
     @Inject
     public TransportTermVectorsAction(Settings settings, ClusterService clusterService, TransportService transportService,
                                       IndicesService indicesService, ThreadPool threadPool, ActionFilters actionFilters,
@@ -85,9 +79,7 @@ public class TransportTermVectorsAction extends TransportSingleShardAction<TermV
     protected TermVectorsResponse shardOperation(TermVectorsRequest request, ShardId shardId) {
         IndexService indexService = indicesService.indexServiceSafe(shardId.getIndex());
         IndexShard indexShard = indexService.getShard(shardId.id());
-        TermVectorsResponse response = TermVectorsService.getTermVectors(indexShard, request);
-        response.updateTookInMillis(request.startTime());
-        return response;
+        return TermVectorsService.getTermVectors(indexShard, request);
     }
 
     @Override

core/src/main/java/org/elasticsearch/index/termvectors/TermVectorsService.java

@@ -60,6 +60,8 @@ import java.util.Iterator;
 import java.util.Map;
 import java.util.Set;
 import java.util.TreeMap;
+import java.util.concurrent.TimeUnit;
+import java.util.function.LongSupplier;
 
 import static org.elasticsearch.index.mapper.SourceToParse.source;
 
@@ -72,6 +74,11 @@ public class TermVectorsService  {
     private TermVectorsService() {}
 
     public static TermVectorsResponse getTermVectors(IndexShard indexShard, TermVectorsRequest request) {
+        return getTermVectors(indexShard, request, System::nanoTime);
+    }
+
+    static TermVectorsResponse getTermVectors(IndexShard indexShard, TermVectorsRequest request, LongSupplier nanoTimeSupplier) {
+        final long startTime = nanoTimeSupplier.getAsLong();
         final TermVectorsResponse termVectorsResponse = new TermVectorsResponse(indexShard.shardId().getIndex().getName(), request.type(), request.id());
         final Term uidTerm = new Term(UidFieldMapper.NAME, Uid.createUidAsBytes(request.type(), request.id()));
 
@@ -141,6 +148,7 @@ public class TermVectorsService  {
                 // write term vectors
                 termVectorsResponse.setFields(termVectorsByField, request.selectedFields(), request.getFlags(), topLevelFields, dfs, termVectorsFilter);
             }
+            termVectorsResponse.setTookInMillis(TimeUnit.NANOSECONDS.toMillis(nanoTimeSupplier.getAsLong() - startTime));
         } catch (Throwable ex) {
             throw new ElasticsearchException("failed to execute term vector request", ex);
         } finally {

core/src/test/java/org/elasticsearch/index/termvectors/TermVectorsServiceTests.java

@@ -0,0 +1,73 @@
+/*
+ * Licensed to Elasticsearch under one or more contributor
+ * license agreements. See the NOTICE file distributed with
+ * this work for additional information regarding copyright
+ * ownership. Elasticsearch licenses this file to you under
+ * the Apache License, Version 2.0 (the "License"); you may
+ * not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *    http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing,
+ * software distributed under the License is distributed on an
+ * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+ * KIND, either express or implied.  See the License for the
+ * specific language governing permissions and limitations
+ * under the License.
+ */
+
+package org.elasticsearch.index.termvectors;
+
+import org.elasticsearch.action.termvectors.TermVectorsRequest;
+import org.elasticsearch.action.termvectors.TermVectorsResponse;
+import org.elasticsearch.common.settings.Settings;
+import org.elasticsearch.common.xcontent.XContentBuilder;
+import org.elasticsearch.index.IndexService;
+import org.elasticsearch.index.shard.IndexShard;
+import org.elasticsearch.indices.IndicesService;
+import org.elasticsearch.test.ESSingleNodeTestCase;
+
+import java.util.List;
+import java.util.concurrent.TimeUnit;
+import java.util.stream.Stream;
+
+import static java.lang.Math.abs;
+import static java.util.stream.Collectors.toList;
+import static org.elasticsearch.common.xcontent.XContentFactory.jsonBuilder;
+import static org.hamcrest.Matchers.equalTo;
+import static org.hamcrest.Matchers.notNullValue;
+
+public class TermVectorsServiceTests extends ESSingleNodeTestCase {
+
+    public void testTook() throws Exception {
+        XContentBuilder mapping = jsonBuilder()
+            .startObject()
+                .startObject("type1")
+                    .startObject("properties")
+                        .startObject("field")
+                            .field("type", "text")
+                            .field("term_vector", "with_positions_offsets_payloads")
+                        .endObject()
+                    .endObject()
+                .endObject()
+            .endObject();
+        createIndex("test", Settings.EMPTY, "type1", mapping);
+        ensureGreen();
+
+        client().prepareIndex("test", "type1", "0").setSource("field", "foo bar").setRefresh(true).execute().get();
+
+        IndicesService indicesService = getInstanceFromNode(IndicesService.class);
+        IndexService test = indicesService.indexService(resolveIndex("test"));
+        IndexShard shard = test.getShardOrNull(0);
+        assertThat(shard, notNullValue());
+
+        List<Long> longs = Stream.of(abs(randomLong()), abs(randomLong())).sorted().collect(toList());
+
+        TermVectorsRequest request = new TermVectorsRequest("test", "type1", "0");
+        TermVectorsResponse response = TermVectorsService.getTermVectors(shard, request, longs.iterator()::next);
+
+        assertThat(response, notNullValue());
+        assertThat(response.getTookInMillis(), equalTo(TimeUnit.NANOSECONDS.toMillis(longs.get(1) - longs.get(0))));
+    }
+}