Why calling get() before exceptional completion waits for exceptionally to execute?

Question

While answering this question, I noticed a strange behaviour of CompletableFuture: if you have a CompletableFuture cf and chain a call with cf.exceptionally(), calling cf.get() appears to behave strangely:

• if you call it before exceptional completion, it waits for the execution of the exceptionally() block before returning
• otherwise, it fails immediately by throwing the expected ExecutionException

Am I missing something or is this a bug? I am using Oracle JDK 1.8.0_131 on Ubuntu 17.04.

The following code illustrates this phenomenon:

public static void main(String[] args) {
    long start = System.currentTimeMillis();
    final CompletableFuture<Object> future = CompletableFuture.supplyAsync(() -> {
        sleep(1000);
        throw new RuntimeException("First");
    }).thenApply(Function.identity());

    future.exceptionally(e -> {
        sleep(1000);
        logDuration(start, "Exceptionally");
        return null;
    });

    final CompletableFuture<Void> futureA = CompletableFuture.runAsync(() -> {
        try {
            future.get();
        } catch (Exception e) {
        } finally {
            logDuration(start, "A");
        }
    });

    final CompletableFuture<Void> futureB = CompletableFuture.runAsync(() -> {
        sleep(1100);
        try {
            future.get();
        } catch (Exception e) {
        } finally {
            logDuration(start, "B");
        }
    });

    try {
        future.join();
    } catch (Exception e) {
        logDuration(start, "Main");
    }

    futureA.join();
    futureB.join();
}

private static void sleep(final int millis) {
    try {
        Thread.sleep(millis);
    } catch (InterruptedException e) {
        Thread.currentThread().interrupt();
    }
}

private static void logDuration(long start, String who) {
    System.out.println(who + " waited for " + (System.currentTimeMillis() - start) + "ms");
}

Output:

B waited for 1347ms
Exceptionally waited for 2230ms
Main waited for 2230ms
A waited for 2230ms

As you can see, futureB which sleeps a bit before calling get() does not block at all. However, both futureA and the main thread wait for exceptionally() to complete.

Note that this behaviour does not occur if you remove the .thenApply(Function.identity()).

Answer 1

Waking up a sleeping thread is a dependent action which has to be processed like any other and it has no precedence. On the other hand, a thread polling a CompletableFuture when it has been completed already will not be put to sleep, have no need to be woken up, hence, no need to compete with the other dependent actions.

With the following program

public static void main(String[] args) {
    final CompletableFuture<Object> future = CompletableFuture.supplyAsync(() -> {
        waitAndLog("Supplier", null, 1000);
        throw new RuntimeException("First");
    }).thenApply(Function.identity());
    long start = System.nanoTime();

    CompletableFuture.runAsync(() -> waitAndLog("A", future, 0));

    LockSupport.parkNanos(TimeUnit.MILLISECONDS.toNanos(10));

    future.exceptionally(e -> {
        waitAndLog("Exceptionally", null, 1000);
        return null;
    });

    CompletableFuture.runAsync(() -> waitAndLog("B", future, 0));
    CompletableFuture.runAsync(() -> waitAndLog("C", future, 1100));

    waitAndLog("Main", future, 0);
    ForkJoinPool.commonPool().awaitQuiescence(10, TimeUnit.SECONDS);
}
private static void waitAndLog(String msg, CompletableFuture<?> primary, int sleep) {
    long nanoTime = System.nanoTime();
    Object result;
    try {
        if(sleep>0) Thread.sleep(sleep);
        result = primary!=null? primary.get(): null;
    } catch (InterruptedException|ExecutionException ex) {
        result = ex;
    }
    long millis=TimeUnit.NANOSECONDS.toMillis(System.nanoTime()-nanoTime);
    System.out.println(msg+" waited for "+millis+"ms"+(result!=null? ", got "+result: ""));
}

I get,

Supplier waited for 993ms
A waited for 993ms, got java.util.concurrent.ExecutionException: java.lang.RuntimeException: First
C waited for 1108ms, got java.util.concurrent.ExecutionException: java.lang.RuntimeException: First
Exceptionally waited for 998ms
Main waited for 1983ms, got java.util.concurrent.ExecutionException: java.lang.RuntimeException: First
B waited for 1984ms, got java.util.concurrent.ExecutionException: java.lang.RuntimeException: First

on my machine, suggesting that in this specific case, the dependent actions were executed right in the order they were scheduled, A first. Note that I inserted extra waiting time before scheduling Exceptionally, which will be the next dependent action. Since B runs in a background thread, it is non-deterministic whether it manages to schedule itself before the Main thread or not. We could insert another delay before either to enforce an order.

Since C polls an already completed future, it can proceed immediately, so its net waiting time is close to the explicitly specified sleeping time.

It must be emphasized that this is only the result of a particular scenario, dependent on implementation details. There is no guaranteed execution order for dependent actions. As you might have noticed yourself, without the .thenApply(Function.identity()) step, the implementation runs a different code path resulting in a different execution order of the dependent actions.

The dependencies form a tree and the implementation has to traverse it in an efficient manner without risking a stack overflow, hence it has to flatten it in some way and small changes to the shape of the dependency tree may influence the resulting order in a non-intuitive way.