tomcat7鏈接數異常致使超時問題的排查

 

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

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:

 

 

protected void countUpOrAwaitConnection() throws InterruptedException {

if (maxConnections==-1) return;

LimitLatch latch = connectionLimitLatch;

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

}

1

2

3

4

5

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

}

} 

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

 

 

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

}

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

 

 

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

}

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

}

到這裏能夠肯定若是線程拋出了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$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)

...

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)

...

根據線程棧定位到異常的緣由是進行正則表達式匹配時棧溢出。

 

4.解決問題

 

嘗試最小代碼重現問題，把tomcat的maxThreadCount調成1，直接在Servlet裏throw new StackOverflowError()，調用普通接口沒有問題，調用一次錯誤接口後，再普通接口發現請求hang住了，與線上表現一致。

把tomcat的connector改成nio，問題解決。

升級tomcat到7.0.61，並改回bio，問題解決。進一步查看代碼發現tomcat7.0.61已經修復了這個bug，單獨判斷了StackOverflow的狀況。