指標可能會欺騙您：測量連接池環境中的執行時間

測量外部服務請求的執行時間對於效能監控和最佳化至關重要。但是，當對這些外部服務的連線進行池化時，您可能會無意中測量的不僅僅是請求時間。具體來說，如果請求花費的時間太長並且您耗盡了可用連接，則您的自訂邏輯可能會開始包括從池中獲取連接的等待時間。這可能會導致誤導性指標，導致您誤解系統的效能。讓我們深入研究一下這是如何發生的，以及如何避免被自己的指標愚弄。

陷阱：在指標中包含等待時間

當池中的所有連線都在使用時，其他請求必須等待，直到連線可用。如果不與實際請求時間分開衡量，此等待時間可能會扭曲您的指標。

場景：連線不足

1. 初始狀態：你的連接池有固定數量的連接，所有連接都在使用中。
2. 新請求：收到新請求，但必須等待連線可用。
3. 等待時間：請求等待（可能等待很長一段時間）直到連線空閒。
4. 請求時間：一旦獲得連接，就會發出實際請求。

如果您的自訂邏輯測量從發出請求到收到回應的總時間，則您將包括等待時間和請求時間。

實際範例：使用 Apache HttpClient 5 重現 Spring Boot 中的問題

為了說明如何在連線池環境中被自己的指標所欺騙，讓我們來看一個使用 Spring Boot 和 Apache HttpClient 5 的實際範例。我們將設定一個簡單的 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);
    }
}

在上面的程式碼中，我們建立了一個請求攔截器 (ClientHttpRequestInterceptor) 來測量我們認為對 httpbin 支援的外部服務的請求的執行時間。

我們也明確地將池設定為非常小的 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 檔案並查看火焰圖，我們可以看到大部分執行時間都花在了 HTTP 用戶端上。客戶端的執行時間分為等待我們的外部服務回應和等待從池中取得連線。

這解釋了為什麼我們看到的回應時間是我們為外部伺服器設定的預期固定延遲 2 秒的兩倍。我們配置了 2 個連接的池。然而，在我們的測試中，我們執行 4 個並發請求。因此，只有前 2 個請求將在 2 秒的預期時間內滿足。後續請求將必須等待池釋放連接，從而增加觀察到的回應時間。

如果我們再次查看火焰圖，我們還可以發現為什麼ClientHttpRequestInterceptor 測量的時間並不反映外部伺服器回應的時間，而是反映從池中獲取連接所需的時間加上它所花費的時間向外部伺服器執行實際請求。我們的攔截器實際上包裝了一個堆疊跟踪，最終調用池管理器來獲取連接：PoolingHttpClientConnectionManager

監控任何 HTTP 用戶端的回應時間最好使用其內建指標來完成，因為這些指標是專門為捕獲精確的計時資訊而設計的。它們負責 HTTP 請求生命週期的各個方面，包括連接獲取、資料傳輸和回應處理。這確保了測量結果準確且與客戶的實際表現一致。

以上是指標可能會欺騙您：測量連接池環境中的執行時間的詳細內容。更多資訊請關注PHP中文網其他相關文章！