diff --git a/jetty-core/jetty-server/src/main/java/org/eclipse/jetty/server/handler/AbstractLatencyRecordingHandler.java b/jetty-core/jetty-server/src/main/java/org/eclipse/jetty/server/handler/AbstractLatencyRecordingHandler.java index bfb0584bde59..fecc01d19275 100644 --- a/jetty-core/jetty-server/src/main/java/org/eclipse/jetty/server/handler/AbstractLatencyRecordingHandler.java +++ b/jetty-core/jetty-server/src/main/java/org/eclipse/jetty/server/handler/AbstractLatencyRecordingHandler.java @@ -25,7 +25,10 @@ import org.slf4j.LoggerFactory; /** - * A Handler that allows recording the latencies of the requests executed by the wrapped handler. + *

A Handler that allows recording the latency of the requests executed by the wrapped handler.

+ *

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)}.

*/ public abstract class AbstractLatencyRecordingHandler extends Handler.Wrapper { @@ -40,27 +43,22 @@ public AbstractLatencyRecordingHandler() @Override public void succeeded() { - long begin = httpStream.getNanoTime(); super.succeeded(); - try - { - onRequestComplete(NanoTime.since(begin)); - } - catch (Throwable t) - { - if (LOG.isDebugEnabled()) - LOG.debug("Error thrown by onRequestComplete", t); - } + fireOnRequestComplete(); } @Override public void failed(Throwable x) { - long begin = httpStream.getNanoTime(); super.failed(x); + fireOnRequestComplete(); + } + + private void fireOnRequestComplete() + { try { - onRequestComplete(NanoTime.since(begin)); + onRequestComplete(NanoTime.since(httpStream.getNanoTime())); } catch (Throwable t) { @@ -79,7 +77,7 @@ public boolean process(Request request, Response response, Callback callback) th } /** - * Called back for each completed request with its execution's duration. + * 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); diff --git a/jetty-core/jetty-server/src/test/java/org/eclipse/jetty/server/LatencyRecordingHandlerTest.java b/jetty-core/jetty-server/src/test/java/org/eclipse/jetty/server/LatencyRecordingHandlerTest.java new file mode 100644 index 000000000000..ec0e53bd2077 --- /dev/null +++ b/jetty-core/jetty-server/src/test/java/org/eclipse/jetty/server/LatencyRecordingHandlerTest.java @@ -0,0 +1,114 @@ +// +// ======================================================================== +// 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.is; + +public class LatencyRecordingHandlerTest +{ + private JettyLevel _oldLevel; + private Server _server; + private LocalConnector _local; + private final List _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)); + } + + @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)); + } +}