Why doesn't this thread pool execute HTTP requests simultaneously?

Question

I wrote a few lines of code which will send 50 HTTP GET requests to a service running on my machine. The service will always sleep 1 second and return a HTTP status code 200 with an empty body. As expected the code runs for about 50 seconds.

To speed things up a little I tried to create an ExecutorService with 4 threads so I could always send 4 requests at the same time to my service. I expected the code to run for about 13 seconds.

final List<String> urls = new ArrayList<>();
for (int i = 0; i < 50; i++)
    urls.add("http://localhost:5000/test/" + i);

final RestTemplate restTemplate = new RestTemplate();

final List<Callable<String>> tasks = urls
        .stream()
        .map(u -> (Callable<String>) () -> {
            System.out.println(LocalDateTime.now() + " - " + Thread.currentThread().getName() + ": " + u);
            return restTemplate.getForObject(u, String.class);
        }).collect(Collectors.toList());

final ExecutorService executorService = Executors.newFixedThreadPool(4);

final long start = System.currentTimeMillis();
try {
    final List<Future<String>> futures = executorService.invokeAll(tasks);

    final List<String> results = futures.stream().map(f -> {
        try {
            return f.get();
        } catch (InterruptedException | ExecutionException e) {
            throw new IllegalStateException(e);
        }
    }).collect(Collectors.toList());
    System.out.println(results);
} finally {
    executorService.shutdown();
    executorService.awaitTermination(10, TimeUnit.SECONDS);
}

final long elapsed = System.currentTimeMillis() - start;
System.out.println("Took " + elapsed + " ms...");

But - if you look at the seconds of the debug output - it seems like the first 4 requests are executed simultaneously but all other request are executed one after another:

2018-10-21T17:42:16.160 - pool-1-thread-3: http://localhost:5000/test/2
2018-10-21T17:42:16.160 - pool-1-thread-1: http://localhost:5000/test/0
2018-10-21T17:42:16.160 - pool-1-thread-2: http://localhost:5000/test/1
2018-10-21T17:42:16.159 - pool-1-thread-4: http://localhost:5000/test/3
2018-10-21T17:42:17.233 - pool-1-thread-3: http://localhost:5000/test/4
2018-10-21T17:42:18.232 - pool-1-thread-2: http://localhost:5000/test/5
2018-10-21T17:42:19.237 - pool-1-thread-4: http://localhost:5000/test/6
2018-10-21T17:42:20.241 - pool-1-thread-1: http://localhost:5000/test/7
...
Took 50310 ms...

So for debugging purposes I changed the HTTP request to a sleep call:

// return restTemplate.getForObject(u, String.class);
TimeUnit.SECONDS.sleep(1);
return "";

And now the code works as expected:

...
Took 13068 ms...

So my question is why does the code with the sleep call work as expected and the code with the HTTP request doesn't? And how can I get it to behave in the way I expected?

Answer 1

From the information, I can see this is the most probable root cause:

The requests you make are done in parallel but the HTTP server which fulfils these request handles 1 request at a time.

So when you start making requests, the executor service fires up the requests concurrently, thus you get the first 4 at same time.

But the HTTP server can respond to requests one at a time i.e. after 1 second each.

Now when 1st request is fulfilled the executor service picks another request and fires it and this goes on till last request.

4 request are blocked at HTTP server at a time, which are being served serially one after the other.

To get a Proof of Concept of this theory what you can do is use a messaging service (queue) which can receive concurrently from 4 channels an test. That should reduce the time.