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

最新推荐文章于 2022-09-29 18:54:03 发布

weixin_34127717

最新推荐文章于 2022-09-29 18:54:03 发布

阅读量783

点赞数

文章标签： java 运维网络

原文链接：https://my.oschina.net/rock912/blog/607349

版权

2019独角兽企业重金招聘Python工程师标准>>>

1.摘要

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

2.现象和处理

某天某个跑在tomcat上的java服务的所有接口都突然开始出现偶发超时，响应时间从几十毫秒增长到几秒，甚至几十秒。

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

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

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

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

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

3.原因排查

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

尝试复现问题：

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

尝试使用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的情况。

转载于:https://my.oschina.net/rock912/blog/607349

weixin_34127717

关注

0
点赞
踩
2

收藏

觉得还不错? 一键收藏
0
评论
tomcat7连接数异常导致超时问题的排查

2019独角兽企业重金招聘Python工程师标准>>> ...
复制链接

扫一扫

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

“相关推荐”对你有帮助么？