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

Question

第一个回调电话很快,其余的延迟~50ms(非加法),我不知道为什么.

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