메트릭이 당신을 속일 수 있습니다: 연결 풀링 환경에서 실행 시간 측정

외부 서비스에 대한 요청 실행 시간을 측정하는 것은 성능 모니터링 및 최적화에 매우 중요합니다. 그러나 이러한 외부 서비스에 대한 연결이 풀링되면 실수로 요청 시간 이상의 것을 측정하게 될 수 있습니다. 특히, 요청이 너무 오래 걸리고 사용 가능한 연결이 부족한 경우 풀에서 연결을 얻기 위한 대기 시간을 포함하여 사용자 지정 논리가 시작될 수 있습니다. 이로 인해 오해의 소지가 있는 측정항목이 발생하여 시스템 성능을 잘못 해석하게 될 수 있습니다. 어떻게 이런 일이 발생하는지, 그리고 자신의 측정항목에 속지 않는 방법을 살펴보겠습니다.

함정: 측정항목에 대기 시간 포함

풀의 모든 연결이 사용 중이면 연결을 사용할 수 있을 때까지 추가 요청을 기다려야 합니다. 이 대기 시간은 실제 요청 시간과 별도로 측정하지 않으면 측정항목이 왜곡될 수 있습니다.

시나리오: 연결 부족

1. 초기 상태: 연결 풀에는 고정된 수의 연결이 있으며 모두 사용 중입니다.
2. 새 요청: 새 요청이 들어오지만 연결이 가능해질 때까지 기다려야 합니다.
3. 대기 시간: 요청은 연결이 해제될 때까지(상당한 시간 동안) 기다립니다.
4. 요청 시간: 연결이 이루어지면 실제 요청이 이루어집니다.

사용자 정의 로직이 요청이 이루어진 시점부터 응답을 수신할 때까지의 총 시간을 측정하는 경우 대기 시간과 요청 시간을 모두 포함하게 됩니다.

실제 예: Apache HttpClient 5를 사용하여 Spring 부팅 문제 재현

연결 풀 환경에서 자신의 측정항목에 어떻게 속을 수 있는지 설명하기 위해 Spring Boot와 Apache HttpClient 5를 사용하는 실제 예제를 살펴보겠습니다. HTTP 요청을 보내는 간단한 Spring Boot 애플리케이션을 설정하겠습니다. 외부 서비스를 사용하여 이러한 요청의 실행 시간을 측정하고 연결 풀 고갈이 어떻게 잘못된 측정항목으로 이어질 수 있는지 보여줍니다.

외부 서비스의 지연을 시뮬레이션하기 위해 httpbin Docker 이미지를 사용하겠습니다. Httpbin은 요청에 인위적인 지연을 만드는 데 사용할 수 있는 사용하기 쉬운 HTTP 요청 및 응답 서비스를 제공합니다.

@SpringBootApplication
@RestController
public class Server {

    public static void main(String... args) {
        SpringApplication.run(Server.class, args);
    }

    class TimeClientHttpRequestInterceptor implements ClientHttpRequestInterceptor {

        @Override
        public ClientHttpResponse intercept(HttpRequest request, byte[] body, ClientHttpRequestExecution execution)
                throws IOException {
            var t0 = System.currentTimeMillis();
            try {
                return execution.execute(request, body);
            } finally {
                System.out.println("Request took: " + (System.currentTimeMillis() - t0) + "ms");
            }
        }
    }

    @Bean
    public RestClient restClient() {
        var connectionManager = new PoolingHttpClientConnectionManager();
        connectionManager.setMaxTotal(2); // Max number of connections in the pool
        connectionManager.setDefaultMaxPerRoute(2); // Max number of connections per route

        return RestClient.builder()//
                .requestFactory(new HttpComponentsClientHttpRequestFactory(
                        HttpClients.custom().setConnectionManager(connectionManager).build()))
                .baseUrl("http://localhost:9091")//
                .requestInterceptor(new TimeClientHttpRequestInterceptor()).build();
    }

    @GetMapping("/")
    String hello() {
        return restClient().get().uri("/delay/2").retrieve().body(String.class);
    }
}

위 코드에서는 httpbin이 지원하는 외부 서비스에 대한 요청의 실행 시간을 측정하기 위해 요청 인터셉터(ClientHttpRequestInterceptor)를 만들었습니다.

또한 문제를 쉽게 재현할 수 있도록 풀을 매우 작은 크기인 2개의 연결로 명시적으로 설정했습니다.

이제 httpbin을 시작하고 spring boot 앱을 실행하고 ab를 사용하여 간단한 테스트를 수행하면 됩니다

$ docker run -p 9091:80 kennethreitz/httpbin

ab -n 10 -c 4 http://localhost:8080/
...
Percentage of the requests served within a certain time (ms)
  50%   4049
  66%   4054
  75%   4055
  80%   4055
  90%   4057
  95%   4057
  98%   4057
  99%   4057
 100%   4057 (longest request)

Request took: 2021ms
Request took: 2016ms
Request took: 2022ms
Request took: 4040ms
Request took: 4047ms
Request took: 4030ms
Request took: 4037ms
Request took: 4043ms
Request took: 4050ms
Request took: 4034ms

수치를 보면 외부 서버에 대해 인위적으로 2초의 지연을 설정했음에도 불구하고 실제로 대부분의 요청에 대해 4초의 지연이 발생하고 있음을 알 수 있습니다. 또한 첫 번째 요청만 구성된 지연 2초를 준수하고 후속 요청에서는 4초 지연이 발생한다는 것을 알 수 있습니다.

프로필 작성 시간

프로파일링은 성능 병목 현상을 식별하고, 메모리 누수와 같은 숨겨진 문제를 찾아내고, 애플리케이션이 시스템 리소스를 사용하는 방식을 보여주기 때문에 이상한 코드 동작이 발생할 때 필수적입니다.

이번에는 Ab 부하 테스트를 진행하면서 JFR을 사용하여 실행 중인 앱을 프로파일링해 보겠습니다.

$ jcmd <pid> JFR.start name=app-profile  duration=60s filename=app-profile-$(date +%FT%H-%M-%S).jfr

$ ab -n 50 -c 4 http://localhost:8080/
...
Percentage of the requests served within a certain time (ms)
  50%   4043
  66%   4051
  75%   4057
  80%   4060
  90%   4066
  95%   4068
  98%   4077
  99%   4077
 100%   4077 (longest request)

JFR 파일을 열고 Flamegraph를 보면 대부분의 실행 시간이 HTTP 클라이언트에서 소비되는 것을 알 수 있습니다. 클라이언트의 실행 시간은 외부 서비스의 응답을 기다리는 것과 풀에서 연결을 기다리는 것으로 나뉩니다.

이는 우리가 보는 응답 시간이 외부 서버에 대해 설정한 예상 고정 지연 2초의 두 배인 이유를 설명합니다. 우리는 2개의 연결 풀을 구성했습니다. 그러나 테스트에서는 4개의 동시 요청을 수행하고 있습니다. 따라서 처음 2개의 요청만 2초라는 예상 시간 내에 처리됩니다. 후속 요청은 풀이 연결을 해제할 때까지 기다려야 하므로 관찰된 응답 시간이 늘어납니다.

플레임 그래프를 다시 보면 ClientHttpRequestInterceptor가 측정한 시간이 외부 서버가 응답하는 데 걸리는 시간이 아니라 풀에서 연결을 얻는 데 걸리는 시간과 걸리는 시간을 반영하는 이유를 알 수 있습니다. 외부 서버에 대한 실제 요청을 수행합니다. 인터셉터는 실제로 연결을 얻기 위해 풀 관리자를 호출하는 스택 추적을 래핑하고 있습니다. PoolingHttpClientConnectionManager

HTTP 클라이언트의 응답 시간을 모니터링하는 것은 내장된 측정항목을 사용하는 것이 가장 좋습니다. 이러한 측정항목은 정확한 타이밍 정보를 캡처하도록 특별히 설계되었기 때문입니다. 이는 연결 획득, 데이터 전송 및 응답 처리를 포함하여 HTTP 요청 수명주기의 모든 측면을 설명합니다. 이를 통해 측정값이 정확하고 클라이언트의 실제 성능과 일관되게 유지됩니다.

위 내용은 메트릭이 당신을 속일 수 있습니다: 연결 풀링 환경에서 실행 시간 측정의 상세 내용입니다. 자세한 내용은 PHP 중국어 웹사이트의 기타 관련 기사를 참조하세요!