使用 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 神器。

This entry was posted on Sun, 01 Dec 2013 03:13:00 GMT and Posted in . You can follow any any response to this entry through the Atom feed. You can leave a comment or a trackback from your own site.

Tags , , ,


Trackbacks

Use the following link to trackback from your own site:
http://wxianfeng.com/trackbacks?article_id=320

Comments

  1. Avatar
    Kerkyra Ancona almost {{count}} years ago:

    After I originally commented I apear to have clkcked on the Notify me
    when new commets are added
    checkbox and froom now on each time a comment is added I recieve 4 emails with the exact same comment.
    There has to bee a way you can remove me from that service?
    Manyy thanks!

  2. Avatar
    Kerkyra Ancona almost {{count}} years ago:

    Afteer I originally commented I appear to have clicked on the Notify me when new comments are added checkbox and from
    now onn each time a comment is adeed I recieve 4 emailss with the exact same comment.
    There has to be a way you can remove me from that service?
    Many thanks!

  3. Avatar
    kerkyra ancona about {{count}} years ago:

    Hello there, You have done an incredible job. I’ll certainly digg itt
    and personally recommend to my friends. I’m confident they’ll be benefited from this website.

  4. Avatar
    kerkyra ancona about {{count}} years ago:

    Hello there, You have done an incredible job. I’ll certainly digg it and personally rrecommend to my friends.
    I’m confident they’ll be benefited from this website.

Leave a comment