Latency can be a major cause of performance issues in distributed systems. Even a simple system with a single web server and a single database can fall victim to the N+1 problem (SQL or API Based), processing one record at a time vs batching, or serial vs parallel execution. To help highlight some of these issues in future posts we need way to add artificial latency to http requests.

Scenario

Create custom Undertow HttpHandler's that block for ~1 second

Web server will only have a single IO worker and five worker threads

Make five requests in parallel

Delay Handler and Sleep Handler

We will start out with a naive sleep implementation using Guava's Uninterruptibles.sleepUninterruptibly and then test out a non-blocking option utilizing XnioExecutor.executeAfter method exposed to us by Undertow. Both approaches will then be tested on just the IO thread followed by dispatching to worker threads. Our only intention is to show the differences between all the approaches, not to compare performance or suggest one method over the other. We will dive into the DelayedExecutionHandler implementation later on.

private static HttpHandler getRouter() { // Handler using Thread.sleep for a blocking delay HttpHandler sleepHandler = (exchange) -> { log.debug("In sleep handler"); Uninterruptibles.sleepUninterruptibly(1L, TimeUnit.SECONDS); Exchange.body().sendText(exchange, "ok"); }; // Custom handler using XnioExecutor.executeAfter // internals for a non blocking delay DelayedExecutionHandler delayedHandler = DiagnosticHandlers.fixedDelay( (exchange) -> { log.debug("In delayed handler"); Exchange.body().sendText(exchange, "ok"); }, 1L, TimeUnit.SECONDS); HttpHandler routes = new RoutingHandler() .get("/sleep", sleepHandler) .get("/dispatch/sleep", new BlockingHandler(sleepHandler)) .get("/delay", delayedHandler) .get("/dispatch/delay", new BlockingHandler(delayedHandler)) .setFallbackHandler(RoutingHandlers::notFoundHandler); return CustomHandlers.accessLog(routes, LoggerFactory.getLogger("Access Log")); }

Parallel Request Helper

Additionally we have a helper function for executing N GET requests in parallel using the OkHttpClient. This will spin up a new fixed size thread pool, execute the requests, and finally shutdown the executor using Guava's MoreExecutors.shutdownAndAwaitTermination .

public static void getInParallel(OkHttpClient client, String url, int count) { ExecutorService exec = Executors.newFixedThreadPool(count); for (int i = 0; i < count; i++) { exec.submit(() -> Http.get(client, url)); } MoreExecutors.shutdownAndAwaitTermination(exec, 30, TimeUnit.SECONDS); }

Main Method

Here we will be spinning up a simple embedded Undertow web server configured with a single IO worker and five worker threads. Then we make five parallel requests to each endpoint to see the results.

public static void main(String[] args) { SimpleServer server = SimpleServer.simpleServer(getRouter()); server.getUndertow() .setIoThreads(1) .setWorkerThreads(5); Undertow undertow = server.start(); OkHttpClient client = HttpClient.globalClient(); Timers.time("---------- sleep ----------", () -> Http.getInParallel(client, "http://localhost:8080/sleep", 5)); Timers.time("---------- dispatch sleep ----------", () -> Http.getInParallel(client, "http://localhost:8080/dispatch/sleep", 5)); Timers.time("---------- delay ----------", () -> Http.getInParallel(client, "http://localhost:8080/delay", 5)); Timers.time("---------- dispatch delay ----------", () -> Http.getInParallel(client, "http://localhost:8080/dispatch/delay", 5)); undertow.stop(); }

Sleep Handler IO Thread Results

You should never be calling blocking operations on the IO threads but we did this purposefully here just as an example. It took a total of ~5 seconds to make our five concurrent requests. The first request took ~1 second and each additional request took a second longer than the one before it. This is expected as we were blocking the only IO thread ( XNIO-1 I/O-1 ) so each request needed to process serially.

2019-03-13 21:56:33.951 [main] INFO com.stubbornjava.common.Timers - ---------- sleep ---------- 2019-03-13 21:56:33.954 [pool-5-thread-2] DEBUG com.stubbornjava.common.HttpClient - --> GET http://localhost:8080/sleep http/1.1 2019-03-13 21:56:33.954 [pool-5-thread-1] DEBUG com.stubbornjava.common.HttpClient - --> GET http://localhost:8080/sleep http/1.1 2019-03-13 21:56:33.957 [pool-5-thread-3] DEBUG com.stubbornjava.common.HttpClient - --> GET http://localhost:8080/sleep http/1.1 2019-03-13 21:56:33.959 [XNIO-1 I/O-1] DEBUG c.s.e.u.h.DelayedHandlerExample - In sleep handler 2019-03-13 21:56:33.959 [pool-5-thread-5] DEBUG com.stubbornjava.common.HttpClient - --> GET http://localhost:8080/sleep http/1.1 2019-03-13 21:56:33.959 [pool-5-thread-4] DEBUG com.stubbornjava.common.HttpClient - --> GET http://localhost:8080/sleep http/1.1 2019-03-13 21:56:34.962 [XNIO-1 I/O-1] INFO Access Log - HTTP/1.1 127.0.0.1 - "GET /sleep HTTP/1.1" 200 1003ms 2 bytes "-" "okhttp/3.11.0" 2019-03-13 21:56:34.962 [pool-5-thread-1] DEBUG com.stubbornjava.common.HttpClient -

Sleep Handler Dispatching to Worker Threads Results

Since you should never be blocking the IO threads this example will dispatch the sleep operation to our pool of five worker threads. Since we now have five worker threads ( XNIO-1 task-{n} ) that are able to handle blocking operations our total response time is ~1 second with each request taking about a second. If we had more requests than workers the requests would queue up.

2019-03-13 21:56:38.980 [main] INFO com.stubbornjava.common.Timers - ---------- dispatch sleep ---------- 2019-03-13 21:56:38.982 [pool-6-thread-2] DEBUG com.stubbornjava.common.HttpClient - --> GET http://localhost:8080/dispatch/sleep http/1.1 2019-03-13 21:56:38.982 [pool-6-thread-4] DEBUG com.stubbornjava.common.HttpClient - --> GET http://localhost:8080/dispatch/sleep http/1.1 2019-03-13 21:56:38.982 [pool-6-thread-1] DEBUG com.stubbornjava.common.HttpClient - --> GET http://localhost:8080/dispatch/sleep http/1.1 2019-03-13 21:56:38.982 [pool-6-thread-3] DEBUG com.stubbornjava.common.HttpClient - --> GET http://localhost:8080/dispatch/sleep http/1.1 2019-03-13 21:56:38.983 [XNIO-1 task-2] DEBUG c.s.e.u.h.DelayedHandlerExample - In sleep handler 2019-03-13 21:56:38.983 [XNIO-1 task-5] DEBUG c.s.e.u.h.DelayedHandlerExample - In sleep handler 2019-03-13 21:56:38.983 [XNIO-1 task-1] DEBUG c.s.e.u.h.DelayedHandlerExample - In sleep handler 2019-03-13 21:56:38.983 [pool-6-thread-5] DEBUG com.stubbornjava.common.HttpClient - --> GET http://localhost:8080/dispatch/sleep http/1.1 2019-03-13 21:56:38.984 [XNIO-1 task-4] DEBUG c.s.e.u.h.DelayedHandlerExample - In sleep handler 2019-03-13 21:56:38.984 [XNIO-1 task-3] DEBUG c.s.e.u.h.DelayedHandlerExample - In sleep handler 2019-03-13 21:56:39.987 [XNIO-1 task-2] INFO Access Log - HTTP/1.1 127.0.0.1 - "GET /dispatch/sleep HTTP/1.1" 200 1004ms 2 bytes "-" "okhttp/3.11.0" 2019-03-13 21:56:39.987 [pool-6-thread-3] DEBUG com.stubbornjava.common.HttpClient -

Delay Handler Implementation

Here we have a non blocking HttpHandler that utilizes XnioExecutor.executeAfter to achieve our delay. We need to undispatch the HttpServerExchange if it has already been dispatched so we can spin on the IO thread.

/** * A non blocking handler to add a time delay before the next handler * is executed. If the exchange has already been dispatched this will * un-dispatch the exchange and re-dispatch it before next is called. */ public class DelayedExecutionHandler implements HttpHandler { private final HttpHandler next; private final Function<HttpServerExchange, Duration> durationFunc; DelayedExecutionHandler(HttpHandler next, Function<HttpServerExchange, Duration> durationFunc) { this.next = next; this.durationFunc = durationFunc; } @Override public void handleRequest(HttpServerExchange exchange) throws Exception { Duration duration = durationFunc.apply(exchange); final HttpHandler delegate; if (exchange.isBlocking()) { // We want to undispatch here so that we are not blocking // a worker thread. We will spin on the IO thread using the // built in executeAfter. exchange.unDispatch(); delegate = new BlockingHandler(next); } else { delegate = next; } exchange.dispatch(exchange.getIoThread(), () -> { exchange.getIoThread().executeAfter(() -> Connectors.executeRootHandler(delegate, exchange), duration.toMillis(), TimeUnit.MILLISECONDS); }); } }

/** * Add a fixed delay before execution of the next handler * @param next * @param duration * @param unit * @return */ public static DelayedExecutionHandler fixedDelay(HttpHandler next, long duration, TimeUnit unit) { return new DelayedExecutionHandler( next, (exchange) -> Duration.ofMillis(unit.toMillis(duration))); } /** * Add a random delay between minDuration (inclusive) and * maxDuration (exclusive) before execution of the next handler. * This can be used to add artificial latency for requests. * * @param next * @param minDuration inclusive * @param maxDuration exclusive * @param unit * @return */ public static DelayedExecutionHandler randomDelay(HttpHandler next, long minDuration, long maxDuration, TimeUnit unit) { return new DelayedExecutionHandler( next, (exchange) -> { long duration = ThreadLocalRandom.current() .nextLong(minDuration, maxDuration); return Duration.ofMillis(unit.toMillis(duration)); }); }

Delay Handler IO Thread Results

Utilizing XnioExecutor.executeAfter we are able to achieve our same one second delay across all five requests with only the IO thread ( XNIO-1 I/O-1 ). This is an option that could allow us to delay many parallel requests with fewer threads than the blocking approach.

2019-03-13 21:56:39.991 [main] INFO com.stubbornjava.common.Timers - ---------- delay ---------- 2019-03-13 21:56:39.992 [pool-7-thread-1] DEBUG com.stubbornjava.common.HttpClient - --> GET http://localhost:8080/delay http/1.1 2019-03-13 21:56:39.992 [pool-7-thread-3] DEBUG com.stubbornjava.common.HttpClient - --> GET http://localhost:8080/delay http/1.1 2019-03-13 21:56:39.992 [pool-7-thread-2] DEBUG com.stubbornjava.common.HttpClient - --> GET http://localhost:8080/delay http/1.1 2019-03-13 21:56:39.993 [pool-7-thread-4] DEBUG com.stubbornjava.common.HttpClient - --> GET http://localhost:8080/delay http/1.1 2019-03-13 21:56:39.993 [pool-7-thread-5] DEBUG com.stubbornjava.common.HttpClient - --> GET http://localhost:8080/delay http/1.1 2019-03-13 21:56:40.998 [XNIO-1 I/O-1] DEBUG c.s.e.u.h.DelayedHandlerExample - In delayed handler 2019-03-13 21:56:40.999 [XNIO-1 I/O-1] INFO Access Log - HTTP/1.1 127.0.0.1 - "GET /delay HTTP/1.1" 200 1005ms 2 bytes "-" "okhttp/3.11.0" 2019-03-13 21:56:40.999 [pool-7-thread-1] DEBUG com.stubbornjava.common.HttpClient -

Delay Handler Dispatching to Worker Threads Results

The delayed handler operating on the dispatched threads has similar results as the sleeping approach dispatching to worker threads. This approach probably has slightly higher overhead since we are bouncing from the IO thread to the worker thread, then back to the IO thread, and finally completing in the worker again.