CompletableFuture inside another CompletableFuture doesn't join with timeout

user_13205898 0
Viewed 48

I have one completable future that just runs another completable future(that takes always about 2 seconds and timeout of 50 ms) and waits for it to complete with timeout 1 second.

The problem is timeout of inner future never works, but get works for about two seconds, though it has timeout of 50 ms and consequently outer CompletableFuture time outs.

sleepFor2000Ms calls Thread.sleep(2000)

private static void oneCompletableFutureInsideAnother() throws InterruptedException, ExecutionException{
    long time = System.nanoTime();
    try{
        System.out.println("2 started");
        CompletableFuture.runAsync(() -> {
            long innerTime = System.nanoTime();
            try{
                System.out.println("inner started");
                CompletableFuture.runAsync(TestApplication::sleepFor2000Ms)
                    .get(50, TimeUnit.MILLISECONDS); // this get doesn't work
                // it waits way longer, until the future completes successfully
                System.out.println("inner completed successfully");
            }catch(InterruptedException | ExecutionException | TimeoutException e){
                System.out.println("inner timed out");
            }
            long innerTimeEnd = System.nanoTime();
            System.out.println("inner took " + (innerTimeEnd - innerTime)/1_000_000 + " ms");
        }).get(1, TimeUnit.SECONDS);
        System.out.println("2 completed successfully");
    }catch(TimeoutException e){
        System.out.println("2 timed out");
    }
    long endTime = System.nanoTime();
    System.out.println("2 took " + (endTime - time)/1_000_000 + " ms");
}

Expected output looks like this(and i get this input on java 8):

2 started
inner started
inner timed out
inner took 61 ms
2 completed successfully
2 took 62 ms

Actual output is(i get it on java 9 and higher):

2 started
inner started
2 timed out
2 took 1004 ms
inner completed successfully
inner took 2013 ms

If i do the same job, but inside single CompletableFuture, it time outs correctly:

private static void oneCompletableFuture() throws InterruptedException, ExecutionException{
    long time = System.nanoTime();
    try{
        System.out.println("1 started");
        CompletableFuture.runAsync(TestApplication::sleepFor2000Ms)
            .get(50, TimeUnit.MILLISECONDS); // this get works ok
        // it waits for 50 ms and then throws TimeoutException
        System.out.println("1 completed successfully");
    }catch(TimeoutException e){
        System.out.println("1 timed out");
    }
    long endTime = System.nanoTime();
    System.out.println("1 took " + (endTime - time)/1_000_000 + " ms");
}

Is it intended to work this way or am I doing something wrong or maybe it's bug in java library?

completable-future forkjoinpool java
1 Answers

Unlike the Java 8 version, the .get(50, TimeUnit.MILLISECONDS) call of newer versions tries to perform some other pending tasks instead of blocking the caller thread, not considering that it can’t predict how long these tasks may take and hence, by what margin it may miss the timeout goal. When it happens to pick up the very task it’s waiting for, the result is like having no timeout at all.

When I add a Thread.dumpStack(); to sleepFor2000Ms(), the affected environments print something like

java.lang.Exception: Stack trace
    at java.base/java.lang.Thread.dumpStack(Thread.java:1380)
    at TestApplication.sleepFor2000Ms(TestApplication.java:36)
    at java.base/java.util.concurrent.CompletableFuture$AsyncRun.run(CompletableFuture.java:1804)
    at java.base/java.util.concurrent.CompletableFuture$AsyncRun.exec(CompletableFuture.java:1796)
    at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:373)
    at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.helpAsyncBlocker(ForkJoinPool.java:1253)
    at java.base/java.util.concurrent.ForkJoinPool.helpAsyncBlocker(ForkJoinPool.java:2237)
    at java.base/java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1933)
    at java.base/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2095)
    at TestApplication.lambda$0(TestApplication.java:15)
    at java.base/java.util.concurrent.CompletableFuture$AsyncRun.run(CompletableFuture.java:1804)
    at java.base/java.util.concurrent.CompletableFuture$AsyncRun.exec(CompletableFuture.java:1796)
    at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:373)
    at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1182)
    at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1655)
    at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1622)
    at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:165)

but note that this is a race. It does not always happen. And when I change the inner code to

CompletableFuture<Void> inner
    = CompletableFuture.runAsync(TestApplication::sleepFor2000Ms);
LockSupport.parkNanos(1_000_000);
inner.get(50, TimeUnit.MILLISECONDS);

the timeout reproducibly works (this may still fail under heavy load though).

I could not find a matching bug report, however, there’s a similar problem with ForkJoinTask, ForkJoinTask.get(timeout) Might Wait Forever. This also hasn’t been fixed yet.

I would expect that when Virtual Threads (aka project Loom) become reality, such problems will disappear, as then, there is no reason to avoid blocking of threads because the underlying native thread can be reused without such quirks.

Until then, you should rather avoid blocking worker threads in general. Java 8’s strategy of starting compensation threads when worker threads get blocked, doesn’t scale well, so you’re exchanging one problem for another.

user_27114880
Related