tomcat7连接数异常导致超时问题的排查

1.摘要

前几天线上tomcat出了一次诡异的超时问题，在此记录下来。每次问题的排查都很痛苦，而定位原因之后再回想整个过程又常常有“当时如果看了那个其实早就能知道了”之类的懊恼，看来问题排查流程的标准化还有很长的路要走。

2.现象和处理

1. 某天某个跑在tomcat上的java服务的所有接口都突然开始出现偶发超时，响应时间从几十毫秒增长到几秒，甚至几十秒。
2. 比较灵异的一个现象tomcat处理日志和业务日志中都没有发现超时，日志里打出来的请求的响应时间都在几十毫秒，并且对线程数的监控也没有发现波动。
3. 怀疑是负载均衡的问题，查看nginx日志，发现nginx访问后端时有很多慢请求。
4. 查看tomcat的gc情况，比较正常。
5. 在tomcat本机调用接口，发现同样存在超时问题，排除nginx的嫌疑。
6. 感觉问题基本出在tomcat上，决定先重启服务，果然重启后响应时间恢复。

3.原因排查

1. 重启的时候从集群中摘除了一台节点保留现场，因为服务已经两周没有上过线，所以怀疑跟某种资源堆积有关。

2. 尝试复现问题：

   1. 直接调用摘除的节点没有发现问题。
   2. 尝试使用ab压测，没有复现。
   3. 尝试使用tcpcopy引流，在引流单台5倍流量的情况下依然没有出现。
   4. 把节点重新加回到线上集群，问题神奇的重现了。

3. jstack查看出问题时的线程栈，没有发现死锁或者大量线程阻塞。

4. jmap做heap dump，分析了一下内存，没发现特别明显的内存泄露或者大对象。

5. strace查看系统调用，发现poll()系统调用偶发会超时，超时时间和connectionTimeout设定的时间一致。

6. 继续追查了一下poll()超时的问题，发现请求超时和poll()超时之间没有什么必然联系，在没有poll()超时的时间段里也会出现偶发的请求超时，这条路似乎走不通。

7. 同时使用strace和tcpdump，在特定机器上调用一个特殊的uri，uri会打印在strace得到的read()的返回值里，从而得可以得到fd，并找出相应的accept()和write()，并结合对指定ip的tcpdump，可以得出这个请求的处理时间轴大概是：

   • 0s 发出请求，tcp握手
   • 11s accept()
   • 11s read()
   • 11s 业务日志
   • 11s write()
   • 11s tomcat access日志

8. 基本可以定位是tcp握手到accept()之间出了什么问题，查看rx_queue，没有发现堆积，排查方向转到tomcat调用accept()部分。

9. 查看tomcat源码，线上使用的是tomcat7.0.24，bio connector。在JioEndpoint的代码里发现了比较可疑的地方：

   1 2 3 4 5 6 7 8 9

   try { //if we have reached max connections, wait countUpOrAwaitConnection(); // 感觉这句比较可疑 Socket socket = null; try { // Accept the next incoming connection from the server // socket socket = serverSocketFactory.acceptSocket(serverSocket); } catch (IOException ioe) {

   内部是一个LimitLatch:

   1 2 3 4 5

   protected void countUpOrAwaitConnection() throws InterruptedException { if (maxConnections==-1) return; LimitLatch latch = connectionLimitLatch; if (latch!=null) latch.countUpOrAwait(); }

10. 简单阅读了一下源码，使用bio的connector时，线程分为：

    • 接收请求并创建client socket的accetpor线程（默认1个），在acceptor中维护了connectionCount，就是上面的connectionLimitLatch（最大连接数，bio中的默认最大值与maxThreadCount相同）
    • 实际处理请求的exec线程(线程池中线程的最大数量等于maxThreadCount)，执行exec的线程池中也有一个线程数threadCount（最大值为maxThreadCount）

    网上随便找了张图，bio的处理流程：

    图片来自http://www./cn/articles/zh-tomcat-http-request-1

11. 通过刚才拿到的heap dump查看connectionLimitLatch的值为800，跟配置的maxThreadCount相同，而当时实际tomcat的工作线程只有不到100个，所以猜测是connectionLimitLatch这个计数值异常导致新请求的accept被阻塞了。

12. 继续追查代码，在实际处理的线程中对这个计数的减操作是这么处理的：

    1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18

    if ((state != SocketState.CLOSED)) { if (status == null) { state = handler.process(socket, SocketStatus.OPEN); } else { state = handler.process(socket,status);            } } if (state == SocketState.CLOSED) { // Close socket if (log.isTraceEnabled()) { log.trace("Closing socket:"+socket); } countDownConnection(); try { socket.getSocket().close(); } catch (IOException e) { // Ignore } }

    似乎对Exception没有做什么处理，进一步查看handler的代码：

    1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19

    try { blablabla... }catch(java.net.SocketException e) { // SocketExceptions are normal getLog().debug(sm.getString("abstractConnectionHandler.socketexception.debug"), e); } catch (java.io.IOException e) { // IOExceptions are normal getLog().debug(sm.getString("abstractConnectionHandler.ioexception.debug"), e); } // Future developers: if you discover any other // rare-but-nonfatal exceptions, catch them here, and log as // above. catch (Throwable e) { ExceptionUtils.handleThrowable(e); // any other exception or error is odd. Here we log it // with "ERROR" level, so it will show up even on // less-than-verbose logs. getLog().error(sm.getString("abstractConnectionHandler.error"), e); }

    进一步查看ExceptionUtils.handleThrowable(e)：

    1 2 3 4 5 6 7 8 9

    public static void handleThrowable(Throwable t) { if (t instanceof ThreadDeath) { throw (ThreadDeath) t; } if (t instanceof VirtualMachineError) { throw (VirtualMachineError) t; } // All other instances of Throwable will be silently swallowed }

13. 到这里可以确定如果线程抛出了ThreadDeath或者VirtualMachineError，那么这个计数应该会有问题。

14. 进一步搜索出错之前的日志，在catalina.out里发现有偶发的StackOverflowError：

    1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29

    Exception in thread "catalina-exec-109" java.lang.StackOverflowError at java.util.regex.Pattern$5.isSatisfiedBy(Pattern.java:5151) at java.util.regex.Pattern$5.isSatisfiedBy(Pattern.java:5151) at java.util.regex.Pattern$5.isSatisfiedBy(Pattern.java:5151) at java.util.regex.Pattern$5.isSatisfiedBy(Pattern.java:5151) at java.util.regex.Pattern$5.isSatisfiedBy(Pattern.java:5151) at java.util.regex.Pattern$5.isSatisfiedBy(Pattern.java:5151) at java.util.regex.Pattern$5.isSatisfiedBy(Pattern.java:5151) at java.util.regex.Pattern$5.isSatisfiedBy(Pattern.java:5151) at java.util.regex.Pattern$5.isSatisfiedBy(Pattern.java:5151) at java.util.regex.Pattern$5.isSatisfiedBy(Pattern.java:5151) at java.util.regex.Pattern$5.isSatisfiedBy(Pattern.java:5151) at java.util.regex.Pattern$5.isSatisfiedBy(Pattern.java:5151) at java.util.regex.Pattern$CharProperty.match(Pattern.java:3694) at java.util.regex.Pattern$GroupHead.match(Pattern.java:4556) at java.util.regex.Pattern$Branch.match(Pattern.java:4502) at java.util.regex.Pattern$GroupHead.match(Pattern.java:4556) at java.util.regex.Pattern$Loop.match(Pattern.java:4683) at java.util.regex.Pattern$GroupTail.match(Pattern.java:4615) at java.util.regex.Pattern$BranchConn.match(Pattern.java:4466) at java.util.regex.Pattern$GroupTail.match(Pattern.java:4615) at java.util.regex.Pattern$CharProperty.match(Pattern.java:3694) at java.util.regex.Pattern$GroupHead.match(Pattern.java:4556) at java.util.regex.Pattern$Branch.match(Pattern.java:4502) at java.util.regex.Pattern$GroupHead.match(Pattern.java:4556) at java.util.regex.Pattern$Loop.match(Pattern.java:4683) at java.util.regex.Pattern$GroupTail.match(Pattern.java:4615) at java.util.regex.Pattern$BranchConn.match(Pattern.java:4466) ...

15. 根据线程栈定位到异常的原因是进行正则表达式匹配时栈溢出。

4.解决问题

1. 尝试最小代码重现问题，把tomcat的maxThreadCount调成1，直接在Servlet里throw new StackOverflowError()，调用普通接口没有问题，调用一次错误接口后，再普通接口发现请求hang住了，与线上表现一致。
2. 把tomcat的connector改为nio，问题解决。
3. 升级tomcat到7.0.61，并改回bio，问题解决。进一步查看代码发现tomcat7.0.61已经修复了这个bug，单独判断了StackOverflow的情况。