一、起源
23年元旦期间,大家都沉浸在一片祥和的过节气氛当中。
“滴滴滴”,这头同事的电话响起,具体说些什么我也没太在意,但见同事接完电话之后展现出了一副懊恼夹杂着些许不耐烦的表情。
我不解问道:“怎么了?”
同事:“刚刚运营反馈系统开始刷白屏了,所有的请求一直处于pending状态。”
此刻我的大脑开始飞速旋转,界面白屏?前端是不是有一个初始化的请求?这个初始化的请求有问题导致前端没有往下运行并渲染页面?
我:“已经登陆进系统的用户可以正常使用吗?”
同事:“也不可以”。
那就不是初始化请求失败的问题了。
再往下分析,应用进程应该没有宕机,否则接口会快速响应404。
我:“所有接口都阻塞住了还是单个接口的问题,最近有没有项目发版?”
同事:“运营反馈是所有接口都有阻塞情况,这段时间一直没有发版”。
那就怪了,近期没有发版,而且所有接口均有问题。
到此,基本可以判定出,这个问题与业务无关,而是类似基础设施出现问题导致了,比如网络问题、Java GC问题、线程池线程短缺出现业务饥饿问题等。
这种问题勾起了我的兴趣,我决定自己上手问题,开始排查…
二、表象
打开系统,发现浏览器发出的接口确实都处于“pending”状态。(Ps:pending是浏览器发出请求之后的一种状态,代表该请求还未得到服务器响应,如果接口RT延迟高,你就有可能经常看到这种状态);
接口处于pending状态,我在本地使用telnet ip port
命令连接应用服务器端口也是正常的,到此说明网络与应用进程都是完好的。
三、排查
打开监控系统查看了Java GC耗时、次数两项指标,发现和平时也没什么不一样。
查看了系统调用量发现与往常相似,没有什么流量突刺。
同事查看了那段时间的系统日志也未发现明显的错误。
我手里的鼠标一直向下滑动着,我和同事紧张的看着电脑,紧盯着各项指标,希望能看出些端倪,并能以此为突破口。
果然,还是看到了…
下图是近几天的TCP连接数曲线图:
TCP涨势图.jpeg
发现TCP连接一直处于只涨不降的趋势(除了中间几次的人为重启机器)。
我进入服务器,熟练的敲起Linux命令:
[root] $ **netstat -na | grep '8089' | awk '/^tcp/ {++S[$NF]} END {for(a in S) print a, S[a]}'
LISTEN 8
CLOSE_WAIT 35
ESTABLISHED 108
SYN_SENT 1
TIME_WAIT 9**
[root] $ netstat -ntp | grep 'CLOSE_WAIT'
tcp 1 0 本机ip:端口 nginx机器 CLOSE_WAIT pid/java
....
观察了十分钟,发现CLOSE_WAT
状态的TCP连接数一直处于增长的状态。并且观察到所有的CLOSE_WAIT状态的TCP都是与Nginx建立的,问了运维同学,这台Nginx是这台后端应用的代理。
同事:“啊,原来是TCP连接数捣鬼,一直上涨但不释放”。
这一点和浏览器发出的接口一直处于Pending
状态刚好吻合起来了。一定是代码出现了什么问题,导致接口延迟上升,所有的HTTP请求映射到底层就是TCP连接,应用服务器一直没有返回内容,那么TCP自然也不会释放了(这里我们先不考虑现代HTTP协议的KeepAlive机制)。
只见同事为了止血抓紧去重启机器了,好让这些TCP连接被强制关闭。
但我还有一点疑问,TCP未能及时释放确实有问题不假,但即便是这样,区区500个TCP连接,也不至于达到操作系统的阈值,要知道操作系统对端口的限制理论上可以达到65535个。
那一定是有一个短板的中间件因达到了阈值而限制了整个系统,很快我便想到了Tomcat,因为Tomcat一定是每个业务接口都绕不过的中间件。
虽然机器已经重启了,但我们有服务治理相关的平台可以调出任意一个时间点的线程状态,不看不知道,一看吓一跳,所有以“http-nio-xxx”为前缀的线程全部阻塞在方法:SocketInputStream.read0
方法中。熟悉这个前缀线程的人都知道,这是Tomcat线程池。
我:”查一下日志,看看接口AOP有没有捕捉到请求信息?“
同事:“捕捉到了”
我:“随机抽取几个请求,看看接口AOP是否捕捉到了接口响应信息”
同事抓紧去查了,不一会儿惊讶的说道:“老朱,还真有很多请求接口响应AOP没有捕获到,那就是说这些请求一直没有处理完”。
同事又说道:“老朱,这个项目比较特殊,项目中所有的接口基本只做了透传的事情,项目只是做简单的数据加工,然后请求其他系统,最后针对结果集再进行过滤、转换返回给前端”
我:“啊,原来是这样,目前使用的HTTP客户端是什么?”
同事:“Apache HttpClient”
我:“Apache HttpClient?三个超时时间都设置了吧?“
同事:“嗯,都设置了,connectTimeout、socketTimeout、connectionRequestTimeout都根据项目的性质调试过了,并且数据流也都妥善处理了”
我有些不解,所有的超时时间都设置好了,那为什么还会有大量的Tomcat线程阻塞在SocketInputstream.read0
方法中呢,最终导致TCP持续飙高。
我和同事都陷入了困境,进入两难处境,不知道如何继续排查,机器重启确实可以强制释放TCP但是这方法治标不治本。
同事:“啊,这,怎么会这样”
我:“怎么了?!吞吞吐吐”
同事:“我记得之前明明在这些应用里都加了接口AOP日志,刚刚看到我们项目有日志,但是其他系统中居然没有日志…
至此我有个大胆的猜测,请求进入项目之后,项目加工请求并转发给其他项目,但转发给系统项目的这段网络出现了什么问题(因为其他系统并未收到请求),又因为种种原因导致超时时间并未生效,慢慢的项目中所有Tomcat线程都阻塞在了SocketInputstream
中的read0
方法中,最后Tomcat无空闲线程可去处理用户提交的新的请求。
但是什么情况下Apache HttpClient中的超时时间不生效呢?
直到我看到了一篇JDK官网说明:
Bug ID: JDK-8172578 SocketInputStream.socketRead0 can hang even with soTimeout set
SocketInputStream.socketRead0 can hang even with soTimeout set
在第二篇文章中有详细描述了SocketTimeOut参数失效的原因,大致意思是:因为OS select方法存在虚假唤醒的问题导致线程提前进行读取,但又因为并没有实际数据因此造成了读取阻塞。
而我们的JDK版本是1.8.0_91,也就是低于JDK修复版本,当OS发出虚假唤醒之后,导致Java线程进入阻塞读取状态,最终导致socketTimeout失效。
事情到这就解释的通了,我再来根据现象与各项指标结合起来从头到尾的阐述一波。
应用拓扑图.png
这里先祭出项目的拓扑图。
应用A是这次案发地点,应用A的大多数功能只是做请求透传工作,将用户请求的参数做过滤、筛选、添油加醋发送给应用B。
根据上述的拓扑性质,以应用A为中心会有两段请求,这里标识为A段、B段。
案发时间前几个小时,起初系统稳如老狗。应用A稳定的处理着Nginx转发来的前端请求,并包装发送给应用B,然后将应用B返回来的数据进行筛选、处理然后返回给用户。
然而好景不长,B段出现了一些网络丢包、抖动等情况变得开始不稳定了,搭配上JDK8U152版本之前可能会受到操作系统的select虚假唤醒的情况,慢慢的Tomcat很多线程都阻塞在了SocketInputstream
的read0
方法上,这一点和之前看到的线程Dump信息一致。
看了眼项目对Tomcat的线程数配置:server.tomcat.max-threads=**400**
,而线程Dump出的信息中刚好有400个线程阻塞在了read0
方法中。
嗯,没错,就是这样,最后Tomcat成为了整个项目的瓶颈。
四、解决
知道了,问题就非常方便解决了,我主要采取了三个措施:
- 将项目中使用的BIO HttpClient化成NIO的方式:HttpAsyncClient
- 升级JDK为JDK8u152版本
- 添加耗时兜底方案,若超过SocketTimeout时间,应用A请求B应用还未结束,则手动关闭TCP连接,Tomcat主线程继续向下运行
其中第二点不用说,我通过一段伪代码来说明一下1和3.
public static String getHttpClientResult(CloseableHttpAsyncClient asyncHttpClient, HttpRequestBase httpMethod) throws IOException {
String content = "";
// TCP强制断开标志
boolean abortFlag = true;
HttpResponse response = null;
// 执行请求
Future<HttpResponse> httpResponseFuture = asyncHttpClient.execute(httpMethod, null);
try {
httpResponse = httpResponseFuture.get(SOCKET_TIMEOUT, TimeUnit.MILLISECONDS);
abortFlag = false;
// 获取返回结果
if (httpResponse.getEntity() != null) {
content = EntityUtils.toString(httpResponse.getEntity(), ENCODING);
}
} catch (InterruptedException e) {
// 线程被打断,重新设置标志并且向下运行
Thread.currentThread().interrupt();
} catch (ExecutionException e) {
// http执行异常,包括readTimeOut、connectTimeOut
log.error("当前线程:{},请求异常,发送TCP RST包强制断开", Thread.currentThread().getName());
} catch (TimeoutException e) {
/**
* future get 超时 兜底方案,避免主线程阻塞在read方法中
* @see java.net.SocketInputStream#socketRead0(java.io.FileDescriptor, byte[], int, int, int)
* 若超时则发送RST包以强制连接双方断开TCP
*/
log.error("当前线程:{},超时:{}秒,仍未获取到数据,发送RST包", Thread.currentThread().getName(), SOCKET_TIMEOUT);
} finally {
if (abortFlag) {
httpMethod.abort();
}
// 释放资源
if (!Objects.isNull(httpResponse)
&& !Objects.isNull(httpResponse.getEntity())
&& !Objects.isNull(httpResponse.getEntity().getContent())) {
httpResponse.getEntity().getContent().close();
}
}
return abortFlag ? null : content;
}
代码优化完毕,赶紧发版,目前我的这位同事在也没有被运维‘骚扰’过了,目前TCP升降趋势稳定喜人 ,如下:
修复后的TCP涨势图.jpeg文章来源:https://www.toymoban.com/news/detail-448631.html
文章来源地址https://www.toymoban.com/news/detail-448631.html
到了这里,关于TCP连接不释放,应用产生大量CLOSE_WAIT状态TCP的文章就介绍完了。如果您还想了解更多内容,请在右上角搜索TOY模板网以前的文章或继续浏览下面的相关文章,希望大家以后多多支持TOY模板网!