1. 程式人生 > >tomcat假死原因分析

tomcat假死原因分析

        最近監控服務發現有臺tomcat 的應用出現了無法訪問的情況 ,由於已做了叢集,基本沒有影響線上服務的正常使用。

        下面來簡單描述該臺tomcat當時具體的表現:客戶端請求沒有響應,檢視伺服器端tomcat 的java 程序存活,檢視tomcat 的catalina.log ,沒有發現異常,也沒有error 日誌.檢視localhost_access.log 也沒有最新的訪問日誌,該臺tomcat 已不能提供服務。

        根據前面的假死表象,最先想到的是網路是否出現了問題,於是開始從請求的資料流程開始分析。由於業務的架構採用的是nginx + tomcat 的叢集配置,一個請求上來的流向可以用下圖來簡單的描述。


        從上圖可以看出,如果是網路的原因,可以從兩個點進行分析。

1.從前端到nginx的網路情況

        分析nginx上的access.log ,在其中一臺上可以查出當時該條請求的訪問日誌,也就是說可以排除這段網路的問題。

2.從nginx 到tomcat 的網路情況

        分析tomcat 的訪問日誌localhost_acess.log 上無法查出該條請求的訪問日誌。可以懷疑是否網路有問題。就該情況,從該臺nginx ping 了一下tomcat server ,均為正常,沒有發現問題。既然網路貌似沒有問題,開始懷疑是tomcat本身的問題,在tomcat本機直接curl 呼叫該條請求,發現仍然沒有響應。到此基本可以斷定網路沒有問題,tomcat 本身出現了假死的情況。

        基於tomcat 假死的情況,開始分析有可能的原因。造成tomcat假死有可能的情況大概有以下幾種:

1.tomcat jvm 記憶體溢位

        分析當時的gc.log

Text程式碼  收藏程式碼
  1. 7581861.927: [GC 7581861.927: [ParNew  
  2. Desired survivor size 76677120 bytes, new threshold 15 (max 15)  
  3. - age   1:    5239168 bytes,    5239168 total  
  4. : 749056K->10477K(898816K), 0.0088550
     secs] 1418818K->680239K(8238848K), 0.0090350 secs]  

        沒有發現有記憶體溢位的情況,直接grep catalina.sh也沒有結果,證明沒有發生記憶體溢位的情況,這種假死可能可以排除。

Linux程式碼  收藏程式碼
  1. grep OutOfMemoryException catalina.sh  

2.jvm GC 時間過長,導致應用暫停

Text程式碼  收藏程式碼
  1. 7581088.402: [Full GC (System) 7581088.402: [CMS: 661091K->669762K(7340032K), 1.7206330 secs] 848607K->669762K(8238848K), [CMS Perm : 34999K->34976K(58372K)], 1.7209480 secs] [Times: user=1.72 sys=0.00, real=1.72 secs]  

        最近的一次full gc 顯示,也不應該會暫停幾分鐘的情況,這種假死可能可以排除。

3.load 太高,已經超出服務的極限

        當時top一下linux

Linux程式碼  收藏程式碼
  1. top   
  2. load average: 0.020.020.00  
  3. Tasks: 272 total,   1 running, 271 sleeping,   0 stopped,   0 zombie  
  4. Cpu(s):  0.2%us,  0.2%sy,  0.0%ni, 99.6%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st  
  5. Mem:  32950500k total, 23173908k used,  9776592k free,  1381456k buffers  
  6. Swap: 33551744k total,      236k used, 33551508k free, 12320412k cached  

        load 並不是高,這種假死可能可以排除。

4.應用本身程式的問題,造成死鎖

        針對這種情況,做了一下jstack,有少量執行緒處於TIMED_WAITING。

Text程式碼  收藏程式碼
  1. "Ice.ThreadPool.Client-75" daemon prio=10 tid=0x000000005c5ed800 nid=0x4cde in Object.wait() [0x0000000047738000]  
  2.    java.lang.Thread.State: TIMED_WAITING (on object monitor)  
  3.         at java.lang.Object.wait(Native Method)  
  4.         - waiting on <0x00002aab14336a10> (a IceInternal.ThreadPool)  
  5.         at IceInternal.ThreadPool.followerWait(ThreadPool.java:554)  
  6.         - locked <0x00002aab14336a10> (a IceInternal.ThreadPool)  
  7.         at IceInternal.ThreadPool.run(ThreadPool.java:344)  
  8.         - locked <0x00002aab14336a10> (a IceInternal.ThreadPool)  
  9.         at IceInternal.ThreadPool.access$300(ThreadPool.java:12)  
  10.         at IceInternal.ThreadPool$EventHandlerThread.run(ThreadPool.java:643)  
  11.         at java.lang.Thread.run(Thread.java:619)  
  12.         "ContainerBackgroundProcessor[StandardEngine[Catalina]]" daemon prio=10 tid=0x00002aacc4347800 nid=0x651 waiting on condition [0x00000000435f7000]  
  13.    java.lang.Thread.State: TIMED_WAITING (sleeping)  
  14.         at java.lang.Thread.sleep(Native Method)  
  15.         at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1378)  
  16.         at java.lang.Thread.run(Thread.java:619)  
  17. "version sniffer" daemon prio=10 tid=0x00002aacc4377000 nid=0x645 in Object.wait() [0x0000000040f3c000]  
  18.    java.lang.Thread.State: TIMED_WAITING (on object monitor)  
  19.         at java.lang.Object.wait(Native Method)  
  20.         - waiting on <0x00002aaaee20b7b8> (a java.lang.Boolean)  
  21.         at com.panguso.map.web.service.LocateServiceFactory$IpDataVersionSniffer.run(LocateServiceFactory.java:351)  
  22.         - locked <0x00002aaaee20b7b8> (a java.lang.Boolean)  
  23.         at java.lang.Thread.run(Thread.java:619)  
  24. "ReplicaSetStatus:Updater" daemon prio=10 tid=0x000000005d070800 nid=0x636 waiting on condition [0x0000000044001000]  
  25.    java.lang.Thread.State: TIMED_WAITING (sleeping)  
  26.         at java.lang.Thread.sleep(Native Method)  
  27.         at com.mongodb.ReplicaSetStatus$Updater.run(ReplicaSetStatus.java:428)  

        從jvm 堆疊資訊可以看出,其中有可能出現執行緒鎖死的情況為:IceInternal 和訪問mongdb的客戶端 com.mongodb.ReplicaSetStatus$Updater類。針對這兩種情況,看了一下原始碼,基本排除。

5.大量tcp 連線 CLOSE_WAIT

Linux程式碼  收藏程式碼
  1. netstat -n | awk '/^tcp/ {++S[$NF]} END {for(a in S) print a, S[a]}'   
  2. TIME_WAIT 48  
  3. CLOSE_WAIT 2228  
  4. ESTABLISHED 86  

        常用的三個狀態是:ESTABLISHED 表示正在通訊,TIME_WAIT 表示主動關閉,CLOSE_WAIT 表示被動關閉。


        從上面的圖可以看出來,如果一直保持在CLOSE_WAIT 狀態,那麼只有一種情況,就是在對方關閉連線之後,伺服器程式自己沒有進一步發出ack 訊號。

       換句話說,就是在對方連線關閉之後,程式裡沒有檢測到,或者程式壓根就忘記了這個時候需要關閉連線,於是這個資源就一直被程式佔著。個人覺得這種情況,通過伺服器核心引數也沒辦法解決,伺服器對於程式搶佔的資源沒有主動回收的權利,除非終止程式執行。

        由於咱們自己使用的是HttpClient ,並且遇到了大量CLOSE_WAIT 的情況。所以懷疑這個點可能出了問題。

        查看了咱們的httpClient 的寫法需要改正:

Java程式碼  收藏程式碼
  1. HttpGet get = new HttpGet(url.toString());  
  2. InputStream ins = null ;  
  3. try {  
  4.             HttpResponse response = excuteHttp(httpClient, get);  
  5.             // HttpResponse response = httpClient.execute(get);  
  6.             if (response.getStatusLine().getStatusCode() != 200) {  
  7.                 throw new MapabcPoiRequestException(  
  8.                         "Http response status is not OK" );  
  9.             }  

        這種寫法意味著一旦出現非200 的連線,InputStream ins根本就不會被賦值,這個連線將永遠僵死在連線池裡頭。

        解決方法:

Java程式碼  收藏程式碼
  1. if (response.getStatusLine().getStatusCode() != 200) {  
  2.                 get.abort();  
  3.                 throw new MapabcPoiRequestException("Http response status is not OK" );  
  4. }  

        應該改為顯示呼叫HttpGet 的abort ,這樣就會直接中止這次連線,我們在遇到異常的時候應該顯示呼叫,因為無法保證異常是在InputStream in 賦值之後才丟擲。但是這種情況也是發生在httpClient 後端的服務出現了沒有響應的情況。