tomcat7链接数异常致使超时问题的排查

时间 2019-11-18

标签 tomcat7 tomcat 链接异常致使超时问题排查栏目 Tomcat 繁體版

原文原文链接

1.摘要java

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

2.现象和处理正则表达式

某天某个跑在tomcat上的java服务的全部接口都忽然开始出现偶发超时，响应时间从几十毫秒增加到几秒，甚至几十秒。后端

比较灵异的一个现象tomcat处理日志和业务日志中都没有发现超时，日志里打出来的请求的响应时间都在几十毫秒，而且对线程数的监控也没有发现波动。tomcat

怀疑是负载均衡的问题，查看nginx日志，发现nginx访问后端时有不少慢请求。负载均衡

查看tomcat的gc状况，比较正常。less

在tomcat本机调用接口，发现一样存在超时问题，排除nginx的嫌疑。socket

感受问题基本出在tomcat上，决定先重启服务，果真重启后响应时间恢复。tcp

3.缘由排查oop

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

尝试复现问题：

直接调用摘除的节点没有发现问题。

尝试使用ab压测，没有复现。

尝试使用tcpcopy引流，在引流单台5倍流量的状况下依然没有出现。

把节点从新加回到线上集群，问题神奇的重现了。

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

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

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

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

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

0s 发出请求，tcp握手

11s accept()

11s read()

11s 业务日志

11s write()

11s tomcat access日志

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

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

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) {

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:

protected void countUpOrAwaitConnection() throws InterruptedException {

if (maxConnections==-1) return;

LimitLatch latch = connectionLimitLatch;

if (latch!=null) latch.countUpOrAwait();

}

protected void countUpOrAwaitConnection() throws InterruptedException {

if (maxConnections==-1) return;

LimitLatch latch = connectionLimitLatch;

if (latch!=null) latch.countUpOrAwait();

}

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

接收请求并建立client socket的accetpor线程（默认1个），在acceptor中维护了connectionCount，就是上面的connectionLimitLatch（最大链接数，bio中的默认最大值与maxThreadCount相同）

实际处理请求的exec线程(线程池中线程的最大数量等于maxThreadCount)，执行exec的线程池中也有一个线程数threadCount（最大值为maxThreadCount）

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

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

经过刚才拿到的heap dump查看connectionLimitLatch的值为800，跟配置的maxThreadCount相同，而当时实际tomcat的工做线程只有不到100个，因此猜想是connectionLimitLatch这个计数值异常致使新请求的accept被阻塞了。

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

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

}

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的代码：

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);

}

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)：

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

}

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

}

到这里能够肯定若是线程抛出了ThreadDeath或者VirtualMachineError，那么这个计数应该会有问题。

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

Exception in thread "catalina-exec-109" java.lang.StackOverflowError

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)

...

Exception in thread "catalina-exec-109" java.lang.StackOverflowError

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)

...

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

4.解决问题

尝试最小代码重现问题，把tomcat的maxThreadCount调成1，直接在Servlet里throw new StackOverflowError()，调用普通接口没有问题，调用一次错误接口后，再普通接口发现请求hang住了，与线上表现一致。

把tomcat的connector改成nio，问题解决。

升级tomcat到7.0.61，并改回bio，问题解决。进一步查看代码发现tomcat7.0.61已经修复了这个bug，单独判断了StackOverflow的状况。