How to measure execution time of webflux WebClient methods?

Viewed 3926

I prepare a bunch of requests that I want to send in parallel to an external webservice. In this flow, I continue to process the response directly (eg inserting something into a database).

Problem: I want to track the maximum request time (for one request!), excluding the processing. But as written, this will only track the global time including any subprocess:

StopWatch watch = new StopWatch();
watch.start();

Flux.fromIterable(requests)
    .flatMap(req -> webClient.send(req, MyResponse.class)
            .doOnSuccess(rsp -> processResponse(rsp))) //assume some longer routine
    .collectList()
    .block();
    
watch.stop();
System.out.println(w.getTotalTimeMillis());
            

Question: how can I measure the maximum time the requests took, excluding the processResponse() time?

3 Answers

When using elapsed on a mono, you will get back a mono of a tuple with both the elapsed time and the original object in it. You have to unwrap them to use those. I wrote an example (a bit simplified from your code) in a test to see it working:

@Test
public void elapsed() {

    Flux.fromIterable(List.of(1, 2, 3, 4, 5))
        .flatMap(req -> Mono.delay(Duration.ofMillis(100L * req))
                            .map(it -> "response_" + req)
                            .elapsed()
                            .doOnNext(it -> System.out.println("I took " + it.getT1() + " MS"))
                            .map(Tuple2::getT2)
                            .doOnSuccess(rsp -> processResponse(rsp)))
        .collectList()
        .block();

}

@SneakyThrows
public void processResponse(Object it) {
    System.out.println("This is the response: " + it);
    Thread.sleep(1000);
}

the output looks like this:

I took 112 MS
This is the response: response_1
I took 205 MS
This is the response: response_2
I took 305 MS
This is the response: response_3
I took 403 MS
This is the response: response_4
I took 504 MS
This is the response: response_5

those numbers represent both the delay (which in your case would be the webClient.send()) and a little overhead from the reactive pipeline itself. It is calculated between subscription (which happens when the flatMap for a specific request runs) and the next signal (the result from the map in my case, in yours the result of the webclient request)

your code would look something like this:

Flux.fromIterable(requests)
        .flatMap(req -> webClient.send(req, MyResponse.class)
                                 .elapsed()
                                 .doOnNext(it -> System.out.println("I took " + it.getT1() + " MS"))
                                 .map(Tuple2::getT2)
                                 .doOnSuccess(rsp -> processResponse(rsp))) //assume some longer routine
        .collectList()
        .block();

note if you want to use a stopwatch in stead, that is also possible by doing something like:

Flux.fromIterable(List.of(1, 2, 3, 4, 5)).flatMap(req -> {
            StopWatch stopWatch = new StopWatch();
            return Mono.fromRunnable(stopWatch::start)
                       .then(Mono.delay(Duration.ofMillis(100L * req)).map(it -> "response_" + req).doOnNext(it -> {
                           stopWatch.stop();
                           System.out.println("I took " + stopWatch.getTime() + " MS");
                       }).doOnSuccess(this::processResponse));
        }).collectList().block();

but personally I would recommend the .elapsed() solution since it's a bit cleaner.

I would avoid stopwatch directly in that method. Rather create a metrics wrapper which can be used at other places as well.

You can leverage .doOnSubscribe(), .doOnError(), .doOnSuccess() But to answer your question, you can have a timer something like this


    public sendRequest(){
                Flux.fromIterable(requests)
                .flatMap(req -> webClient.send(req, MyResponse.class)
                        .transform(timerPublisher("time took for ", req.id)))
                .collectList()
                .block();
   }

//this can be made sophisticated by determining what kind of publisher it is
//mono or flux
    private Function<Mono<T>, Publisher<T>> timerPublisher(String metric) {

        StopWatchHelper stopWatch = new StopWatchHelper(metric);
        return s -> s.doOnSubscribe((s) -> stopWatch.start())
                .doOnSuccess(documentRequest -> stopWatch.record())
                .doOnError(stopWatch::record);
    }

    private class StopWatchHelper{
        private StopWatch stopWatch;
        private String metric;
        public StopWatchHelper(String metric){
            this.metric = metric;
            stopWatch = new StopWatch();
        }
        public Consumer<Subscription> start() {
            return (s) -> stopWatch.start();
        }

        public void record(){
            if(stopWatch.isStarted()){
                System.out.println(String.format("Metric %s took %s", metric, stopWatch.getTime()));
            }
        }

        public void record(Throwable t){
            if(stopWatch.isStarted()){
                System.out.println(String.format("Metric %s took %s, reported in error %s", metric, stopWatch.getTime(),throwable));
            }
        }
    }


PS: Avoid using .block() -> it beats the purpose :) 

Spring boot provides an out of the box feature that will add instrumentation to your WebClient.

You can "enable" these metrics by using the auto-configured WebClient.Builder to create your WebClient instances ie.

@Bean
public WebClient myCustomWebClient(WebClient.Builder builder) {
    return builder
            // your custom web client config code
            .build();
}

This instrumentation will time each individual API call made by your WebClient and register it in your configured MeterRegistry

Reference Docs

Related