响应时间远大于超时时间

不喜欢看文字可以跳转 B站视频

服务A请求服务B接口，服务B响应时间突然增加，服务A的http超时时间设置了5000ms。但是在观察日志时发现了大于50s的日志，如图：

image.png

日志在log/spring.log中。

因为设置了超时时间5s，但是现在50s，剩下的45s是发生了什么呢？

复现步骤：
yum install -y httpd
ab -c 20 -n 100 http://localhost:8080/trigger

服务A代码如下：

    @Bean
    public RestTemplate restTemplate() {
        Registry<ConnectionSocketFactory> registry = RegistryBuilder.<ConnectionSocketFactory>create()
                .register("http", PlainConnectionSocketFactory.getSocketFactory())
                .build();
        PoolingHttpClientConnectionManager connectionManager = new PoolingHttpClientConnectionManager(registry);
        connectionManager.setMaxTotal(10);
        RequestConfig requestConfig = RequestConfig.custom()
                .setSocketTimeout(5000)
                .setConnectTimeout(200)
                .build();
        CloseableHttpClient httpClient = HttpClientBuilder.create()
                .setDefaultRequestConfig(requestConfig)
                .setConnectionManager(connectionManager)
                .build();

        HttpComponentsClientHttpRequestFactory requestFactory = new HttpComponentsClientHttpRequestFactory(httpClient);
        return new RestTemplateBuilder().requestFactory(requestFactory).build();
    }

    @GetMapping("trigger")
    public String trigger() {
        long begin = System.currentTimeMillis();
        try {
            restTemplate.getForEntity("http://localhost:8080/bar", String.class);
        } catch (Exception e) {
        }
        long end = System.currentTimeMillis();
        LOGGER.info("http call cost:{}", (end - begin));
        return "";
    }

服务B代码如下：

    @GetMapping("bar")
    public String bar() {
        try {
            TimeUnit.SECONDS.sleep(10L);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        return "bar";
    }

解答：
时间不知道去哪了？想知道进程在做什么？最适合看线程栈。
NOTE：还应该查看是不是存在long gc的情况，jstat可以查看，本case忽略这部分操作。

jstack -l pid > jsk.log，然后打开仔细查看，尤其是BLOCKED，WAITING，TIMED_WAITING这几种状态。
NOTE：本case为了模拟超时情况，sleep了下，线程是TIMEED_WAITING状态，所以忽略这部分
如果线程比较多看花眼了，可以使用fastthread进行分析。

image.png

点进去可以看到好多http线程都在等待，如图：

image.png

看到是从连接池拿连接，一般这种情况发生要么就是连接池设置过小，要么就是响应时间太慢。响应时间慢就要考虑会不会发生级联问题。