Merge pull request #26398 from vespa-engine/balder/only-create-log-if-needed

Balder/only create log if needed

1 files changed, 37 insertions, 39 deletions

diff --git a/container-core/src/main/java/com/yahoo/container/jdisc/LoggingRequestHandler.java b/container-core/src/main/java/com/yahoo/container/jdisc/LoggingRequestHandler.java
index d608977a7ff..bacceac9d76 100644
--- a/container-core/src/main/java/com/yahoo/container/jdisc/LoggingRequestHandler.java
+++ b/container-core/src/main/java/com/yahoo/container/jdisc/LoggingRequestHandler.java
@@ -3,7 +3,6 @@ package com.yahoo.container.jdisc;
 
 import com.yahoo.component.annotation.Inject;
 import com.yahoo.container.handler.Timing;
-import com.yahoo.container.logging.AccessLog;
 import com.yahoo.container.logging.AccessLogEntry;
 import com.yahoo.jdisc.Metric;
 import com.yahoo.jdisc.Response;
@@ -102,54 +101,54 @@ public abstract class LoggingRequestHandler extends ThreadedHttpRequestHandler {
 
     private void logTimes(long startTime, String sourceIP,
                           long renderStartTime, long commitStartTime, long endTime,
-                          String req, String normalizedQuery, Timing t) {
+                          String req, ExtendedResponse response) {
 
         // note: intentionally only taking time since request was received
         long totalTime = endTime - startTime;
 
-        long timeoutInterval = Long.MAX_VALUE;
-        long requestOverhead = 0;
-        long summaryStartTime = 0;
+        long timeoutInterval;
+        long requestOverhead;
+        long summaryStartTime;
+        Timing t = response.getTiming();
         if (t != null) {
             timeoutInterval = t.getTimeout();
             long queryStartTime = t.getQueryStartTime();
-            if (queryStartTime > 0) {
-                requestOverhead = queryStartTime - startTime;
-            }
+            requestOverhead = (queryStartTime > 0) ? queryStartTime - startTime : 0;
             summaryStartTime = t.getSummaryStartTime();
-        }
-
-        if (totalTime <= timeoutInterval) {
-            return;
-        }
-
-        StringBuilder b = new StringBuilder();
-        b.append(normalizedQuery);
-        b.append(" from ").append(sourceIP).append(". ");
-
-        if (requestOverhead > 0) {
-            b.append("Time from HTTP connection open to request reception ");
-            b.append(requestOverhead).append(" ms. ");
-        }
-        if (summaryStartTime != 0) {
-            b.append("Request time: ");
-            b.append(summaryStartTime - startTime).append(" ms. ");
-            b.append("Summary fetch time: ");
-            b.append(renderStartTime - summaryStartTime).append(" ms. ");
         } else {
-            long spentSearching = renderStartTime - startTime;
-            b.append("Processing time: ").append(spentSearching).append(" ms. ");
+            requestOverhead = 0;
+            summaryStartTime = 0;
+            timeoutInterval = Long.MAX_VALUE;
         }
 
-        b.append("Result rendering/transfer: ");
-        b.append(commitStartTime - renderStartTime).append(" ms. ");
-        b.append("End transaction: ");
-        b.append(endTime - commitStartTime).append(" ms. ");
-        b.append("Total: ").append(totalTime).append(" ms. ");
-        b.append("Timeout: ").append(timeoutInterval).append(" ms. ");
-        b.append("Request string: ").append(req);
+        if (totalTime <= timeoutInterval) return;
 
-        log.log(Level.WARNING, "Slow execution. " + b);
+        log.log(Level.FINE, () -> {
+            StringBuilder b = new StringBuilder();
+            b.append(response.getParsedQuery());
+            b.append(" from ").append(sourceIP).append(". ");
+            if (requestOverhead > 0) {
+                b.append("Time from HTTP connection open to request reception ");
+                b.append(requestOverhead).append(" ms. ");
+            }
+            if (summaryStartTime != 0) {
+                b.append("Request time: ");
+                b.append(summaryStartTime - startTime).append(" ms. ");
+                b.append("Summary fetch time: ");
+                b.append(renderStartTime - summaryStartTime).append(" ms. ");
+            } else {
+                long spentSearching = renderStartTime - startTime;
+                b.append("Processing time: ").append(spentSearching).append(" ms. ");
+            }
+            b.append("Result rendering/transfer: ");
+            b.append(commitStartTime - renderStartTime).append(" ms. ");
+            b.append("End transaction: ");
+            b.append(endTime - commitStartTime).append(" ms. ");
+            b.append("Total: ").append(totalTime).append(" ms. ");
+            b.append("Timeout: ").append(timeoutInterval).append(" ms. ");
+            b.append("Request string: ").append(req);
+            return b.toString();
+        });
     }
 
     private static class NullResponse extends ExtendedResponse {
@@ -224,8 +223,7 @@ public abstract class LoggingRequestHandler extends ThreadedHttpRequestHandler {
                      commitStartTime,
                      endTime,
                      getUri(jdiscRequest),
-                     extendedResponse.getParsedQuery(),
-                     extendedResponse.getTiming());
+                     extendedResponse);
 
             Optional<AccessLogEntry> jdiscRequestAccessLogEntry =
                     AccessLoggingRequestHandler.getAccessLogEntry(jdiscRequest);