天津网站开发学校百度软件
一、起源
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、connectTimeOutlog.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