使用CompletableFuture时，如何正确统计testOrderFunc的操作耗时？

想要统计testOrderFunc的操作耗时，但当前代码执行时，外部的handle回调会先于内部的whenComplete执行，导致拿不到正确的耗时值，输出的是初始的0。

当前执行结果：

• 1s complete
• test0
• whenComplete 1.cost:1050

问题根源在于CompletableFuture的回调执行规则：它的回调是后进先出的——后添加的回调会先执行。你在testOrderFunc里给原始Future加了whenComplete，之后外部又给返回的这个Future加了handle，相当于handle是后添加的，所以会先跑，这时候耗时还没计算出来，execInfo.cost还是初始值0。

方案1：返回已处理耗时统计的Future（推荐） #

修改testOrderFunc，让它返回经过耗时统计处理后的新Future，而非原始的Future。这样外部的handle会附加在这个新Future上，确保耗时统计逻辑先执行，再触发外部业务回调。

修改后的完整代码：

@Test
public void testOrder2() throws InterruptedException {
    ExecInfo execInfo = new ExecInfo();
    CompletableFuture<Integer> dataFuture = testOrderFunc(execInfo);
    dataFuture.handle((dataRet, err) -> {
        System.out.println("test" + execInfo.cost);
        return null;
    });
    Thread.sleep(2000);
}

class ExecInfo {
    long cost = 0;
}

private CompletableFuture<Integer> testOrderFunc(ExecInfo execInfo) {
    long start = System.currentTimeMillis();

    CompletableFuture<Integer> ret = new CompletableFuture<>();

    // 给原始Future绑定耗时统计回调，返回处理后的新Future
    CompletableFuture<Integer> resultFuture = ret.whenComplete((data, error) -> {
        long end = System.currentTimeMillis();
        long spend = end - start;
        execInfo.cost = spend;
        System.out.println("whenComplete 1.cost:" + execInfo.cost);
    });

    invoke2(ret);
    // 其他关于ret的操作可正常执行
    return resultFuture;
}

private void invoke2(CompletableFuture<Integer> ret) {
    CompletableFuture.runAsync(() -> {
        try {
            Thread.sleep(1000);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        System.out.println("1s complete");
        ret.complete(1);
    });
}

方案2：调整外部回调添加顺序（不推荐） #

如果无法修改testOrderFunc的返回值，也可以在外部先添加耗时统计回调，再添加业务逻辑回调，但这种方式会把内部职责暴露到外部，封装性较差。

修改后执行结果 #

调整后执行顺序会变为：

• 1s complete
• whenComplete 1.cost:1050
• test1050

此时外部的handle就能获取到正确的耗时值了。

CompletableFuture每次调用whenComplete/handle等方法时，都会返回一个新的Future，新的回调是绑定在这个新Future上的。方案1中，外部的handle是附加在耗时统计之后的Future上，执行顺序变为：原始Future完成 → 执行耗时统计回调 → 触发新Future完成 → 执行外部handle，完美解决了回调顺序问题。

内容的提问来源于stack exchange，提问作者walker_fish