メトリクスはあなたを騙す可能性があります: 接続プール環境での実行時間の測定

外部サービスへのリクエストの実行時間を測定することは、パフォーマンスの監視と最適化にとって重要です。ただし、これらの外部サービスへの接続がプールされている場合、誤ってリクエスト時間以上のものを測定してしまう可能性があります。具体的には、リクエストに時間がかかりすぎて利用可能な接続がなくなった場合、カスタム ロジックにプールから接続を取得するための待機時間が含まれるようになる可能性があります。これにより、誤解を招くメトリクスが生成され、システムのパフォーマンスを誤解する可能性があります。これがどのようにして起こるのか、また独自の指標に騙されないようにする方法を詳しく見てみましょう。

落とし穴: メトリクスに待ち時間を含める

プール内のすべての接続が使用中の場合、追加のリクエストは接続が使用可能になるまで待機する必要があります。この待機時間は、実際のリクエスト時間とは別に測定しないと、メトリクスを歪める可能性があります。

シナリオ: 接続が不足している

1. 初期状態: 接続プールには固定数の接続があり、すべて使用中です。
2. 新しいリクエスト: 新しいリクエストが届きましたが、接続が利用可能になるまで待つ必要があります。
3. 待機時間: リクエストは、接続が空くまで (場合によってはかなりの時間) 待機します。
4. リクエスト時間: 接続が取得されると、実際のリクエストが行われます。

カスタム ロジックでリクエストが行われてから応答を受信するまでの合計時間を測定する場合、待機時間とリクエスト時間の両方が含まれます。

実践例: Apache HttpClient 5 を使用した Spring Boot の問題の再現

接続プール環境で独自のメトリクスにどのように騙されるかを説明するために、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 秒の遅延が発生することがわかります。

プロファイルを作成する時間

プロファイリングは、パフォーマンスのボトルネックを特定し、メモリ リークなどの隠れた問題を明らかにし、アプリケーションがシステム リソースをどのように使用しているかを示すため、コードの奇妙な動作が発生した場合に不可欠です。

今回は、腹筋負荷テストを実施しながら、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 ファイルを開いてフレームグラフを見ると、実行時間のほとんどが HTTP クライアントによって費やされていることがわかります。クライアントの実行時間は、外部サービスが応答するのを待つ時間と、プールから接続を取得するのを待つ時間に分けられます。

これにより、応答時間が、外部サーバーに設定した予想される固定遅延の 2 秒の 2 倍である理由が説明されます。 2 つの接続のプールを構成しました。ただし、このテストでは 4 つのリクエストを同時に実行しています。したがって、最初の 2 つのリクエストのみが 2 秒の予想時間内に処理されます。後続のリクエストは、プールが接続を解放するまで待機する必要があるため、観測される応答時間は長くなります。

もう一度フレームグラフを見ると、ClientHttpRequestInterceptor によって測定された時間が、外部サーバーの応答にかかる時間ではなく、プールからの接続を取得するのにかかる時間とそれにかかる時間を反映している理由がわかります。外部サーバーへの実際のリクエストを実行します。私たちのインターセプターは実際には、接続を取得するためにプール マネージャーを呼び出すことになるスタック トレースをラップしています: PoolingHttpClientConnectionManager

HTTP クライアントの応答時間を監視するには、組み込みメトリックを使用するのが最適です。これらのメトリックは、正確なタイミング情報を取得するように特別に設計されているためです。これらは、接続の取得、データ送信、応答処理など、HTTP リクエストのライフサイクルのあらゆる側面を考慮します。これにより、測定が正確であり、クライアントの実際のパフォーマンスと一致していることが保証されます。

以上がメトリクスはあなたを騙す可能性があります: 接続プール環境での実行時間の測定の詳細内容です。詳細については、PHP 中国語 Web サイトの他の関連記事を参照してください。