how to add the spendTime of the operation when use CompletableFuture whenComplete

Question

The demo code is like this:

@Test
public void testOrder2() throws InterruptedException {
    ExecInfo execInfo = new ExecInfo();
    CompletableFuture<Integer> dataFutrue = testOrderFunc(execInfo);
    dataFutrue.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<>();

    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);
    //may be has other operation about ret. if ret is not completed.
    return ret;
}

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

The result is :

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

It seems that whenCompete is like stack FILO.

How to get testOrderFunc cost time? Thanks your answer.

Answer 1

Since your access to cost has a dependency to the action that writes the value you should also chain it to the associated stage. E.g.

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

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

    CompletableFuture<Integer> finalStage = 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);
    // other stuff
    return finalStage;
}

But it’s preferable not to use side effects, precisely to prevent such dependency related bugs. An alternative would be

@Test
public void testOrder2() {
    CompletableFuture<Long> executionTime = new CompletableFuture<>();
    CompletableFuture<Integer> dataFuture = testOrderFunc(executionTime);
    CompletableFuture<Void> printTime = executionTime
        .thenAccept(nanos -> System.out.printf("test took %.1f ms%n", nanos * 1e-6));
    CompletableFuture.allOf(dataFuture, printTime).join();
}

private CompletableFuture<Integer> testOrderFunc(CompletableFuture<Long> timeTarget) {
    long start = System.nanoTime();
    CompletableFuture<Integer> ret = new CompletableFuture<>();
    ret.whenComplete((data, error) -> timeTarget.complete(System.nanoTime() - start));

    invoke2(ret);
    // other stuff
    return ret;
}

private void invoke2(CompletableFuture<Integer> ret) {
    CompletableFuture.runAsync(() -> {
        LockSupport.parkNanos(TimeUnit.SECONDS.toNanos(1));
        System.out.println("1s complete");
        ret.complete(1);
    });
}

This forces the caller to chain the consumer of the measured time to the right future. Further, callers not interested in the execution time can chain dependent evaluations to the data future, without creating a dependency to the time measurement.

It also allows the caller to do something like that instead:

@Test
public void testOrder2() {
    CompletableFuture<Long> executionTime = new CompletableFuture<>();
    CompletableFuture<Integer> dataFuture = testOrderFunc(executionTime);
    dataFuture.exceptionally(t -> null).thenCombine(executionTime,
        (result, nanos) -> System.out.printf("test completed with %s after %.1f ms%n",
            result == null? "an error": result, nanos * 1e-6)) .join();
    dataFuture.join(); // relay exceptions to caller, if any
}

---

Note that in general, to measure elapsed time, you should use the difference between two values returned by System.nanoTime(), which will be immune against leap seconds, NTP updates or such alike.