tomcat假死原因分析

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.02, 0.02, 0.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.   
18. "version sniffer" daemon prio=10 tid=0x00002aacc4377000 nid=0x645 in Object.wait() [0x0000000040f3c000]  
19.    java.lang.Thread.State: TIMED_WAITING (on object monitor)  
20.         at java.lang.Object.wait(Native Method)  
21.         - waiting on <0x00002aaaee20b7b8> (a java.lang.Boolean)  
22.         at com.panguso.map.web.service.LocateServiceFactory$IpDataVersionSniffer.run(LocateServiceFactory.java:351)  
23.         - locked <0x00002aaaee20b7b8> (a java.lang.Boolean)  
24.         at java.lang.Thread.run(Thread.java:619)  
25.   
26. "ReplicaSetStatus:Updater" daemon prio=10 tid=0x000000005d070800 nid=0x636 waiting on condition [0x0000000044001000]  
27.    java.lang.Thread.State: TIMED_WAITING (sleeping)  
28.         at java.lang.Thread.sleep(Native Method)  
29.         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.    
7.             if (response.getStatusLine().getStatusCode() != 200) {  
8.                    
9.                 throw new MapabcPoiRequestException(  
10.                         "Http response status is not OK" );  
11.             }  

        这种写法意味着一旦出现非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 后端的服务出现了没有响应的情况。

 

文章来源：http://www.myexception.cn/open-source/921974.html

• 查看图片附件