14장 Operator 6 - time

github : https://github.com/bjpublic/Spring-Reactive/tree/main/part2/src/main/java/chapter14/operator_6_time

 

 

14.7 Sequence 의 동작 시간 측정을 위한 Operator

delayElements(), interval(), timeout() 등 Reactor Sequence 의 동작 시간을 제어하는 Operator 를 사용해 보았는데, 

이외에도 Reactor Sequence 의 동작 시간 자체를 측정하는 특별한 Operator 가 존재합니다

1) elapsed

https://projectreactor.io/docs/core/release/api/reactor/core/publisher/Flux.html#elapsed--

elapsed() Operator 는 emit 된 데이터 사이(interval)의 경과 시간을 측정해서 Tuple<Long,T> 형태로 Downstream 에 emit 합니다

emit 되는 첫 번째 데이터는 onSubscribe Signal  과 첫 번째 데이터 사이를 기준으로 시간을 측정합니다

 

코드 14-51 elapsed 예제 1

public static void main(String[] args) throws InterruptedException {
  Flux
      .range(1, 5)
      .delayElements(Duration.ofSeconds(1))
      .elapsed()
      .subscribe(data -> log.info("# onNext: {}, time: {}",
          data.getT2(), data.getT1()));

  Thread.sleep(6000);
}
// result
> Task :Example14_51.main()
16:58:14.496 [main] reactor.util.Loggers DEBUG- Using Slf4j logging framework
16:58:15.556 [parallel-1] c.operator_6_time.Example14_51 INFO - # onNext: 1, time: 1040
16:58:16.569 [parallel-2] c.operator_6_time.Example14_51 INFO - # onNext: 2, time: 1013
16:58:17.575 [parallel-3] c.operator_6_time.Example14_51 INFO - # onNext: 3, time: 1006
16:58:18.578 [parallel-4] c.operator_6_time.Example14_51 INFO - # onNext: 4, time: 1003
16:58:19.583 [parallel-5] c.operator_6_time.Example14_51 INFO - # onNext: 5, time: 1005

delayElements 로 1초 씩 지연 시키고, elapsed() 로 시간을 측정합니다

1040

1013

1006

1003

1005

각각 1초(1,000ms) 약간 지난 시간이 측정 됩니다

 

코드 14-52 elapsed 예제 2

public static void main(String[] args) {
  URI worldTimeUri = UriComponentsBuilder.newInstance().scheme("http")
      .host("worldtimeapi.org")
      .port(80)
      .path("/api/timezone/Asia/Seoul")
      .build()
      .encode()
      .toUri();

  RestTemplate restTemplate = new RestTemplate();
  HttpHeaders headers = new HttpHeaders();
  headers.setAccept(Collections.singletonList(MediaType.APPLICATION_JSON));

  Mono.defer(() -> Mono.just(
              restTemplate
                  .exchange(worldTimeUri,
                      HttpMethod.GET,
                      new HttpEntity<String>(headers),
                      String.class)
          )
      )
      .repeat(4)
      .elapsed()
      .map(response -> {
        DocumentContext jsonContext =
            JsonPath.parse(response.getT2().getBody());
        String dateTime = jsonContext.read("$.datetime");
        return Tuples.of(dateTime, response.getT1());
      })
      .subscribe(
          data -> log.info("now: {}, elapsed time: {}", data.getT1(), data.getT2()),
          error -> log.error("# onError:", error),
          () -> log.info("# onComplete")
      );
}
// result
> Task :Example14_52.main()
17:06:26.207 [main] reactor.util.Loggers DEBUG- Using Slf4j logging framework
17:06:26.302 [main] o.s.web.client.RestTemplate DEBUG- HTTP GET http://worldtimeapi.org:80/api/timezone/Asia/Seoul
17:06:26.309 [main] o.s.web.client.RestTemplate DEBUG- Accept=[text/plain, application/json, application/*+json, */*]
17:06:26.816 [main] o.s.web.client.RestTemplate DEBUG- Response 200 OK
17:06:26.819 [main] o.s.web.client.RestTemplate DEBUG- Reading to [java.lang.String] as "application/json;charset=utf-8"
17:06:26.867 [main] c.j.j.internal.path.CompiledPath DEBUG- Evaluating path: $['datetime']
17:06:26.870 [main] c.operator_6_time.Example14_52 INFO - now: 2023-07-29T17:06:26.702709+09:00, elapsed time: 536
17:06:26.871 [main] o.s.web.client.RestTemplate DEBUG- HTTP GET http://worldtimeapi.org:80/api/timezone/Asia/Seoul
17:06:26.871 [main] o.s.web.client.RestTemplate DEBUG- Accept=[text/plain, application/json, application/*+json, */*]
17:06:27.066 [main] o.s.web.client.RestTemplate DEBUG- Response 200 OK
17:06:27.066 [main] o.s.web.client.RestTemplate DEBUG- Reading to [java.lang.String] as "application/json;charset=utf-8"
17:06:27.066 [main] c.j.j.internal.path.CompiledPath DEBUG- Evaluating path: $['datetime']
17:06:27.066 [main] c.operator_6_time.Example14_52 INFO - now: 2023-07-29T17:06:26.956999+09:00, elapsed time: 242
17:06:27.067 [main] o.s.web.client.RestTemplate DEBUG- HTTP GET http://worldtimeapi.org:80/api/timezone/Asia/Seoul
17:06:27.067 [main] o.s.web.client.RestTemplate DEBUG- Accept=[text/plain, application/json, application/*+json, */*]
17:06:27.257 [main] o.s.web.client.RestTemplate DEBUG- Response 200 OK
17:06:27.257 [main] o.s.web.client.RestTemplate DEBUG- Reading to [java.lang.String] as "application/json;charset=utf-8"
17:06:27.257 [main] c.j.j.internal.path.CompiledPath DEBUG- Evaluating path: $['datetime']
17:06:27.258 [main] c.operator_6_time.Example14_52 INFO - now: 2023-07-29T17:06:27.146173+09:00, elapsed time: 191
17:06:27.258 [main] o.s.web.client.RestTemplate DEBUG- HTTP GET http://worldtimeapi.org:80/api/timezone/Asia/Seoul
17:06:27.258 [main] o.s.web.client.RestTemplate DEBUG- Accept=[text/plain, application/json, application/*+json, */*]
17:06:27.451 [main] o.s.web.client.RestTemplate DEBUG- Response 200 OK
17:06:27.451 [main] o.s.web.client.RestTemplate DEBUG- Reading to [java.lang.String] as "application/json;charset=utf-8"
17:06:27.452 [main] c.j.j.internal.path.CompiledPath DEBUG- Evaluating path: $['datetime']
17:06:27.452 [main] c.operator_6_time.Example14_52 INFO - now: 2023-07-29T17:06:27.339847+09:00, elapsed time: 195
17:06:27.453 [main] o.s.web.client.RestTemplate DEBUG- HTTP GET http://worldtimeapi.org:80/api/timezone/Asia/Seoul
17:06:27.453 [main] o.s.web.client.RestTemplate DEBUG- Accept=[text/plain, application/json, application/*+json, */*]
17:06:27.642 [main] o.s.web.client.RestTemplate DEBUG- Response 200 OK
17:06:27.643 [main] o.s.web.client.RestTemplate DEBUG- Reading to [java.lang.String] as "application/json;charset=utf-8"
17:06:27.646 [main] c.j.j.internal.path.CompiledPath DEBUG- Evaluating path: $['datetime']
17:06:27.646 [main] c.operator_6_time.Example14_52 INFO - now: 2023-07-29T17:06:27.535231+09:00, elapsed time: 194
17:06:27.647 [main] c.operator_6_time.Example14_52 INFO - # onComplete

http://worldtimeapi.org/api/timezone/Asia/Seoul 에 https 요청을 반복적으로 전송하고 응답 시간을 측정하는 예제 코드 입니다

예제 코드에서는 repeat() Operator 를 이용해 구독을 4회 반복해서 HTTP request 를 반복적으로 전송하고 있는데,

최초 구독 + repeat() 의 파라미터 숫자만큼, (총 5번)의 HTTP request 를 전송합니다

 

17:06:26.870 [main] c.operator_6_time.Example14_52 INFO - now: 2023-07-29T17:06:26.702709+09:00, elapsed time: 536
...
17:06:27.066 [main] c.operator_6_time.Example14_52 INFO - now: 2023-07-29T17:06:26.956999+09:00, elapsed time: 242
...
17:06:27.258 [main] c.operator_6_time.Example14_52 INFO - now: 2023-07-29T17:06:27.146173+09:00, elapsed time: 191
...
17:06:27.452 [main] c.operator_6_time.Example14_52 INFO - now: 2023-07-29T17:06:27.339847+09:00, elapsed time: 195
...
17:06:27.646 [main] c.operator_6_time.Example14_52 INFO - now: 2023-07-29T17:06:27.535231+09:00, elapsed time: 194

 

저자님께서는 설명을 생략하셨는데요.

restTemplate 은 동기(sync) 방식 입니다. 그리고, Mono.defer 를 사용하여, 구독 시에 호출되도록 지연시켰습니다

Mono.defer(() -> Mono.just(restTemplate.exchange(worldTimeUri, ~~ 

 

 

http://worldtimeapi.org/api/timezone/Asia/Seoul