Calculate elapsed time in a completable future chain

Question

I have several async api calls combined together in a completable futures chain. Each stage depends on the previous stage, i.e. if the previous call returned non-empty data, then we skip next call or make a call otherwise.

I want to measure not only the total time spent on the whole chain execution but also time spent on each api call individually.

How one can achieve that?

import java.util.concurrent.CompletableFuture;
import java.util.concurrent.ExecutionException;

public class CompletableFutureApiCallsExample {

public static void main(String[] args) throws ExecutionException, InterruptedException {
    var chain = apiCall1()
            .thenCompose(result1 -> {
                if (result1.isEmpty()) {
                    return apiCall2();
                } else {
                    return CompletableFuture.completedFuture(result1);
                }
            })
            .thenCompose(result2 -> {
                if (result2.isEmpty()) {
                    return apiCall3();
                } else {
                    return CompletableFuture.completedFuture(result2);
                }
            })
            .thenApply(CompletableFutureApiCallsExample::finalMapping);
    System.out.println(chain.get()); // return result
}

private static CompletableFuture<String> apiCall1() {
    return CompletableFuture.supplyAsync(() -> "API Call 1 result");
}

private static CompletableFuture<String> apiCall2() {
    return CompletableFuture.supplyAsync(() -> "API Call 2 result");
}

private static CompletableFuture<String> apiCall3() {
    return CompletableFuture.supplyAsync(() -> "API Call 3 result");
}

private static String finalMapping(String result) {
    // do mapping and return result;
    return "Final result";
}

Answer 1

You can keep a Map<Call, Instant> timestamps with an enum Call

enum Call {
 START,
 API_CALL_1,
 API_CALL_2,
 API_CALL_3,
 END
}

so in the end you have something like

START -> 12:17:01.123
API_CALL_1 -> 12:17:01.124
API_CALL_2 -> 12:17:03.242
API_CALL_3 -> 12:17:04.530
END -> 12:17:05.124

which will allow you to see how long each call took as well as the overall thing.

To do this, you can create something like a CallTimer which allows you to wrap each individual CompletableFuture into the associated enum value, like

class CallTimer {
 // use an EnumMap here but I'm too lazy to look up how to create one
 Map<Call, Instant> callTimes = new HashMap<>(); 

 public CallTimer() {
  callTimes.put(START, Instant.now());
 }

 // put start time into the map, but return the result of the actual call
 <T> CompletableFuture<T> wrap(CompletableFuture<T> call, Call id) {
   return CompletableFuture.completedFuture(Instant.now())
          .thenCompose(timestamp -> {
            calltimes.put(id, timestamp); 
            return call;
          });
 }

 void finished() {
  callTimes.put(END, Instant.now());
 }

 Map<Call, Instant> callTimes() {
  return Collections.unmodifiableMap(callTimes);
 }
}

and then for each call you perform in the main function, you use the timer's wrap instead.

public static void main(String[] args) throws ExecutionException, InterruptedException {
    CallTimer timer = new CallTimer();
    var chain = timer.wrap(apiCall1(), API_CALL_1)
            .thenCompose(result1 -> {
                if (result1.isEmpty()) {
                    return timer.wrap(apiCall2(), API_CALL_2);
                } else {
                    return CompletableFuture.completedFuture(result1);
                }
            })
            .thenCompose(result2 -> {
                if (result2.isEmpty()) {
                    return timer.wrap(apiCall3(), API_CALL_3);
                } else {
                    return CompletableFuture.completedFuture(result2);
                }
            })
            .thenApply(r -> {
               var result = finalMapping(r);
               timer.finished();
               return result;
             );
    System.out.println(chain.get()); // return result
    System.out.println(timer.callTimes()); // print times
}

I have not actually run or even compiled this so there's probably going to be some issues, but the general concept should be sound. You can also extend the enum and wrap() to track API_CALL_1_START and API_CALL_1_END by adding another thenApply() to put the end time after call completion.