使用 jstack 对 Java 线程 Dump 分析

Posted by wxianfeng Sun, 01 Dec 2013 03:13:00 GMT

用 httpclient 写了个代理服务, 没跑一会就会出现 504 TimeOut 错误, tomcat 假死现象, 业务日志无任何输出, 切入点使用 jstack 分析线程堆栈

jstack dump 堆栈

查看 Tomcat 进程

➜  photostore git:(photostore_1.0.0) ps aux | grep tomcat
haomiao         40556   0.0  0.6  6352212  51224   ??  S     6:35PM   0:38.59

jstack Dump 进程堆栈:

➜  photostore git:(photostore_1.0.0) jstack -l 40556  > /tmp/ps.log
"http-bio-8080-exec-8" #85 daemon prio=5 os_prio=31 tid=0x00007fb8e18e8000 nid=0x11a13 waiting on condition [0x000000011d20a000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x000000079e359ad8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at org.apache.http.pool.PoolEntryFuture.await(PoolEntryFuture.java:138)
    at org.apache.http.pool.AbstractConnPool.getPoolEntryBlocking(AbstractConnPool.java:306)
    at org.apache.http.pool.AbstractConnPool.access$000(AbstractConnPool.java:64)
    at org.apache.http.pool.AbstractConnPool$2.getPoolEntry(AbstractConnPool.java:192)
    at org.apache.http.pool.AbstractConnPool$2.getPoolEntry(AbstractConnPool.java:185)
    at org.apache.http.pool.PoolEntryFuture.get(PoolEntryFuture.java:107)
    at org.apache.http.impl.conn.PoolingHttpClientConnectionManager.leaseConnection(PoolingHttpClientConnectionManager.java:276)
    at org.apache.http.impl.conn.PoolingHttpClientConnectionManager$1.get(PoolingHttpClientConnectionManager.java:263)
    at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:190)
    at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:184)
    at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:88)
    at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110)
    at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:184)
    at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:82)
    at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:107)
    at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:55)
    at com.yunos.photostore.gatedlaunch.biz.http.HttpReuqestExecutor.doPOST(HttpReuqestExecutor.java:42)
    at com.yunos.photostore.gatedlaunch.web.MyAsyncServlet.service(MyAsyncServlet.java:72)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:731)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:505)
    at com.taobao.tomcat.valves.ContextLoadFilterValve$FilterChainAdapter.doFilter(ContextLoadFilterValve.java:191)
    at com.taobao.eagleeye.EagleEyeFilter.doFilter(EagleEyeFilter.java:81)
    at com.taobao.tomcat.valves.ContextLoadFilterValve.invoke(ContextLoadFilterValve.java:150)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:429)
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1085)
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:625)
    at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:316)
    - locked <0x000000079cff4ba0> (a org.apache.tomcat.util.net.SocketWrapper)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:745)

   Locked ownable synchronizers:
    - <0x000000079cfec500> (a java.util.concurrent.ThreadPoolExecutor$Worker)

可以看到 线程都在 java.lang.Thread.State: WAITING (parking) 再看堆栈是在 httpclient 抛出来的, at org.apache.http.pool.AbstractConnPool.getPoolEntryBlocking(AbstractConnPool.java:306) 可以看出来 取连接的时候, 都被 Block 住了

netstat 看 TCP 连接, 果然存在 50 个 CLOSE_WAIT 的 TCP 连接

➜  photostore-test git:(master) ✗ netstat -a | grep rest.kanbox.com
tcp4       0      0  30.11.194.152.55421    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55418    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55402    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55400    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55398    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55396    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55394    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55392    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55390    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55388    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55386    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55384    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55382    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55380    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55378    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55376    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55374    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55372    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55370    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55368    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55366    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55364    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55362    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55360    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55357    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55338    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55336    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55127    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55090    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55089    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55088    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55087    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55086    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55085    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55084    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55081    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55079    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55075    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55058    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55050    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55025    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55021    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55020    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55019    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55017    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55016    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.55012    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.54985    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.54981    rest.kanbox.com.http   CLOSE_WAIT
tcp4       0      0  30.11.194.152.54980    rest.kanbox.com.http   CLOSE_WAIT

设置的 连接池 50 个, 所以只能处理 50 次请求就会出现 504 timeout 了, 因为连接池中取不到链接了。

CLOSE_WAIT 说明被动关闭了, 即对方关闭了连接, 自己没有关闭

解决办法

主动关闭连接: HttpClient 使用我们常用的InputStream.close()来确认连接关闭, httpclient 拿到 response, response 读取完了, 然后关闭流

public static void prepareForResponse(HttpServletResponse response, HttpResponse result) throws IOException {
    response.setStatus(result.getStatusLine().getStatusCode());
    response.setHeader("Content-Type","text/html;charset=UTF-8");
    InputStream inputStream = result.getEntity().getContent();
    OutputStream outputStream = response.getOutputStream();
    byte[] buffer = new byte[1024];
    int len ;
    while ((len = inputStream.read(buffer)) != -1) {
        outputStream.write(buffer, 0, len);
    }
    inputStream.close();
}

这个 case 告诉我们, Java 服务遇到假死的情况, 可以使用 jstack 神器。