java - java-8 CompletableFuture 回调调用的不合理延迟

Question

第一个回调调用非常快，其余的延迟约 50 毫秒(非累加)，我不知道为什么。

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();
    }

}

输出:

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

编辑:其他情况更让我吃惊。我认为 CompletableFuture 可能不是问题所在。

如果我添加这一行:

    ...
    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

我得到这个输出，没有变化:

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

但是如果我改为添加这一行:

    ...
    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

延迟消失了!!

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

Answer 1

如果我在加入之前添加这一行，延迟就消失了，所以延迟一定与类加载有关 String.format 初始化:

    ...
    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

输出:

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