Merge pull request #12151 from vespa-engine/balder/add-option-to-trace-first-1k-requests-after-startup

If debugging of SearchHandler is turned on, the 1k first request will…

7 files changed, 33 insertions, 10 deletions

diff --git a/container-core/src/main/java/com/yahoo/container/jdisc/ThreadedHttpRequestHandler.java b/container-core/src/main/java/com/yahoo/container/jdisc/ThreadedHttpRequestHandler.java
index dddde1205ca..a9ea737c96c 100644
--- a/container-core/src/main/java/com/yahoo/container/jdisc/ThreadedHttpRequestHandler.java
+++ b/container-core/src/main/java/com/yahoo/container/jdisc/ThreadedHttpRequestHandler.java
@@ -93,7 +93,7 @@ public abstract class ThreadedHttpRequestHandler extends ThreadedRequestHandler
 
     /** Render and return whether the channel was closed */
     private void render(HttpRequest request, HttpResponse httpResponse,
-                        LazyContentChannel channel, long startTime) throws IOException {
+                        LazyContentChannel channel, long startTime) {
         LoggingCompletionHandler logOnCompletion = null;
         ContentChannelOutputStream output = null;
         try {
@@ -168,7 +168,7 @@ public abstract class ThreadedHttpRequestHandler extends ThreadedRequestHandler
         @Override
         public void close(CompletionHandler completionHandler) {
             if ( closed ) return;
-            try { httpRequest.getData().close(); } catch (IOException e) {};
+            try { httpRequest.getData().close(); } catch (IOException e) {}
             if (channel == null)
                 channel = handleResponse();
             try {
diff --git a/container-core/src/main/resources/configdefinitions/container-http.def b/container-core/src/main/resources/configdefinitions/container-http.def
index ccf559b862a..23edd402893 100644
--- a/container-core/src/main/resources/configdefinitions/container-http.def
+++ b/container-core/src/main/resources/configdefinitions/container-http.def
@@ -3,3 +3,6 @@ namespace=container.core
 
 ## If non-empty, handlers should emit a header containing this string as key and the local host name as value
 hostResponseHeaderKey string default=""
+
+## For debugging, number of requests to add trace and timing information too if debugging is enabled.
+numQueriesToTraceOnDebugAfterConstruction int default=1000
diff --git a/container-search/src/main/java/com/yahoo/search/handler/HttpSearchResponse.java b/container-search/src/main/java/com/yahoo/search/handler/HttpSearchResponse.java
index 3602d21f7d8..23eb8387427 100644
--- a/container-search/src/main/java/com/yahoo/search/handler/HttpSearchResponse.java
+++ b/container-search/src/main/java/com/yahoo/search/handler/HttpSearchResponse.java
@@ -69,14 +69,14 @@ public class HttpSearchResponse extends ExtendedResponse {
         }
     }
 
-    public ListenableFuture<Boolean> waitableRender(OutputStream stream) throws IOException {
+    public ListenableFuture<Boolean> waitableRender(OutputStream stream) {
         return waitableRender(result, query, rendererCopy, stream);
     }
 
     public static ListenableFuture<Boolean> waitableRender(Result result,
                                                            Query query,
                                                            Renderer<Result> renderer,
-                                                           OutputStream stream) throws IOException {
+                                                           OutputStream stream) {
         SearchResponse.trimHits(result);
         SearchResponse.removeEmptySummaryFeatureFields(result);
         return renderer.render(stream, result, query.getModel().getExecution(), query);
diff --git a/container-search/src/main/java/com/yahoo/search/handler/SearchHandler.java b/container-search/src/main/java/com/yahoo/search/handler/SearchHandler.java
index 316b2376060..0f0df3aa93e 100644
--- a/container-search/src/main/java/com/yahoo/search/handler/SearchHandler.java
+++ b/container-search/src/main/java/com/yahoo/search/handler/SearchHandler.java
@@ -58,6 +58,7 @@ import java.util.Optional;
 import java.util.concurrent.Executor;
 import java.util.concurrent.ThreadPoolExecutor;
 import java.util.concurrent.atomic.AtomicInteger;
+import java.util.concurrent.atomic.AtomicLong;
 import java.util.logging.Level;
 import java.util.logging.Logger;
 
@@ -98,6 +99,8 @@ public class SearchHandler extends LoggingRequestHandler {
 
     private final ExecutionFactory executionFactory;
 
+    private final AtomicLong numRequestsLeftToTrace;
+
     private final class MeanConnections implements Callback {
 
         @Override
@@ -125,6 +128,7 @@ public class SearchHandler extends LoggingRequestHandler {
              accessLog,
              QueryProfileConfigurer.createFromConfig(queryProfileConfig).compile(),
              executionFactory,
+             containerHttpConfig.numQueriesToTraceOnDebugAfterConstruction(),
              containerHttpConfig.hostResponseHeaderKey().equals("") ?
              Optional.empty() : Optional.of( containerHttpConfig.hostResponseHeaderKey()));
     }
@@ -136,6 +140,17 @@ public class SearchHandler extends LoggingRequestHandler {
                          CompiledQueryProfileRegistry queryProfileRegistry,
                          ExecutionFactory executionFactory,
                          Optional<String> hostResponseHeaderKey) {
+        this(statistics, metric, executor, accessLog, queryProfileRegistry, executionFactory, 0, hostResponseHeaderKey);
+    }
+
+    private SearchHandler(Statistics statistics,
+                         Metric metric,
+                         Executor executor,
+                         AccessLog accessLog,
+                         CompiledQueryProfileRegistry queryProfileRegistry,
+                         ExecutionFactory executionFactory,
+                         long numQueriesToTraceOnDebugAfterStartup,
+                         Optional<String> hostResponseHeaderKey) {
         super(executor, accessLog, metric, true);
         log.log(LogLevel.DEBUG, "SearchHandler.init " + System.identityHashCode(this));
         this.queryProfileRegistry = queryProfileRegistry;
@@ -150,6 +165,7 @@ public class SearchHandler extends LoggingRequestHandler {
                                                             .setCallback(new MeanConnections()));
 
         this.hostResponseHeaderKey = hostResponseHeaderKey;
+        this.numRequestsLeftToTrace = new AtomicLong(numQueriesToTraceOnDebugAfterStartup);
     }
 
     /** @deprecated use the other constructor */
@@ -215,7 +231,6 @@ public class SearchHandler extends LoggingRequestHandler {
 
     }
 
-    @SuppressWarnings("unchecked")
     private HttpResponse errorResponse(HttpRequest request, ErrorMessage errorMessage) {
         Query query = new Query();
         Result result = new Result(query, errorMessage);
@@ -330,7 +345,13 @@ public class SearchHandler extends LoggingRequestHandler {
 
         Execution execution = executionFactory.newExecution(searchChain);
         query.getModel().setExecution(execution);
-        execution.trace().setForceTimestamps(query.properties().getBoolean(FORCE_TIMESTAMPS, false));
+        if (log.isLoggable(Level.FINE) && (numRequestsLeftToTrace.getAndDecrement() > 0)) {
+            query.setTraceLevel(Math.max(1, query.getTraceLevel()));
+            execution.trace().setForceTimestamps(true);
+
+        } else {
+            execution.trace().setForceTimestamps(query.properties().getBoolean(FORCE_TIMESTAMPS, false));
+        }
         if (query.properties().getBoolean(DETAILED_TIMING_LOGGING, false)) {
             // check and set (instead of set directly) to avoid overwriting stuff from prepareForBreakdownAnalysis()
             execution.context().setDetailedDiagnostics(true);
diff --git a/container-search/src/main/java/com/yahoo/search/searchchain/Execution.java b/container-search/src/main/java/com/yahoo/search/searchchain/Execution.java
index 5cc34ff5b28..84fe88d0292 100644
--- a/container-search/src/main/java/com/yahoo/search/searchchain/Execution.java
+++ b/container-search/src/main/java/com/yahoo/search/searchchain/Execution.java
@@ -3,7 +3,6 @@ package com.yahoo.search.searchchain;
 
 import com.yahoo.component.chain.Chain;
 import com.yahoo.language.Linguistics;
-import com.yahoo.log.LogLevel;
 import com.yahoo.prelude.IndexFacts;
 import com.yahoo.prelude.Ping;
 import com.yahoo.prelude.Pong;
@@ -11,7 +10,6 @@ import com.yahoo.prelude.query.parser.SpecialTokenRegistry;
 import com.yahoo.processing.Processor;
 import com.yahoo.processing.Request;
 import com.yahoo.processing.Response;
-import com.yahoo.protect.Validator;
 import com.yahoo.search.Query;
 import com.yahoo.search.Result;
 import com.yahoo.search.Searcher;
diff --git a/processing/src/main/java/com/yahoo/processing/execution/Execution.java b/processing/src/main/java/com/yahoo/processing/execution/Execution.java
index ee1e9eb39e4..aeeae58543e 100644
--- a/processing/src/main/java/com/yahoo/processing/execution/Execution.java
+++ b/processing/src/main/java/com/yahoo/processing/execution/Execution.java
@@ -206,7 +206,7 @@ public class Execution {
          * Creates an empty environment. Only useful for some limited testing
          */
         public static <C extends Processor> Environment<C> createEmpty() {
-            return new Environment<C>(new ChainRegistry<C>());
+            return new Environment<>(new ChainRegistry<>());
         }
 
         /**
@@ -254,7 +254,7 @@ public class Execution {
         /**
          * If true, do timing logic, even though trace level is low.
          */
-        private boolean forceTimestamps = false;
+        private boolean forceTimestamps;
 
         /**
          * Creates an empty root trace with a given level of tracing
diff --git a/searchlib/src/tests/fef/fef_test.cpp b/searchlib/src/tests/fef/fef_test.cpp
index 896a917d6e3..4d1163de6ee 100644
--- a/searchlib/src/tests/fef/fef_test.cpp
+++ b/searchlib/src/tests/fef/fef_test.cpp
@@ -94,6 +94,7 @@ TEST("verify size of essential fef classes") {
     EXPECT_EQUAL(24u,sizeof(TermFieldMatchDataPosition));
     EXPECT_EQUAL(24u,sizeof(TermFieldMatchData::Features));
     EXPECT_EQUAL(40u,sizeof(TermFieldMatchData));
+    EXPECT_EQUAL(48u, sizeof(search::fef::FeatureExecutor));
 }
 
 TEST_MAIN() { TEST_RUN_ALL(); }