前言
最近在某應用更新代碼后部分機器發布失敗，發布失敗的機器上Tomcat一直沒有啟動成功，日志卡在Deploying web application，重啟數次之后仍然是一樣的情況。所以進行排查問題，下面記錄了所有的排查過程，需要的朋友們可以參考學習。
排查過程
1. Tomcat啟動線程卡住
下文中Tomcat啟動線程代指線程名為localhost-startStop-$id的線程。
使用jstack打印出Tomcat的線程堆棧：
jstack `jps |grep Bootstrap |awk '{print $1}'` > jstack.log從jstack.log里面可以看到線程localhost-startStop-1處于WAITING狀態，堆棧如下：
"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)
對應的代碼如下：
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）：
tcpdump -X -s0 -i bond0 port yyy
發現只有建連接的包，沒有length != 0的數據包：
IP app-ip.56599 > xxx-server-ip.yyy: Flags [S], seq 3536490816, win 14600, options [mss 1460,sackOK,TS val 3049061547 ecr 0], length 0IP 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 0IP 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一起啟動：
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方法時拋出了異常，異常堆棧為：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如下：
@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代碼里找到答案：
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的版本：
netty-3.10.6.Final.jarnetty-all-4.1.4.Final.jarnetty-buffer-4.1.5.Final.jarnetty-codec-4.1.5.Final.jarnetty-codec-http-4.1.5.Final.jarnetty-common-4.1.5.Final.jarnetty-handler-4.1.5.Final.jarnetty-resolver-4.1.5.Final.jarnetty-transport-4.1.5.Final.jartransport-netty3-client-5.0.0.jartransport-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加載的日志：
JAVA_OPTS="$JAVA_OPTS -verbose:class"
可以看到：
...[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包）：
$ ls -f |grep nettynetty-buffer-4.1.5.Final.jarnetty-all-4.1.4.Final.jar...netty-common-4.1.5.Final.jar...
ls加-f參數的含義可以通過man手冊看到：
-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包的順序：
$ ls -f |grep netty...netty-all-4.1.4.Final.jar...netty-common-4.1.5.Final.jarnetty-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下才能少犯錯誤。
總結
以上就是這篇文章的全部內容了，希望本文的內容對大家的學習或者工作能帶來一定的幫助，如果有疑問大家可以留言交流，謝謝大家對VEVB武林網的支持。
新聞熱點
疑難解答
圖片精選
