Using thenAccept after supplyAsync blocks the main thread

Question

I am developing a web application which communicates with other web applications. From time to time, my system sends HTTP request as notification to other systems. Since their responses are not essential to me, I send the requests with Java 8 CompletableFuture supplyAsync and prints their responses with thenAccept so that my main thread will not get blocked. However, I found the CompletableFuture function chains took around 100 to 200 ms each time, which confused me because from my understanding thenAccept() should run in the same thread with supplyAsync()'s.

I mocked my process with below codes

public static void run() {
    long start = System.currentTimeMillis();
    log.info("run start -> " + new Timestamp(start));
    CompletableFuture.supplyAsync(() -> {
        try {
            Thread.sleep(500);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        return 42;
    }).thenAccept(res -> log.info("run result -> " + res + ", time -> " + new Timestamp(System.currentTimeMillis())));
    log.info("run duration ->" + (System.currentTimeMillis() - start));
}

public static void runAsync() {
    long start = System.currentTimeMillis();
    log.info("runAsync start -> " + new Timestamp(start));
    CompletableFuture.supplyAsync(() -> {
        try {
            Thread.sleep(500);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        return 42;
    }).thenAcceptAsync(res -> log.info("runAsync result -> " + res + ", time ->" + new Timestamp(System.currentTimeMillis())));
    log.info("runAsync duration ->" + (System.currentTimeMillis() - start));
}

public static void main(String[] args) throws InterruptedException {
    Test.run();
    Test.runAsync();
    Thread.sleep(1000);
}

the run() method uses thenAccept() with supplyAsync() while runAsync() uses thenAcceptAsync(). I expected both of them should take just a few milliseconds. However, the real outputs are:

10:04:54.632 [main] INFO Test - run start -> 2017-12-08 10:04:54.622
10:04:54.824 [main] INFO Test - run duration ->202
10:04:54.824 [main] INFO Test - runAsync start -> 2017-12-08 10:04:54.824
10:04:54.826 [main] INFO Test - runAsync duration ->2
10:04:55.333 [ForkJoinPool.commonPool-worker-1] INFO Test - run result -> 42, time -> 2017-12-08 10:04:55.333
10:04:55.333 [ForkJoinPool.commonPool-worker-3] INFO Test - runAsync result -> 42, time ->2017-12-08 10:04:55.333

We can see run() takes 202 ms which is 100 times of the duration of runAsync() which uses only 2 ms.

I don't understand where is the 202 ms overhead comes from, and obviously it is not the lambda function in supplyAysnc() which sleeps 500 ms.

Could anyone explain why the run() method blocks, and should I always use thenAcceptAsync() over thenAccept() ?

Many thanks.

Answer 1

The 200 ms are startup time for the thread pool and all the classes supporting it.

It becomes obvious if you swap the statements in your main class:

public static void main(String[] args) throws InterruptedException {
    Test.runAsync();
    Test.run();
    Thread.sleep(1000);
}

now Test.runAsync(); is the call that needs 200 ms and Test.run(); completes in 2 ms