不喜歡看文字可以跳轉(zhuǎn) B站視頻
服務(wù)A請求服務(wù)B接口魄健，服務(wù)B響應(yīng)時間突然增加插勤，服務(wù)A的http超時時間設(shè)置了5000ms。但是在觀察日志時發(fā)現(xiàn)了大于50s的日志析恋，如圖：
image.png
日志在log/spring.log中助隧。
因為設(shè)置了超時時間5s，但是現(xiàn)在50s并村，剩下的45s是發(fā)生了什么呢？
復(fù)現(xiàn)步驟：
yum install -y httpd
ab -c 20 -n 100 http://localhost:8080/trigger
服務(wù)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 "";
}
服務(wù)B代碼如下：
@GetMapping("bar")
public String bar() {
try {
TimeUnit.SECONDS.sleep(10L);
} catch (InterruptedException e) {
e.printStackTrace();
}
return "bar";
}
解答：
時間不知道去哪了？想知道進(jìn)程在做什么丸边？最適合看線程棧外潜。
NOTE：還應(yīng)該查看是不是存在long gc的情況，jstat可以查看处窥，本case忽略這部分操作。
jstack -l pid > jsk.log谒麦，然后打開仔細(xì)查看哆致，尤其是BLOCKED，WAITING摊阀，TIMED_WAITING這幾種狀態(tài)。
NOTE：本case為了模擬超時情況臣咖，sleep了下漱牵，線程是TIMEED_WAITING狀態(tài)，所以忽略這部分
如果線程比較多看花眼了刁赦，可以使用fastthread進(jìn)行分析。
image.png
點進(jìn)去可以看到好多http線程都在等待丸升，如圖：
image.png
看到是從連接池拿連接宦焦，一般這種情況發(fā)生要么就是連接池設(shè)置過小，要么就是響應(yīng)時間太慢酝豪。響應(yīng)時間慢就要考慮會不會發(fā)生級聯(lián)問題精堕。
