Add latency recording utility handler (#9172)

* #8069 add latency recording handler

Signed-off-by: Ludovic Orban <[email protected]>

jetty-core/jetty-server/src/main/java/org/eclipse/jetty/server/handler/AbstractLatencyRecordingHandler.java

@@ -0,0 +1,88 @@
+//
+// ========================================================================
+// Copyright (c) 1995-2022 Mort Bay Consulting Pty Ltd and others.
+//
+// This program and the accompanying materials are made available under the
+// terms of the Eclipse Public License v. 2.0 which is available at
+// https://www.eclipse.org/legal/epl-2.0, or the Apache License, Version 2.0
+// which is available at https://www.apache.org/licenses/LICENSE-2.0.
+//
+// SPDX-License-Identifier: EPL-2.0 OR Apache-2.0
+// ========================================================================
+//
+
+package org.eclipse.jetty.server.handler;
+
+import org.eclipse.jetty.server.Handler;
+import org.eclipse.jetty.server.HttpStream;
+import org.eclipse.jetty.server.Request;
+import org.eclipse.jetty.server.Response;
+import org.eclipse.jetty.util.Callback;
+import org.eclipse.jetty.util.NanoTime;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
+/**
+ * <p>A <code>Handler</code> that allows recording the latency of the requests executed by the wrapped handler.</p>
+ * <p>The latency reported by {@link #onRequestComplete(long)} is the delay between the first notice of the request
+ * (obtained from {@link HttpStream#getNanoTime()}) until the stream completion event has been handled by
+ * {@link HttpStream#succeeded()} or {@link HttpStream#failed(Throwable)}.</p>
+ */
+public abstract class AbstractLatencyRecordingHandler extends Handler.Wrapper
+{
+    private static final Logger LOG = LoggerFactory.getLogger(AbstractLatencyRecordingHandler.class);
+
+    public AbstractLatencyRecordingHandler()
+    {
+    }
+
+    private HttpStream recordingWrapper(HttpStream httpStream)
+    {
+        return new HttpStream.Wrapper(httpStream)
+        {
+            @Override
+            public void succeeded()
+            {
+                // Take the httpStream nano timestamp before calling super.
+                long begin = httpStream.getNanoTime();
+                super.succeeded();
+                fireOnRequestComplete(begin);
+            }
+
+            @Override
+            public void failed(Throwable x)
+            {
+                // Take the httpStream nano timestamp before calling super.
+                long begin = httpStream.getNanoTime();
+                super.failed(x);
+                fireOnRequestComplete(begin);
+            }
+
+            private void fireOnRequestComplete(long begin)
+            {
+                try
+                {
+                    onRequestComplete(NanoTime.since(begin));
+                }
+                catch (Throwable t)
+                {
+                    if (LOG.isDebugEnabled())
+                        LOG.debug("Error thrown by onRequestComplete", t);
+                }
+            }
+        };
+    }
+
+    @Override
+    public boolean process(Request request, Response response, Callback callback) throws Exception
+    {
+        request.addHttpStreamWrapper(this::recordingWrapper);
+        return super.process(request, response, callback);
+    }
+
+    /**
+     * Called back for each completed request with its execution's latency.
+     * @param durationInNs the duration in nanoseconds of the completed request
+     */
+    protected abstract void onRequestComplete(long durationInNs);
+}

jetty-core/jetty-server/src/test/java/org/eclipse/jetty/server/LatencyRecordingHandlerTest.java

@@ -0,0 +1,124 @@
+//
+// ========================================================================
+// Copyright (c) 1995-2022 Mort Bay Consulting Pty Ltd and others.
+//
+// This program and the accompanying materials are made available under the
+// terms of the Eclipse Public License v. 2.0 which is available at
+// https://www.eclipse.org/legal/epl-2.0, or the Apache License, Version 2.0
+// which is available at https://www.apache.org/licenses/LICENSE-2.0.
+//
+// SPDX-License-Identifier: EPL-2.0 OR Apache-2.0
+// ========================================================================
+//
+
+package org.eclipse.jetty.server;
+
+import java.util.List;
+import java.util.concurrent.CopyOnWriteArrayList;
+import java.util.concurrent.TimeUnit;
+
+import org.awaitility.Awaitility;
+import org.eclipse.jetty.logging.JettyLevel;
+import org.eclipse.jetty.logging.JettyLogger;
+import org.eclipse.jetty.server.handler.AbstractLatencyRecordingHandler;
+import org.eclipse.jetty.server.handler.ContextHandler;
+import org.eclipse.jetty.util.Callback;
+import org.junit.jupiter.api.AfterEach;
+import org.junit.jupiter.api.BeforeEach;
+import org.junit.jupiter.api.Test;
+import org.slf4j.LoggerFactory;
+
+import static org.hamcrest.MatcherAssert.assertThat;
+import static org.hamcrest.Matchers.containsString;
+import static org.hamcrest.Matchers.greaterThan;
+import static org.hamcrest.Matchers.is;
+
+public class LatencyRecordingHandlerTest
+{
+    private JettyLevel _oldLevel;
+    private Server _server;
+    private LocalConnector _local;
+    private final List<Long> _latencies = new CopyOnWriteArrayList<>();
+
+    @BeforeEach
+    public void setUp() throws Exception
+    {
+        _server = new Server();
+        _local = new LocalConnector(_server, new HttpConnectionFactory());
+        _server.addConnector(_local);
+
+        Handler handler = new Handler.Abstract()
+        {
+            @Override
+            public boolean process(Request request, Response response, Callback callback)
+            {
+                String path = request.getHttpURI().getPath();
+                if (path.endsWith("/fail"))
+                    callback.failed(new Exception());
+                else
+                    callback.succeeded();
+                return true;
+            }
+        };
+        AbstractLatencyRecordingHandler latencyRecordingHandler = new AbstractLatencyRecordingHandler()
+        {
+            @Override
+            protected void onRequestComplete(long durationInNs)
+            {
+                _latencies.add(durationInNs);
+            }
+        };
+        latencyRecordingHandler.setHandler(handler);
+
+        ContextHandler contextHandler = new ContextHandler("/ctx");
+        contextHandler.setHandler(latencyRecordingHandler);
+
+        _server.setHandler(contextHandler);
+        _server.start();
+
+        // Disable WARN logs of failed requests.
+        JettyLogger logger = (JettyLogger)LoggerFactory.getLogger(Response.class);
+        _oldLevel = logger.getLevel();
+        logger.setLevel(JettyLevel.OFF);
+    }
+
+    @AfterEach
+    public void tearDown() throws Exception
+    {
+        _server.stop();
+        _latencies.clear();
+
+        JettyLogger logger = (JettyLogger)LoggerFactory.getLogger(Response.class);
+        logger.setLevel(_oldLevel);
+    }
+
+    @Test
+    public void testLatenciesRecodingUponSuccess() throws Exception
+    {
+        for (int i = 0; i < 100; i++)
+        {
+            String response = _local.getResponse("GET /ctx/succeed HTTP/1.1\r\nHost: localhost\r\n\r\n");
+            assertThat(response, containsString(" 200 OK"));
+        }
+        Awaitility.await().atMost(5, TimeUnit.SECONDS).until(_latencies::size, is(100));
+        for (Long latency : _latencies)
+        {
+            assertThat(latency, greaterThan(0L));
+        }
+    }
+
+    @Test
+    public void testLatenciesRecodingUponFailure() throws Exception
+    {
+        for (int i = 0; i < 100; i++)
+        {
+            String response = _local.getResponse("GET /ctx/fail HTTP/1.1\r\nHost: localhost\r\n\r\n");
+            assertThat(response, containsString(" 500 Server Error"));
+        }
+        Awaitility.await().atMost(5, TimeUnit.SECONDS).until(_latencies::size, is(100));
+        for (Long latency : _latencies)
+        {
+            assertThat(latency, greaterThan(0L));
+        }
+    }
+}