【全网首发】记一次socket read导致业务线程阻塞的案例分析原创
问题描述
TAM同学反馈某个应用阻塞了：访问应用健康检查URL也访问不通，目前排查了EDAS、SLB及WAF等云产品均没有发现明显问题。
我登录到ECS，curl健康检查URL，确实已经访问不通了（建立连接超时）。
基本情况
流量是从互联网终端请求过来的，最终经过云产品SLB负载均衡到该应用，该应用使用的是taobao-tomcat-7.0.59，监听端口是8080。
分析过程
系统负载太高了？
首先怀疑是不是因为系统负载太高了，导致应用无法处理请求，所以先检查一下系统指标。
top
对于4c8g的配置来说，CPU、内存、Load等指标都很低。
jstat
GC情况也算正常，不像是系统负载过高导致的问题，需要换个思路了。
网络连接有问题？
从curl结果看是无法建立网络连接，怀疑什么就检查什么，看看网络连接情况吧。
netstat
netstat -ant | grep 8080 | awk '/^tcp/{++state[$NF]};END{for(key in state) print key,state[key]}'
netstat多执行几次，发现CLOSE_WAIT状态的连接一直存在，按道理CLOSE_WAIT状态的连接应该很快就会消失才对；而SYNC_REVC状态也是一种不经常见到的状态，难道真的无法建立连接了？
ss
ss -lnt | grep 8080
从图中看我们的全连接队列最大长度是128，当前全连接数量是129？多执行几次依然是这种状态，全连接队列满了。
netstat -s
netstat -s | grep -E 'overflowed|SYNs'
从图中看有连接不断的连过来，无论是握手成功还是半握手失败的数量都在不断增加。
线程阻塞？
对于网络应用程序来说，通常的线程模型是：独立的线程accept网络连接，拿到连接后丢到另外的线程做报文解析、反序列化、业务处理等，是不是tomcat业务线程阻塞住了？
jstack
通过分析jstack文件，发现tomcat线程都处在java.net.SocketInputStream.socketRead0的地方。
vmtool --action getInstances --className java.lang.Thread --limit 700 --express 'instances.{? #this.getName().equals("http-bio-8080-exec-6")}.{#this.getStackTrace()}'
从jstack线程栈来看，这么多的tomcat业务线程都处于同一个代码逻辑，已经很不正常，通过jstack信息怀疑此时tomcat线程池已经满了？
tomcat thread pool
一路代码跟下去，org.apache.coyote.http11.Http11Protocol类是我们此次关注点，该类线程池配置：
线程池配置的最大线程数
vmtool --action getInstances --className org.apache.coyote.http11.Http11Protocol --express 'instances[0].getExecutor().getMaximumPoolSize()'
可以看到配置的最大线程数是：360
线程池运行状态
vmtool --action getInstances --className org.apache.coyote.http11.Http11Protocol --express 'instances[0].getExecutor().toString()'
从图中看pool size=360,active threads=360,queued tasks=40,说明tomcat线程池已经用满了，到这里curl无法建立连接的原因算是定位到了。
接下来我们根据线程栈一步步排查吧（很多问题不了解业务并不影响问题排查，但是了解业务的话会更快的分析定位问题）。
jad
反编译业务Controller，看看从具体业务逻辑中是否能够找到线索。
jad 类的全局限定名
一眼看去这块代码存在几个很明显的问题：
- Controller每接收到一个请求都新创建一个DefaultHttpClient对象是不合理的，因为DefaultHttpClient本身就是连接池的概念，全局使用一个就可以了；
- 由于DefaultHttpClient是方法局部变量，当方法执行完后该对象在某个时候就会被垃圾回收掉，该对象持有的连接能保证安全关闭吗？
- 该DefaultHttpClient对象没有设置任何socket相关的参数，没有数据返回的情况下，socket.read会不会一直阻塞着？
sc
sc -d org.apache.http.impl.client.DefaultHttpClient
看了下lib目录下有比较新的版本，似乎用新版本更好一些。
vmtool HttpGet
vmtool --action getInstances --className org.apache.http.client.methods.HttpGet --express 'instances[0]'
从图中可以看出请求的url，接下来看一下与这个url的建立的网络连接情况：
netstat -ant | grep 10.3.50.152 | awk '/^tcp/{++state[$NF]};END{for(key in state) print key,state[key]}'
从图中可以看出有360个网络连接，跟tomcat线程池中线程个数基本一致，也就是说tomat线程池中的线程都被阻塞了。
vmtool Socket
我们跟着org.apache.http.impl.client.DefaultHttpClient对象看看Socket的配置信息。
DefaultHttpClient
vmtool --action getInstances --className org.apache.http.impl.client.DefaultHttpClient --express 'instances[0]'
socket是在什么时候创建的？异常socket的创建时间是否有规律性？我们接着一层层找下去
poolEntry
vmtool --action getInstances --className org.apache.http.impl.client.DefaultHttpClient --express 'instances.{? #this.connManager.conn.poolEntry.conn.socket.impl.localport=55084}.{#this.connManager.conn.poolEntry}' -x 2
批量查看Socket创建时间
vmtool -c 5e7cfcd6 --action getInstances --className org.apache.http.impl.client.DefaultHttpClient --express 'instances.{#crt=#this.connManager.conn.poolEntry.created,@org.apache.logging.log4j.core.util.datetime.FastDateFormat@getInstance("yyyy-MM-dd HH:mm:ss,SSS").format(#crt)} --limit 400
出现问题的Socket的创建时间并没有什么规律，也就是说不太可能是因为本应用的一些规律性事件（比如GC、锁等）导致的。
socket
vmtool --action getInstances --className org.apache.http.impl.client.DefaultHttpClient --express 'instances[0].connManager.conn.poolEntry.conn.socket'
从图中看，socket状态是很正常的：created=true，connected=true，closed=false。接下来查看超时时间配置
socket.impl
vmtool --action getInstances --className org.apache.http.impl.client.DefaultHttpClient --express 'instances[0].connManager.conn.poolEntry.conn.socket.impl'
timeout=0，当被调用服务没有响应或是被调用服务连接异常断开而没通知到的情况下，线程会一直阻塞在这里，分析到这里已经比较倾向是服务端没有响应造成了一直read，进而阻塞了整个线程。
如果服务端一直没有响应，那么socket接收队列和http client接收数据的buffer都应该是没有数据，现在我们验证下这个猜想。
该socket接收队列是否有未被应用读取的数据？
netstat -antp | grep 55084
从图中看接收队列是0，没有待处理的数据。
当前接收队列中没有数据，那之前是否接收到过数据呢？
从线程栈看http client代码正在等待解析http head的数据，一路代码跟下去，org.apache.http.impl.io.SessionInputBufferImpl是最终与Socket.InputStream交互的类，该类中存放着接收到数据；
org.apache.http.impl.io.SessionInputBufferImpl是在DefaultHttpClientConnection初始化的时候构建的：
查看SessionInputBuffer是否接收过数据
接下来我们查看下本地端口号是55084的连接，是否之前接收过数据及接收的数据是什么样的
vmtool -c 5e7cfcd6 --action getInstances --className org.apache.http.impl.client.DefaultHttpClient --express 'instances.{? #this.connManager.conn.poolEntry.conn.socket.impl.localport=55084}.{#bf=this.connManager.conn.poolEntry.conn.poolEntry.conn.inbuffer.buffer,@org.apache.commons.codec.binary.StringUtils@newStringUsAscii(#bf)}' -x 2 --limit 50
分析到这里已经颠覆了之前的猜想，之前猜想是由于服务端一直没返回数据造成socket一直阻塞在read上，现在看服务端返回了数据，但是返回的数据格式不符合http协议，所以一直在parseHead处阻塞着（话说这个地方算不算是httpclient的bug?）。
查看了其他有问题的socket，返回的数据也是异常的；
通过tcpdump抓包，从返回的数据看，与分析是一致的：
从返回的异常数据（-ERR … get …）猜测这是服务端代码在访问redis时候出现的报错信息，无论如何服务端出问题了。
解决办法
- 将异常信息告知服务提供方
- 优化httpclient使用方式
- 去掉httpclient低版本依赖，使用高版本httpclient
- 建立全局httpclient实例
- 为httpclient设置合适的参数
- 完善接口监控指标
