Logo Questions Linux Laravel Mysql Ubuntu Git Menu
 

Unjustified delay on java-8 CompletableFuture callback calls

First callback call is quite fast and the rest are delayed ~50ms (non additive) and I don't know why.

public class CfTest {

    final static long t0 = System.nanoTime();

    public static void main(String[] args) {
        CompletableFuture<Integer> cf1 = CompletableFuture.supplyAsync(()->{sleep(2000); return 100;});
        CompletableFuture<Long> cf2 = CompletableFuture.supplyAsync(()->{sleep(1000); return 1L;});
        CompletableFuture<Long> cfs = cf1.thenCombine(cf2, (a,b)->a+b);
        cfs.thenAccept(x->debug("a1. " + x)); // Async process, sync when complete
        cfs.thenAccept(x->debug("a2. " + x)); // Async process, sync when complete
        cfs.thenAcceptAsync(x->debug("a3. " + x)); // Async process, async after complete too
        debug("b. " + cfs.join()); // Wait and process
        debug("c. " + cfs.join()); // Wait and process
    }

    private static void sleep(int i) {
        try {
            Thread.sleep(i);
        } catch (InterruptedException e) {
            throw new RuntimeException(e);
        }
    }

    private static void debug(Object res) {
        System.out.println(String.format("after %.3fs: %s", (System.nanoTime()-t0) / (float)TimeUnit.SECONDS.toNanos(1), res));
        System.out.flush();
    }

}

output:

after 2,067s: a1. 101
after 2,129s: a2. 101
after 2,129s: a3. 101
after 2,129s: b. 101
after 2,129s: c. 101

EDIT: Other cases that surprises me even more. I think CompletableFuture may not be the problem.

If I add this line:

    ...
    cfs.thenAcceptAsync(x->debug("a3. " + x)); // Async process, async after complete too
    System.out.println("Waiting..."); // <-- New Line
    debug("b. " + cfs.join()); // Wait and process
    debug("c. " + cfs.join()); // Wait and process

I get this output, no change:

Waiting...
after 2,066s: a1. 101
after 2,121s: a2. 101
after 2,122s: a3. 101
after 2,122s: b. 101
after 2,122s: c. 101

But if I add this line instead:

    ...
    cfs.thenAcceptAsync(x->debug("a3. " + x)); // Async process, async after complete too
    debug("Waiting..."); // <-- New Line
    debug("b. " + cfs.join()); // Wait and process
    debug("c. " + cfs.join()); // Wait and process

The delay is gone!!

after 0,068s: Waiting...
after 2,066s: a1. 101
after 2,067s: a2. 101
after 2,067s: b. 101
after 2,067s: a3. 101
after 2,068s: c. 101
like image 880
aalku Avatar asked Sep 18 '15 08:09

aalku


1 Answers

If I add this line before join the delay is gone, so the delay must be related to class loading about String.format initialization:

    ...
    cfs.thenAcceptAsync(x->debug("a3. " + x)); // Async process, async after complete too
    String.format("test"); // <-- Delay is gone with this line too
    debug("b. " + cfs.join()); // Wait and process
    debug("c. " + cfs.join()); // Wait and process

output:

after 2,057s: a1. 101
after 2,068s: a2. 101
after 2,068s: b. 101
after 2,068s: a3. 101
after 2,069s: c. 101
like image 136
aalku Avatar answered Oct 16 '22 15:10

aalku