From f3c229437ae8e68db2fcdf903560c99a2d67c1b1 Mon Sep 17 00:00:00 2001 From: Ludovic Orban Date: Thu, 19 Jan 2023 10:27:05 +0100 Subject: [PATCH] Add latency recording utility handler (#9172) * #8069 add latency recording handler Signed-off-by: Ludovic Orban --- .../AbstractLatencyRecordingHandler.java | 88 +++++++++++++ .../server/LatencyRecordingHandlerTest.java | 124 ++++++++++++++++++ 2 files changed, 212 insertions(+) create mode 100644 jetty-core/jetty-server/src/main/java/org/eclipse/jetty/server/handler/AbstractLatencyRecordingHandler.java create mode 100644 jetty-core/jetty-server/src/test/java/org/eclipse/jetty/server/LatencyRecordingHandlerTest.java 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 new file mode 100644 index 000000000000..6f177859a844 --- /dev/null +++ b/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; + +/** + *

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 +{ + 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); +} 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..044c82ccdc35 --- /dev/null +++ b/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 _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)); + } + } +}