Include queue time in search handler for query metrics in StatisticsSearcher

3 files changed, 32 insertions, 4 deletions

diff --git a/container-core/abi-spec.json b/container-core/abi-spec.json
index 5e4033c22a7..5f9185ebef6 100644
--- a/container-core/abi-spec.json
+++ b/container-core/abi-spec.json
@@ -1636,6 +1636,7 @@
       "public boolean isChunked()",
       "public boolean hasChunkedResponse()",
       "public boolean isKeepAlive()",
+      "public long relativeCreatedAtNanoTime()",
       "public java.security.Principal getUserPrincipal()",
       "public void setUserPrincipal(java.security.Principal)",
       "public static com.yahoo.jdisc.http.HttpRequest newServerRequest(com.yahoo.jdisc.service.CurrentContainer, java.net.URI)",
diff --git a/container-core/src/main/java/com/yahoo/jdisc/http/HttpRequest.java b/container-core/src/main/java/com/yahoo/jdisc/http/HttpRequest.java
index ea01d215ca5..0b5e9ddde58 100644
--- a/container-core/src/main/java/com/yahoo/jdisc/http/HttpRequest.java
+++ b/container-core/src/main/java/com/yahoo/jdisc/http/HttpRequest.java
@@ -71,6 +71,7 @@ public class HttpRequest extends Request implements ServletOrJdiscHttpRequest {
         }
     }
 
+    private final long jvmRelativeCreatedAt = System.nanoTime();
     private final HeaderFields trailers = new HeaderFields();
     private final Map<String, List<String>> parameters = new HashMap<>();
     private Principal principal;
@@ -297,6 +298,11 @@ public class HttpRequest extends Request implements ServletOrJdiscHttpRequest {
         return version == Version.HTTP_1_1;
     }
 
+    /**
+     * @return the relative created timestamp (using {@link System#nanoTime()}
+     */
+    public long relativeCreatedAtNanoTime() { return jvmRelativeCreatedAt; }
+
     public Principal getUserPrincipal() {
         return principal;
     }
diff --git a/container-search/src/main/java/com/yahoo/prelude/statistics/StatisticsSearcher.java b/container-search/src/main/java/com/yahoo/prelude/statistics/StatisticsSearcher.java
index 941015b2fae..24b631f1773 100644
--- a/container-search/src/main/java/com/yahoo/prelude/statistics/StatisticsSearcher.java
+++ b/container-search/src/main/java/com/yahoo/prelude/statistics/StatisticsSearcher.java
@@ -5,9 +5,9 @@ import com.yahoo.component.chain.dependencies.Before;
 import com.yahoo.concurrent.CopyOnWriteHashMap;
 import com.yahoo.container.protect.Error;
 import com.yahoo.jdisc.Metric;
-import java.util.logging.Level;
-import com.yahoo.metrics.simple.MetricSettings;
+import com.yahoo.jdisc.http.HttpRequest;
 import com.yahoo.metrics.simple.MetricReceiver;
+import com.yahoo.metrics.simple.MetricSettings;
 import com.yahoo.processing.request.CompoundName;
 import com.yahoo.search.Query;
 import com.yahoo.search.Result;
@@ -29,7 +29,18 @@ import java.util.PriorityQueue;
 import java.util.Queue;
 import java.util.logging.Level;
 
-import static com.yahoo.container.protect.Error.*;
+import static com.yahoo.container.protect.Error.BACKEND_COMMUNICATION_ERROR;
+import static com.yahoo.container.protect.Error.EMPTY_DOCUMENTS;
+import static com.yahoo.container.protect.Error.ERROR_IN_PLUGIN;
+import static com.yahoo.container.protect.Error.ILLEGAL_QUERY;
+import static com.yahoo.container.protect.Error.INTERNAL_SERVER_ERROR;
+import static com.yahoo.container.protect.Error.INVALID_QUERY_PARAMETER;
+import static com.yahoo.container.protect.Error.INVALID_QUERY_TRANSFORMATION;
+import static com.yahoo.container.protect.Error.NO_BACKENDS_IN_SERVICE;
+import static com.yahoo.container.protect.Error.RESULT_HAS_ERRORS;
+import static com.yahoo.container.protect.Error.SERVER_IS_MISCONFIGURED;
+import static com.yahoo.container.protect.Error.TIMEOUT;
+import static com.yahoo.container.protect.Error.UNSPECIFIED;
 
 
 /**
@@ -236,7 +247,7 @@ public class StatisticsSearcher extends Searcher {
 
         incrQueryCount(metricContext);
         logQuery(query);
-        long start_ns = System.nanoTime(); // Start time, in nanoseconds.
+        long start_ns = getStartNanoTime(query);
         qps(metricContext);
         Result result;
         //handle exceptions thrown below in searchers
@@ -428,5 +439,15 @@ public class StatisticsSearcher extends Searcher {
         }
     }
 
+    /**
+     * Returns the relative start time from request was received by jdisc
+     */
+    private static long getStartNanoTime(Query query) {
+        return Optional.ofNullable(query.getHttpRequest())
+                .flatMap(httpRequest -> Optional.ofNullable(httpRequest.getJDiscRequest()))
+                .map(HttpRequest::relativeCreatedAtNanoTime)
+                .orElseGet(System::nanoTime);
+    }
+
 }