前言
最近在某應用更新代碼后部分機器發布失敗,發布失敗的機器上Tomcat一直沒有啟動成功,日志卡在Deploying web application,重啟數次之后仍然是一樣的情況。所以進行排查問題,下面記錄了所有的排查過程,需要的朋友們可以參考學習。
排查過程
1. Tomcat啟動線程卡住
下文中Tomcat啟動線程代指線程名為localhost-startStop-$id
的線程。
使用jstack打印出Tomcat的線程堆棧:
1
|
jstack `jps |grep Bootstrap |awk '{print $1}'` > jstack.log |
從jstack.log里面可以看到線程localhost-startStop-1處于WAITING狀態,堆棧如下:
1
2
3
4
5
6
7
8
9
|
"localhost-startStop-1" #26 daemon prio=5 os_prio=0 tid=0x00007fe6c8002000 nid=0x3dc1 waiting on condition [0x00007fe719c1e000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000007147be150> (a xxx.heartbeat.network.client.FutureResult) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.FutureTask.awaitDone(FutureTask.java:429) at java.util.concurrent.FutureTask.get(FutureTask.java:191) at xxx.HeartBeatContainer.invoke(HeartBeatContainer.java:183) at xxx.HeartBeatContainer.registry(HeartBeatContainer.java:130) |
對應的代碼如下:
1
2
3
|
final ResponseFuture<XxxMessage<Result>> future = responseFutureFactory.newResponseFuture(request); channel.writeAndFlush(request); XxxMessage<Result> response = future.get(); |
線程一直卡在future.get()
沒有返回。這個步驟是在等待客戶端向Xxx-Server發送的注冊請求的返回。
2. Xxx注冊請求沒返回
用tcpdump抓了下包(Xxx-Server的服務端口是yyy):
1
|
tcpdump -X -s0 -i bond0 port yyy |
發現只有建連接的包,沒有length != 0的數據包:
1
2
3
|
IP app-ip.56599 > xxx-server-ip.yyy: Flags [S], seq 3536490816, win 14600, options [mss 1460,sackOK,TS val 3049061547 ecr 0], length 0 IP xxx-server-ip.yyy > app-ip.56599: Flags [S.], seq 2500877640, ack 3536490817, win 14480, options [mss 1460,sackOK,TS val 1580197458 ecr 3049061547], length 0 IP app-ip.56599 > xxx-server-ip.yyy: Flags [.], ack 1, win 14600, options [nop,nop,TS val 3049061548 ecr 1580197458], length 0 |
所以,推斷注冊請求沒返回的原因是請求壓根兒沒有發送出去。
3. Xxx注冊請求沒發送出去
Xxx代碼里面調用了channel.writeAndFlush,但是數據卻沒有發送出去。這塊的代碼,更友好的做法應該是writeAndFlush之后對返回的ChannelFuture注冊一個Listener,在write操作完成之后的回調里面判斷狀態。
在Netty大神 – @yh的指導下用BTrace跟了一下Netty的代碼。
在Tomcat啟動邏輯相關腳本bin/catalina.sh里面加上參數讓Btrace agent和Tomcat一起啟動:
1
|
JAVA_OPTS="$JAVA_OPTS -javaagent:${BTRACE_HOME}/build/btrace-agent.jar=script=${BTRACE_HOME}/scripts/HangDebug.class,stdout=true,debug=true,noServer=true" |
HangDebug.class里面包含了一些需要查看的方法,下面是排查沒有發送請求原因的步驟:
-
首先發現沒有調用接口
io.netty.channel.Channel.Unsafe
的write方法,驗證了請求沒有發送出去的推論; -
然后發現調用接口
io.netty.channel.ChannelOutboundHandler
的write方法時報錯; -
最后定位到調用類
io.netty.handler.codec.MessageToByteEncoder
的write方法時拋出了異常,異常堆棧為:
1
2
3
4
5
6
7
|
io.netty.handler.codec.EncoderException: java.lang.NoSuchMethodError: io.netty.util.internal.MathUtil.safeFindNextPositivePowerOfTwo(I)I io.netty.handler.codec.MessageToByteEncoder.write(MessageToByteEncoder.java:125) ... Caused by: java.lang.NoSuchMethodError: io.netty.util.internal.MathUtil.safeFindNextPositivePowerOfTwo(I)I io.netty.buffer.PoolThreadCache$MemoryRegionCache.<init>(PoolThreadCache.java:372) ... |
這個時候,問題的原因比較明確了:
io.netty.util.internal.MathUtil.safeFindNextPositivePowerOfTwo
這個方法沒有找到。
最后找到問題的BTrace Method如下:
1
2
3
4
5
6
7
8
9
10
|
@OnMethod( clazz = "+io.netty.channel.ChannelOutboundHandler", method = "write", location = @Location(value = Kind.ERROR) ) public static void errorChannelOutboundHandlerWrite(@ProbeClassName String className, Throwable cause) { println("error ChannelOutboundHandler.write, real class: " + className); Threads.jstack(cause); println("====================="); } |
這里有一個問題:為什么這個異常日志里面沒有打印呢?
這個問題可以從io.netty.channel.AbstractChannelHandlerContext
代碼里找到答案:
1
2
3
4
5
6
7
|
private void invokeWrite(Object msg, ChannelPromise promise) { try { ((ChannelOutboundHandler)this.handler()).write(this, msg, promise); } catch (Throwable var4) { notifyOutboundHandlerException(var4, promise); } } |
notifyOutboundHandlerException會去通知對應的Listener,Xxx的這段老代碼沒有注冊Listener,所以沒有打印出這個異常。
4. NoSuchMethodError原因
再次查看了下$WEBAPP-DIR/WEB-INF/lib下Netty的版本:
1
2
3
4
5
6
7
8
9
10
11
|
netty-3.10.6.Final.jar netty-all-4.1.4.Final.jar netty-buffer-4.1.5.Final.jar netty-codec-4.1.5.Final.jar netty-codec-http-4.1.5.Final.jar netty-common-4.1.5.Final.jar netty-handler-4.1.5.Final.jar netty-resolver-4.1.5.Final.jar netty-transport-4.1.5.Final.jar transport-netty3-client-5.0.0.jar transport-netty4-client-5.0.0.jar |
比較扎眼的是netty-all-4.1.4.Final.jar的版本和其它jar包版本不太一致。需要進一步確認一下,io.netty.buffer.PoolThreadCache$MemoryRegionCache
和io.netty.util.internal.MathUtil
這兩個類分別是從哪個jar包中加載的。
在Tomcat啟動邏輯相關腳本bin/catalina.sh里面加上啟動參數,打印Class加載的日志:
1
|
JAVA_OPTS="$JAVA_OPTS -verbose:class" |
可以看到:
1
2
3
4
5
|
... [Loaded io.netty.buffer.PoolThreadCache$MemoryRegionCache from file:$WEBAPP-DIR/WEB-INF/lib/WEB-INF/lib/netty-buffer-4.1.5.Final.jar] ... [Loaded io.netty.util.internal.MathUtil from file:$WEBAPP-DIR/WEB-INF/lib/netty-all-4.1.4.Final.jar] ... |
從netty-all-4.1.4.Final.jar中加載的io.netty.util.internal.MathUtil
,是沒有safeFindNextPositivePowerOfTwo這個方法的(正常情況下,應該從netty-common-4.1.5.Final.jar中加載這個類)。
至此為止,弄清楚了啟動卡住的原因:
Netty包加載問題 => Xxx調用channel.writeAndFlush發送注冊請求時異常 => 沒有回包,future.get()
一直卡住 => Tomcat啟動線程卡住
還有一個令人費解的現象:為什么有的機器啟動正常,有的機器啟動不正常呢?
5. 不同機器表現不同
再回頭看一下啟動有問題的機器上Netty相關jar包的順序,這里我們使用ls -f命令(只關注和問題相關的jar包):
1
2
3
4
5
6
|
$ ls -f |grep netty netty-buffer-4.1.5.Final.jar netty-all-4.1.4.Final.jar ... netty-common-4.1.5.Final.jar ... |
ls加-f參數的含義可以通過man手冊看到:
1
|
-f do not sort, enable -aU, disable -ls --color |
意思是直接使用系統調用getdents的返回,不再做排序。從man手冊可以看到,ls默認排序方法是Sort entries alphabetically if none。
NoSuchMethodError的原因是:從netty-buffer-4.1.5.Final.jar中加載了io.netty.buffer.PoolThreadCache$MemoryRegionCache
,這個類是會調用io.netty.util.internal.MathUtil.safeFindNextPositivePowerOfTwo
這個方法的;從netty-all-4.1.4.Final.jar加載的io.netty.util.internal.MathUtil
沒有這個方法。
對比看下啟動正確的機器上的Netty相關jar包的順序:
1
2
3
4
5
6
7
|
$ ls -f |grep netty ... netty-all-4.1.4.Final.jar ... netty-common-4.1.5.Final.jar netty-buffer-4.1.5.Final.jar ... |
由此可以看出所有Netty相關的Class均從netty-all-4.1.4.Final.jar中加載,不會有不兼容的問題產生。
要么問題來了:為什么在ext4中,擁有相同目錄項的目錄,ls -f出來的順序是不一樣的呢?
這個問題我暫時也回答不上來,至少我還沒有拿到令自己信服的代碼級別的解釋。
嗯,沒有代碼的解釋不是解釋,沒有deadline的任務不是任務,沒有流程圖或分享的源碼閱讀不是源碼閱讀,沒有報告的性能測試不是性能測試。
這里有一個基于現象的解釋,我覺得還比較靠譜:
On modern filesystems where directory data structures are based on a search tree or hash table, the order is practically unpredictable.
我們可以做的
事后諸葛亮時間 :) 開玩笑的,遇事多review下才能少犯錯誤。
- 基礎組件:多考慮失敗的情況,不吞異常;可能阻塞的操作考慮超時時間(自勉)
- 發布系統:能夠添加一些規則,哪些包不能共存,比如上述問題中的netty-all和netty-common這些
- 容器隔離:隔離中間件使用的三方包和業務使用的三方包
總結
以上就是這篇文章的全部內容了,希望本文的內容對大家的學習或者工作能帶來一定的幫助,如果有疑問大家可以留言交流,謝謝大家對服務器之家的支持。
原文鏈接:http://sel-fish.net/2017/04/12/tomcat-startup-hang/