指标可能会欺骗您：测量连接池环境中的执行时间

测量外部服务请求的执行时间对于性能监控和优化至关重要。然而，当这些外部服务的连接池化时，你可能会无意中测量不仅仅是要求时间。具体来说，如果要求花费的时间太长，你耗尽了可用的连接，你的自定义逻辑可能会开始包括从池中获得连接的等待时间。这可能会导致误导性指标，误解系统的性能。让我们深入研究一下这是如何发生的，以及如何避免被我们自己的指标愚弄。

陷阱：指标中包含等待时间

当池中的所有连接都在使用时，必须等待额外的请求，直到连接可用。如果不单独测量实际请求时间，此等待时间可能会扭曲您的指标。

场景：连接不足

1. 初始状态：您的连接池有固定数量的连接，并且都在使用中。
2. 新请求：收到新请求，但必须等待连接可用。
3. 等待时间：请求等待（可能等待很长时间），直到连接到空闲。
4. 请求时间：一旦获得连接，就会发出实际请求。

如果您的自定义逻辑测量从请求到收到响应的总时间，您将包括等待时间和请求时间。

实际例子：使用 apache httpclient 5 重现 spring boot 中的问题

为了解释如何在连接池环境中被自己的指标欺骗，让我们来看看一个使用 spring boot 和 apache httpclient 5 实际示例。我们将设置一个简单的设置 spring boot 该应用程序向外部发出应用程序 http 请求服务，测量这些请求的执行时间，并演示连接池耗尽如何导致误导性指标。

我们将使用它来模拟外部服务的延迟 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
</pid>

$ 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 要求生命周期的各个方面，包括连接获取、数据传输和响应处理。这确保了测量结果的准确性和与客户实际性能的一致性。

以上是指标可能会欺骗您：测量连接池环境中执行时间的详细信息，请更多地关注图灵教育的其他相关文章！