Eclipse
/
jetty.project
mirror of https://github.com/jetty/jetty.project.git
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

Reintroduce dispatched and errors stats as well as stats-on time (#10678) 

* #10555 reintroduced dispatched and errors stats as well as stats-on time counter

Signed-off-by: Ludovic Orban <lorban@bitronix.be>
This commit is contained in:
Ludovic Orban 2023-10-17 14:20:08 +02:00 committed by GitHub
parent 5a21bd328a
commit 7e2c9e5e2f
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
3 changed files with 329 additions and 32 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

140
jetty-core/jetty-server/src/main/java/org/eclipse/jetty/server/handler/StatisticsHandler.java
View File

@ -15,6 +15,7 @@ package org.eclipse.jetty.server.handler;
import java.io.IOException;
import java.nio.ByteBuffer;
import java.time.Duration;
import java.util.concurrent.TimeoutException;
import java.util.concurrent.atomic.LongAdder;
@ -36,6 +37,9 @@ public class StatisticsHandler extends EventsHandler
{
private final CounterStatistic _requestStats = new CounterStatistic(); // how many requests are being handled (full lifecycle)
private final SampleStatistic _requestTimeStats = new SampleStatistic(); // latencies of requests (full lifecycle)
private final CounterStatistic _handleStats = new CounterStatistic(); // how many requests are in handle()
private final SampleStatistic _handleTimeStats = new SampleStatistic(); // latencies of requests in handle()
private final LongAdder _failures = new LongAdder();
private final LongAdder _handlingFailures = new LongAdder();
private final LongAdder _responses1xx = new LongAdder();
private final LongAdder _responses2xx = new LongAdder();
@ -44,6 +48,7 @@ public class StatisticsHandler extends EventsHandler
private final LongAdder _responses5xx = new LongAdder();
private final LongAdder _bytesRead = new LongAdder();
private final LongAdder _bytesWritten = new LongAdder();
private long _startTime = NanoTime.now();
public StatisticsHandler()
{
@ -54,10 +59,18 @@ public class StatisticsHandler extends EventsHandler
super(handler);
}
@Override
protected void doStart() throws Exception
{
reset();
super.doStart();
}
@Override
protected void onBeforeHandling(Request request)
{
_requestStats.increment();
_handleStats.increment();
}
@Override
@ -65,6 +78,8 @@ public class StatisticsHandler extends EventsHandler
{
if (failure != null)
_handlingFailures.increment();
_handleStats.decrement();
_handleTimeStats.record(NanoTime.since(request.getHeadersNanoTime()));
}
@Override
@ -98,6 +113,8 @@ public class StatisticsHandler extends EventsHandler
@Override
protected void onComplete(Request request, Throwable failure)
{
if (failure != null)
_failures.increment();
_requestTimeStats.record(NanoTime.since(request.getBeginNanoTime()));
_requestStats.decrement();
}
@ -108,6 +125,9 @@ public class StatisticsHandler extends EventsHandler
dumpObjects(out, indent,
Dumpable.named("requestStats", _requestStats),
Dumpable.named("requestTimeStats", _requestTimeStats),
Dumpable.named("handleStats", _handleStats),
Dumpable.named("handleTimeStats", _handleTimeStats),
Dumpable.named("failures", _failures),
Dumpable.named("handlingFailures", _handlingFailures),
Dumpable.named("1xxResponses", _responses1xx),
Dumpable.named("2xxResponses", _responses2xx),
@ -122,8 +142,12 @@ public class StatisticsHandler extends EventsHandler
@ManagedOperation(value = "resets the statistics", impact = "ACTION")
public void reset()
{
_startTime = NanoTime.now();
_requestStats.reset();
_requestTimeStats.reset();
_handleStats.reset();
_handleTimeStats.reset();
_failures.reset();
_handlingFailures.reset();
_responses1xx.reset();
_responses2xx.reset();
@ -134,13 +158,23 @@ public class StatisticsHandler extends EventsHandler
_bytesWritten.reset();
}
/**
* @deprecated use {@link #getRequestTotal()} instead.
*/
@Deprecated
@ManagedAttribute("number of requests")
public int getRequests()
{
return (int)_requestStats.getTotal();
}
@ManagedAttribute("number of requests currently active")
@ManagedAttribute("total number of requests")
public int getRequestTotal()
{
return (int)_requestStats.getTotal();
}
@ManagedAttribute("current number of active requests")
public int getRequestsActive()
{
return (int)_requestStats.getCurrent();
@ -152,6 +186,78 @@ public class StatisticsHandler extends EventsHandler
return (int)_requestStats.getMax();
}
@ManagedAttribute("total time spent in request execution (in ns)")
public long getRequestTimeTotal()
{
return _requestTimeStats.getTotal();
}
@ManagedAttribute("maximum request execution time (in ns)")
public long getRequestTimeMax()
{
return _requestTimeStats.getMax();
}
@ManagedAttribute("mean request execution time (in ns)")
public double getRequestTimeMean()
{
return _requestTimeStats.getMean();
}
@ManagedAttribute("standard deviation for request execution time (in ns)")
public double getRequestTimeStdDev()
{
return _requestTimeStats.getStdDev();
}
@ManagedAttribute("total number of calls to handle()")
public int getHandleTotal()
{
return (int)_handleStats.getTotal();
}
@ManagedAttribute("current number of requests in handle()")
public int getHandleActive()
{
return (int)_handleStats.getCurrent();
}
@ManagedAttribute("maximum number of requests in handle()")
public int getHandleActiveMax()
{
return (int)_handleStats.getMax();
}
@ManagedAttribute("maximum handle() execution time (in ns)")
public long getHandleTimeMax()
{
return _handleTimeStats.getMax();
}
@ManagedAttribute("total time spent in handle() execution (in ns)")
public long getHandleTimeTotal()
{
return _handleTimeStats.getTotal();
}
@ManagedAttribute("mean handle() execution time (in ns)")
public double getHandleTimeMean()
{
return _handleTimeStats.getMean();
}
@ManagedAttribute("standard deviation for handle() execution time (in ns)")
public double getHandleTimeStdDev()
{
return _handleTimeStats.getStdDev();
}
@ManagedAttribute("number of failed requests")
public int getFailures()
{
return _failures.intValue();
}
@ManagedAttribute("number of requests with 1xx response status")
public int getResponses1xx()
{
@ -182,36 +288,12 @@ public class StatisticsHandler extends EventsHandler
return _responses5xx.intValue();
}
@ManagedAttribute("number of requests that threw an exception during handling")
@ManagedAttribute("number of requests that threw an exception from handle()")
public int getHandlingFailures()
{
return _handlingFailures.intValue();
}
@ManagedAttribute("total time spend in all request execution (in ns)")
public long getRequestTimeTotal()
{
return _requestTimeStats.getTotal();
}
@ManagedAttribute("maximum time spend executing requests (in ns)")
public long getRequestTimeMax()
{
return _requestTimeStats.getMax();
}
@ManagedAttribute("mean time spent executing requests (in ns)")
public double getRequestTimeMean()
{
return _requestTimeStats.getMean();
}
@ManagedAttribute("standard deviation for request execution (in ns)")
public double getRequestTimeStdDev()
{
return _requestTimeStats.getStdDev();
}
@ManagedAttribute("bytes read count")
public long getBytesRead()
{
@ -224,6 +306,12 @@ public class StatisticsHandler extends EventsHandler
return _bytesWritten.longValue();
}
@ManagedAttribute("duration for which statistics have been collected")
public Duration getStatisticsDuration()
{
return Duration.ofNanos(NanoTime.since(_startTime));
}
/**
* Checks that the wrapped handler can read/write at a minimal rate of N bytes per second.
* When reading or writing does not conform to the specified rates, this handler prevents

219
jetty-core/jetty-server/src/test/java/org/eclipse/jetty/server/handler/StatisticsHandlerTest.java
View File

@ -43,6 +43,7 @@ import static org.hamcrest.Matchers.allOf;
import static org.hamcrest.Matchers.containsString;
import static org.hamcrest.Matchers.equalTo;
import static org.hamcrest.Matchers.greaterThan;
import static org.hamcrest.Matchers.greaterThanOrEqualTo;
import static org.hamcrest.Matchers.instanceOf;
import static org.hamcrest.Matchers.is;
import static org.hamcrest.Matchers.lessThan;
@ -259,6 +260,9 @@ public class StatisticsHandlerTest
assertEquals(1, _statsHandler.getRequests());
assertEquals(1, _statsHandler.getRequestsActive());
assertEquals(1, _statsHandler.getRequestsActiveMax());
assertEquals(1, _statsHandler.getHandleActive());
assertEquals(1, _statsHandler.getHandleActiveMax());
assertEquals(0, _statsHandler.getFailures());
barrier[1].await();
barrier[2].await();
@ -267,7 +271,10 @@ public class StatisticsHandlerTest
assertEquals(1, _statsHandler.getRequests());
assertEquals(0, _statsHandler.getRequestsActive());
assertEquals(1, _statsHandler.getRequestsActiveMax());
assertEquals(0, _statsHandler.getHandleActive());
assertEquals(1, _statsHandler.getHandleActiveMax());
assertEquals(1, _statsHandler.getResponses2xx());
assertEquals(0, _statsHandler.getFailures());
_latchHandler.reset();
barrier[0].reset();
@ -282,6 +289,9 @@ public class StatisticsHandlerTest
assertEquals(2, _statsHandler.getRequests());
assertEquals(1, _statsHandler.getRequestsActive());
assertEquals(1, _statsHandler.getRequestsActiveMax());
assertEquals(1, _statsHandler.getHandleActive());
assertEquals(1, _statsHandler.getHandleActiveMax());
assertEquals(0, _statsHandler.getFailures());
barrier[1].await();
barrier[2].await();
@ -291,7 +301,10 @@ public class StatisticsHandlerTest
assertEquals(2, _statsHandler.getRequests());
assertEquals(0, _statsHandler.getRequestsActive());
assertEquals(1, _statsHandler.getRequestsActiveMax());
assertEquals(0, _statsHandler.getHandleActive());
assertEquals(1, _statsHandler.getHandleActiveMax());
assertEquals(2, _statsHandler.getResponses2xx());
assertEquals(0, _statsHandler.getFailures());
}
@Test
@ -316,6 +329,9 @@ public class StatisticsHandlerTest
assertEquals(2, _statsHandler.getRequests());
assertEquals(2, _statsHandler.getRequestsActive());
assertEquals(2, _statsHandler.getRequestsActiveMax());
assertEquals(2, _statsHandler.getHandleActive());
assertEquals(2, _statsHandler.getHandleActiveMax());
assertEquals(0, _statsHandler.getFailures());
barrier[1].await();
barrier[2].await();
@ -324,14 +340,17 @@ public class StatisticsHandlerTest
assertEquals(2, _statsHandler.getRequests());
assertEquals(0, _statsHandler.getRequestsActive());
assertEquals(2, _statsHandler.getRequestsActiveMax());
assertEquals(0, _statsHandler.getHandleActive());
assertEquals(2, _statsHandler.getHandleActiveMax());
assertEquals(2, _statsHandler.getResponses2xx());
assertEquals(0, _statsHandler.getFailures());
}
@Test
public void testProcessingIncrementThenAcceptingIncrement() throws Exception
public void testHandlingIncrementThenAcceptingIncrement() throws Exception
{
CyclicBarrier[] barrier = {new CyclicBarrier(2), new CyclicBarrier(2), new CyclicBarrier(2), new CyclicBarrier(2), new CyclicBarrier(2)};
_statsHandler.setHandler(new Handler.Abstract(Invocable.InvocationType.BLOCKING)
_statsHandler.setHandler(new Handler.Abstract()
{
@Override
public boolean handle(Request request, Response response, Callback callback) throws Exception
@ -362,12 +381,14 @@ public class StatisticsHandlerTest
assertEquals(1, _statistics.getConnections());
assertEquals(1, _statsHandler.getRequests());
assertEquals(1, _statsHandler.getRequestsActive());
assertEquals(1, _statsHandler.getHandleActive());
barrier[1].await();
barrier[2].await();
assertEquals(1, _statistics.getConnections());
assertEquals(1, _statsHandler.getRequests());
assertEquals(1, _statsHandler.getRequestsActive());
assertEquals(1, _statsHandler.getHandleActive());
barrier[3].await();
barrier[4].await();
@ -378,11 +399,86 @@ public class StatisticsHandlerTest
assertEquals(1, _statistics.getConnections());
assertEquals(1, _statsHandler.getRequests());
assertEquals(0, _statsHandler.getRequestsActive());
assertEquals(0, _statsHandler.getHandleActive());
}
}
@Test
public void testThrownInProcess() throws Exception
public void testHandlingIncrementThenAsyncSuccessIncrement() throws Exception
{
CyclicBarrier[] barrier = {new CyclicBarrier(2), new CyclicBarrier(2), new CyclicBarrier(2), new CyclicBarrier(2), new CyclicBarrier(2), new CyclicBarrier(2)};
_statsHandler.setHandler(new Handler.Abstract()
{
@Override
public boolean handle(Request request, Response response, Callback callback) throws Exception
{
barrier[0].await();
barrier[1].await();
barrier[2].await();
barrier[3].await();
new Thread(() ->
{
try
{
barrier[4].await();
barrier[5].await();
callback.succeeded();
}
catch (Throwable x)
{
callback.failed(x);
}
}).start();
return true;
}
});
_server.start();
String request = """
GET / HTTP/1.1\r
Host: localhost\r
\r
""";
try (LocalConnector.LocalEndPoint endp = _connector.executeRequest(request))
{
barrier[0].await();
assertEquals(1, _statistics.getConnections());
assertEquals(1, _statsHandler.getRequests());
assertEquals(1, _statsHandler.getRequestsActive());
assertEquals(1, _statsHandler.getHandleActive());
barrier[1].await();
barrier[2].await();
assertEquals(1, _statistics.getConnections());
assertEquals(1, _statsHandler.getRequests());
assertEquals(1, _statsHandler.getRequestsActive());
assertEquals(1, _statsHandler.getHandleActive());
barrier[3].await();
barrier[4].await();
assertEquals(1, _statistics.getConnections());
assertEquals(1, _statsHandler.getRequests());
assertEquals(1, _statsHandler.getRequestsActive());
assertEquals(0, _statsHandler.getHandleActive());
barrier[5].await();
String response = endp.getResponse();
assertThat(response, containsString(" 200 OK"));
await().atMost(5, TimeUnit.SECONDS).until(_statsHandler::getRequestsActive, equalTo(0));
assertEquals(1, _statistics.getConnections());
assertEquals(1, _statsHandler.getRequests());
assertEquals(0, _statsHandler.getRequestsActive());
assertEquals(0, _statsHandler.getHandleActive());
}
}
@Test
public void testThrownInHandle() throws Exception
{
_statsHandler.setHandler(new Handler.Abstract(Invocable.InvocationType.BLOCKING)
{
@ -408,6 +504,7 @@ public class StatisticsHandlerTest
await().atMost(5, TimeUnit.SECONDS).until(_statsHandler::getRequestsActive, is(0));
assertEquals(1, _statsHandler.getRequests(), "stats.requests");
assertEquals(1, _statsHandler.getRequestsActiveMax(), "stats.requestsActiveMax");
assertEquals(1, _statsHandler.getHandleActiveMax(), "stats.dispatchedActiveMax");
// We get no recorded status, but we get a recorded thrown response.
assertEquals(0, _statsHandler.getResponses1xx(), "stats.responses1xx");
@ -416,10 +513,102 @@ public class StatisticsHandlerTest
assertEquals(0, _statsHandler.getResponses4xx(), "stats.responses4xx");
assertEquals(1, _statsHandler.getResponses5xx(), "stats.responses5xx");
assertEquals(1, _statsHandler.getHandlingFailures(), "stats.handlingFailures");
assertEquals(1, _statsHandler.getFailures(), "stats.errors");
}
@Test
public void testThrownInProcessAfterCallback() throws Exception
public void testFailCallbackInHandle() throws Exception
{
_statsHandler.setHandler(new Handler.Abstract(Invocable.InvocationType.BLOCKING)
{
@Override
public boolean handle(Request request, Response response, Callback callback)
{
callback.failed(new IllegalStateException("expected"));
return true;
}
});
_server.start();
try (StacklessLogging ignored = new StacklessLogging(Response.class))
{
String request = """
GET / HTTP/1.1\r
Host: localhost\r
\r
""";
String response = _connector.getResponse(request);
assertThat(response, containsString("HTTP/1.1 500 Server Error"));
}
await().atMost(5, TimeUnit.SECONDS).until(_statsHandler::getRequestsActive, is(0));
assertEquals(1, _statsHandler.getRequests(), "stats.requests");
assertEquals(1, _statsHandler.getRequestsActiveMax(), "stats.requestsActiveMax");
assertEquals(1, _statsHandler.getHandleActiveMax(), "stats.dispatchedActiveMax");
// We get no recorded status, but we get a recorded thrown response.
assertEquals(0, _statsHandler.getResponses1xx(), "stats.responses1xx");
assertEquals(0, _statsHandler.getResponses2xx(), "stats.responses2xx");
assertEquals(0, _statsHandler.getResponses3xx(), "stats.responses3xx");
assertEquals(0, _statsHandler.getResponses4xx(), "stats.responses4xx");
assertEquals(1, _statsHandler.getResponses5xx(), "stats.responses5xx");
assertEquals(0, _statsHandler.getHandlingFailures(), "stats.handlingFailures");
assertEquals(1, _statsHandler.getFailures(), "stats.errors");
}
@Test
public void testFailCallbackAfterHandle() throws Exception
{
_statsHandler.setHandler(new Handler.Abstract(Invocable.InvocationType.BLOCKING)
{
@Override
public boolean handle(Request request, Response response, Callback callback)
{
new Thread(() ->
{
try
{
Thread.sleep(1000);
}
catch (InterruptedException e)
{
// ignore
}
callback.failed(new IllegalStateException("expected"));
}).start();
return true;
}
});
_server.start();
try (StacklessLogging ignored = new StacklessLogging(Response.class))
{
String request = """
GET / HTTP/1.1\r
Host: localhost\r
\r
""";
String response = _connector.getResponse(request);
assertThat(response, containsString("HTTP/1.1 500 Server Error"));
}
await().atMost(5, TimeUnit.SECONDS).until(_statsHandler::getRequestsActive, is(0));
assertEquals(1, _statsHandler.getRequests(), "stats.requests");
assertEquals(1, _statsHandler.getRequestsActiveMax(), "stats.requestsActiveMax");
assertEquals(1, _statsHandler.getHandleActiveMax(), "stats.dispatchedActiveMax");
// We get no recorded status, but we get a recorded thrown response.
assertEquals(0, _statsHandler.getResponses1xx(), "stats.responses1xx");
assertEquals(0, _statsHandler.getResponses2xx(), "stats.responses2xx");
assertEquals(0, _statsHandler.getResponses3xx(), "stats.responses3xx");
assertEquals(0, _statsHandler.getResponses4xx(), "stats.responses4xx");
assertEquals(1, _statsHandler.getResponses5xx(), "stats.responses5xx");
assertEquals(0, _statsHandler.getHandlingFailures(), "stats.handlingFailures");
assertEquals(1, _statsHandler.getFailures(), "stats.errors");
}
@Test
public void testThrownInHandleAfterCallback() throws Exception
{
_statsHandler.setHandler(new Handler.Abstract(Invocable.InvocationType.BLOCKING)
{
@ -447,6 +636,8 @@ public class StatisticsHandlerTest
assertEquals(1, _statsHandler.getRequests());
assertEquals(0, _statsHandler.getRequestsActive());
assertEquals(1, _statsHandler.getRequestsActiveMax());
assertEquals(0, _statsHandler.getHandleActive());
assertEquals(1, _statsHandler.getHandleActiveMax());
// We get no recorded status, but we get a recorded thrown response.
assertEquals(0, _statsHandler.getResponses1xx());
@ -455,10 +646,11 @@ public class StatisticsHandlerTest
assertEquals(0, _statsHandler.getResponses4xx());
assertEquals(0, _statsHandler.getResponses5xx());
assertEquals(1, _statsHandler.getHandlingFailures());
assertEquals(0, _statsHandler.getFailures(), "stats.errors");
}
@Test
public void testHandlingProcessingTime() throws Exception
public void testHandlingTime() throws Exception
{
final long acceptingTime = 250;
final long acceptedTime = 500;
@ -511,6 +703,7 @@ public class StatisticsHandlerTest
barrier[1].await();
assertEquals(1, _statsHandler.getRequests());
assertEquals(1, _statsHandler.getRequestsActive());
assertEquals(1, _statsHandler.getHandleActive());
barrier[2].await();
assertTrue(_latchHandler.await());
await().atMost(5, TimeUnit.SECONDS).until(_statsHandler::getRequestsActive, equalTo(0));
@ -519,6 +712,7 @@ public class StatisticsHandlerTest
assertEquals(1, _statsHandler.getRequests());
assertEquals(0, _statsHandler.getRequestsActive());
assertEquals(0, _statsHandler.getHandleActive());
assertEquals(1, _statsHandler.getResponses2xx());
_statsHandler.dumpStdErr();
@ -533,9 +727,24 @@ public class StatisticsHandlerTest
lessThan(TimeUnit.MILLISECONDS.toNanos(requestTime + wastedTime) * 5 / 4)));
assertEquals(_statsHandler.getRequestTimeTotal(), _statsHandler.getRequestTimeMax());
assertEquals(_statsHandler.getRequestTimeTotal(), _statsHandler.getRequestTimeMean(), 1.0);
assertThat(_statsHandler.getHandleTimeTotal(), allOf(
greaterThan(TimeUnit.MILLISECONDS.toNanos(handleTime + wastedTime) * 3 / 4),
lessThan(TimeUnit.MILLISECONDS.toNanos(handleTime + wastedTime) * 5 / 4)));
assertEquals(_statsHandler.getHandleTimeTotal(), _statsHandler.getHandleTimeMax());
assertEquals(_statsHandler.getHandleTimeTotal(), _statsHandler.getHandleTimeMean(), 1.0);
}
}
@Test
public void testStatsOn() throws Exception
{
_statsHandler.reset();
Thread.sleep(500);
assertThat(_statsHandler.getStatisticsDuration().toMillis(), greaterThanOrEqualTo(500L));
_statsHandler.reset();
assertThat(_statsHandler.getStatisticsDuration().toMillis(), lessThan(500L));
}
// This handler is external to the statistics handler and it is used to ensure that statistics handler's
// handle() is fully executed before asserting its values in the tests, to avoid race conditions with the
// tests' code where the test executes but the statistics handler has not finished yet.

2
jetty-core/jetty-util/src/main/java/org/eclipse/jetty/util/statistic/SampleStatistic.java
View File

@ -125,6 +125,6 @@ public class SampleStatistic
@Override
public String toString()
{
return String.format("%s@%x{count=%d,max=%d,mean=%f,total=%d,stddev=%f}", getClass().getSimpleName(), hashCode(), getCount(), getMax(), getMean(), getTotal(), getStdDev());
return String.format("%s@%x{count=%d,max=%d,mean=%f,total=%d,variance=%f,stddev=%f}", getClass().getSimpleName(), hashCode(), getCount(), getMax(), getMean(), getTotal(), getVariance(), getStdDev());
}
}