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