Add metric for render latency

3 files changed, 35 insertions, 5 deletions

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 949b42c7613..38dd806395e 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
@@ -9,6 +9,7 @@ import com.yahoo.container.jdisc.ExtendedResponse;
 import com.yahoo.container.logging.AccessLogEntry;
 import com.yahoo.container.logging.HitCounts;
 import com.yahoo.jdisc.HeaderFields;
+import com.yahoo.jdisc.Metric;
 import com.yahoo.jdisc.handler.CompletionHandler;
 import com.yahoo.jdisc.handler.ContentChannel;
 import com.yahoo.processing.execution.Execution.Trace.LogValue;
@@ -21,6 +22,7 @@ import com.yahoo.yolean.trace.TraceNode;
 
 import java.io.IOException;
 import java.io.OutputStream;
+import java.time.Duration;
 import java.util.Collections;
 import java.util.List;
 import java.util.Map;
@@ -35,20 +37,21 @@ public class HttpSearchResponse extends ExtendedResponse {
     private final Result result;
     private final Query query;
     private final Renderer<Result> rendererCopy;
+    private final Metric metric;
     private final Timing timing;
     private final HitCounts hitCounts;
     private final TraceNode trace;
 
     public HttpSearchResponse(int status, Result result, Query query, Renderer<Result> renderer) {
-        this(status, result, query, renderer, null);
+        this(status, result, query, renderer, null, null);
     }
 
-    HttpSearchResponse(int status, Result result, Query query, Renderer<Result> renderer, TraceNode trace) {
+    HttpSearchResponse(int status, Result result, Query query, Renderer<Result> renderer, TraceNode trace, Metric metric) {
         super(status);
         this.query = query;
         this.result = result;
         this.rendererCopy = renderer;
-
+        this.metric = metric;
         this.timing = SearchResponse.createTiming(query, result);
         this.hitCounts = SearchResponse.createHitCounts(query, result);
         this.trace = trace;
@@ -98,7 +101,10 @@ public class HttpSearchResponse extends ExtendedResponse {
         }
         try {
             try {
-                waitableRender(output);
+                ListenableFuture<Boolean> promise = waitableRender(output);
+                if (metric != null) {
+                    promise.addListener(new RendererLatencyReporter(), Runnable::run);
+                }
             } finally {
                 if (!(rendererCopy instanceof AsynchronousSectionedRenderer)) {
                     output.flush();
@@ -178,4 +184,18 @@ public class HttpSearchResponse extends ExtendedResponse {
                 : context::logValueIterator;
     }
 
+    private class RendererLatencyReporter implements Runnable {
+
+        final long nanoStart = System.nanoTime();
+
+        @Override
+        public void run() {
+            long latencyMillis = Duration.ofNanos(System.nanoTime() - nanoStart).toMillis();
+            Metric.Context ctx = metric.createContext(Map.of(
+                    SearchHandler.RENDERER_DIMENSION, rendererCopy.getClassName(),
+                    SearchHandler.MIME_DIMENSION, rendererCopy.getMimeType()));
+            metric.set(SearchHandler.RENDER_LATENCY_METRIC, latencyMillis, ctx);
+        }
+    }
+
 }
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 a0c5bfbe0cf..f81aab4259d 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
@@ -87,6 +87,9 @@ public class SearchHandler extends LoggingRequestHandler {
 
     /** Event name for number of connections to the search subsystem */
     private static final String SEARCH_CONNECTIONS = "search_connections";
+    static final String RENDER_LATENCY_METRIC = "jdisc.search.render_latency";
+    static final String MIME_DIMENSION = "mime";
+    static final String RENDERER_DIMENSION = "renderer";
 
     private static final String JSON_CONTENT_TYPE = "application/json";
 
@@ -229,6 +232,8 @@ public class SearchHandler extends LoggingRequestHandler {
              new ExecutionFactory(chainsConfig, indexInfo, clusters, searchers, specialtokens, linguistics, renderers));
     }
 
+    Metric metric() { return metric; }
+
     private static int examineExecutor(Executor executor) {
         if (executor instanceof ThreadPoolExecutor) {
             return ((ThreadPoolExecutor) executor).getMaximumPoolSize();
@@ -330,7 +335,8 @@ public class SearchHandler extends LoggingRequestHandler {
         Renderer<Result> renderer = toRendererCopy(query.getPresentation().getRenderer());
         HttpSearchResponse response = new HttpSearchResponse(getHttpResponseStatus(request, result),
                                                              result, query, renderer,
-                                                             extractTraceNode(query));
+                                                             extractTraceNode(query),
+                                                             metric);
         response.setRequestType(Request.RequestType.READ);
         hostResponseHeaderKey.ifPresent(key -> response.headers().add(key, selfHostname));
 
diff --git a/container-search/src/test/java/com/yahoo/search/handler/SearchHandlerTest.java b/container-search/src/test/java/com/yahoo/search/handler/SearchHandlerTest.java
index 3fe3c824653..2b584c7b285 100644
--- a/container-search/src/test/java/com/yahoo/search/handler/SearchHandlerTest.java
+++ b/container-search/src/test/java/com/yahoo/search/handler/SearchHandlerTest.java
@@ -10,6 +10,7 @@ import com.yahoo.container.jdisc.ThreadedHttpRequestHandler;
 import com.yahoo.io.IOUtils;
 import com.yahoo.jdisc.Request;
 import com.yahoo.jdisc.handler.RequestHandler;
+import com.yahoo.jdisc.test.MockMetric;
 import com.yahoo.net.HostName;
 import com.yahoo.search.Query;
 import com.yahoo.search.Result;
@@ -57,6 +58,7 @@ public class SearchHandlerTest {
 
     private RequestHandlerTestDriver driver = null;
     private HandlersConfigurerTestWrapper configurer = null;
+    private MockMetric metric;
     private SearchHandler searchHandler;
 
     @Before
@@ -70,6 +72,7 @@ public class SearchHandlerTest {
 
         configurer = new HandlersConfigurerTestWrapper(new Container(), configId);
         searchHandler = (SearchHandler)configurer.getRequestHandlerRegistry().getComponent(SearchHandler.class.getName());
+        metric = (MockMetric) searchHandler.metric();
         driver = new RequestHandlerTestDriver(searchHandler);
     }
 
@@ -287,6 +290,7 @@ public class SearchHandlerTest {
         assertEquals(expected, response.readAll());
         assertEquals(200, response.getStatus());
         assertEquals(selfHostname, response.getResponse().headers().get(myHostnameHeader).get(0));
+        assertTrue(metric.metrics().containsKey(SearchHandler.RENDER_LATENCY_METRIC));
     }
 
     @Test