不喜欢看文字可以跳转 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
看到是从连接池拿连接，一般这种情况发生要么就是连接池设置过小，要么就是响应时间太慢。响应时间慢就要考虑会不会发生级联问题。
