記一次socket read導緻業務線程阻塞的案例分析（arthas神器也）

問題描述

TAM同學回報某個應用阻塞了：通路應用健康檢查URL也通路不通，目前排查了EDAS、SLB及WAF等雲産品均沒有發現明顯問題。

我登入到ECS，curl健康檢查URL，确實已經通路不通了（建立連接配接逾時）。

基本情況

流量是從網際網路終端請求過來的，最終經過雲産品SLB負載均衡到該應用，該應用使用的是taobao-tomcat-7.0.59，監聽端口是8080。

分析過程

系統負載太高了？

首先懷疑是不是因為系統負載太高了，導緻應用無法處理請求，是以先檢查一下系統名額。

top

top

對于4c8g的配置來說，CPU、記憶體、Load等名額都很低。

jstat

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'           

全連接配接和半連接配接被drop的數量

從圖中看有連接配接不斷地連過來，無論是握手成功還是半握手的，失敗的數量都在不斷增加。

線程阻塞？

對于網絡應用程式來說，通常的線程模型是：獨立的線程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()}'           

vmtool精确定位線程棧

從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()'           

vmtool擷取tomcat線程配置

可以看到配置的最大線程數是：360

線程池運作狀态

vmtool --action getInstances --className org.apache.coyote.http11.Http11Protocol --express 'instances[0].getExecutor().toString()'           

vmtool擷取線程運作狀态

從圖中看pool size=360,active threads=360,queued tasks=40,說明tomcat線程池已經用滿了，到這裡curl無法建立連接配接的原因算是定位到了。

接下來我們根據線程棧一步步排查吧（很多問題不了解業務并不影響問題排查，但是了解業務的話會更快地分析定位問題）。

jad

反編譯業務Controller，看看從具體業務邏輯中是否能夠找到線索。

jad 類的全局限定名           

jad反編譯檢視業務代碼

一眼看去這塊代碼存在幾個很明顯的問題：

• Controller每接收到一個請求都新建立一個DefaultHttpClient對象是不合理的，因為DefaultHttpClient本身就是連接配接池的概念，全局使用一個就可以了；
• 由于DefaultHttpClient是方法局部變量，當方法執行完後該對象在某個時候就會被垃圾回收掉，該對象持有的連接配接能保證安全關閉嗎？
• 該DefaultHttpClient對象沒有設定任何socket相關的參數，沒有資料傳回的情況下，socket.read會不會一直阻塞着？

sc

sc -d org.apache.http.impl.client.DefaultHttpClient           

sc檢視依賴包

看了下lib目錄下有比較新的版本，似乎用新版本更好一些。

vmtool HttpGet

vmtool --action getInstances --className org.apache.http.client.methods.HttpGet --express 'instances[0]'           

vmtool檢視HttpGet

從圖中可以看出請求的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]'           

vmtool檢視DefaultHttpClient

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           

vmtool檢視PoolEntry

批量檢視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           

vmtool檢視socket建立時間

出現問題的Socket的建立時間并沒有什麼規律，也就是說不太可能是因為本應用的一些規律性事件（比如GC、鎖等）導緻的。

socket

vmtool --action getInstances --className org.apache.http.impl.client.DefaultHttpClient --express 'instances[0].connManager.conn.poolEntry.conn.socket'           

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'           

socket配置資訊

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初始化的時候建構的：

SessionInputBufferImpl

檢視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抓包，從傳回的資料看，與分析是一緻的：

tcpdump抓包驗證

從傳回的異常資料（-ERR … get …）猜測這是服務端代碼在通路redis時候出現的報錯資訊，無論如何服務端出問題了。

解決辦法

• 将異常資訊告知服務提供方
• 去掉httpclient低版本依賴，使用高版本httpclient
• 建立全局httpclient執行個體
• 為httpclient設定合适的參數
• 完善接口監控名額