前言

最近在某應(yīng)用更新代碼后部分機(jī)器發(fā)布失敗，發(fā)布失敗的機(jī)器上Tomcat一直沒(méi)有啟動(dòng)成功，日志卡在Deploying web application，重啟數(shù)次之后仍然是一樣的情況。所以進(jìn)行排查問(wèn)題，下面記錄了所有的排查過(guò)程，需要的朋友們可以參考學(xué)習(xí)。

排查過(guò)程

1. Tomcat啟動(dòng)線程卡住

下文中Tomcat啟動(dòng)線程代指線程名為localhost-startStop-$id的線程。

使用jstack打印出Tomcat的線程堆棧：

jstack `jps |grep Bootstrap |awk '{print $1}'` > jstack.log

從jstack.log里面可以看到線程localhost-startStop-1處于WAITING狀態(tài)，堆棧如下：

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

對(duì)應(yīng)的代碼如下：

final ResponseFuture<XxxMessage<Result>> future = responseFutureFactory.newResponseFuture(request);
channel.writeAndFlush(request);
XxxMessage<Result> response = future.get();

線程一直卡在future.get()沒(méi)有返回。這個(gè)步驟是在等待客戶端向Xxx-Server發(fā)送的注冊(cè)請(qǐng)求的返回。

2. Xxx注冊(cè)請(qǐng)求沒(méi)返回

用tcpdump抓了下包（Xxx-Server的服務(wù)端口是yyy）：

tcpdump -X -s0 -i bond0 port yyy

發(fā)現(xiàn)只有建連接的包，沒(méi)有l(wèi)ength != 0的數(shù)據(jù)包：

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

所以，推斷注冊(cè)請(qǐng)求沒(méi)返回的原因是請(qǐng)求壓根兒沒(méi)有發(fā)送出去。

3. Xxx注冊(cè)請(qǐng)求沒(méi)發(fā)送出去

Xxx代碼里面調(diào)用了channel.writeAndFlush，但是數(shù)據(jù)卻沒(méi)有發(fā)送出去。這塊的代碼，更友好的做法應(yīng)該是writeAndFlush之后對(duì)返回的ChannelFuture注冊(cè)一個(gè)Listener，在write操作完成之后的回調(diào)里面判斷狀態(tài)。

在Netty大神 – @yh的指導(dǎo)下用BTrace跟了一下Netty的代碼。

在Tomcat啟動(dòng)邏輯相關(guān)腳本bin/catalina.sh里面加上參數(shù)讓Btrace agent和Tomcat一起啟動(dòng)：

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里面包含了一些需要查看的方法，下面是排查沒(méi)有發(fā)送請(qǐng)求原因的步驟：

• 首先發(fā)現(xiàn)沒(méi)有調(diào)用接口io.netty.channel.Channel.Unsafe的write方法，驗(yàn)證了請(qǐng)求沒(méi)有發(fā)送出去的推論；
• 然后發(fā)現(xiàn)調(diào)用接口io.netty.channel.ChannelOutboundHandler的write方法時(shí)報(bào)錯(cuò)；
• 最后定位到調(diào)用類io.netty.handler.codec.MessageToByteEncoder的write方法時(shí)拋出了異常，異常堆棧為：

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

這個(gè)時(shí)候，問(wèn)題的原因比較明確了：
io.netty.util.internal.MathUtil.safeFindNextPositivePowerOfTwo這個(gè)方法沒(méi)有找到。

最后找到問(wèn)題的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("=====================");
}

這里有一個(gè)問(wèn)題：為什么這個(gè)異常日志里面沒(méi)有打印呢？

這個(gè)問(wèn)題可以從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會(huì)去通知對(duì)應(yīng)的Listener，Xxx的這段老代碼沒(méi)有注冊(cè)Listener，所以沒(méi)有打印出這個(gè)異常。

4. NoSuchMethodError原因

再次查看了下$WEBAPP-DIR/WEB-INF/lib下Netty的版本：

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包版本不太一致。需要進(jìn)一步確認(rèn)一下，io.netty.buffer.PoolThreadCache$MemoryRegionCache和io.netty.util.internal.MathUtil這兩個(gè)類分別是從哪個(gè)jar包中加載的。

在Tomcat啟動(dòng)邏輯相關(guān)腳本bin/catalina.sh里面加上啟動(dòng)參數(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，是沒(méi)有safeFindNextPositivePowerOfTwo這個(gè)方法的（正常情況下，應(yīng)該從netty-common-4.1.5.Final.jar中加載這個(gè)類）。

至此為止，弄清楚了啟動(dòng)卡住的原因：

Netty包加載問(wèn)題 => Xxx調(diào)用channel.writeAndFlush發(fā)送注冊(cè)請(qǐng)求時(shí)異常 => 沒(méi)有回包，future.get()一直卡住 => Tomcat啟動(dòng)線程卡住

還有一個(gè)令人費(fèi)解的現(xiàn)象：為什么有的機(jī)器啟動(dòng)正常，有的機(jī)器啟動(dòng)不正常呢？

5. 不同機(jī)器表現(xiàn)不同

再回頭看一下啟動(dòng)有問(wèn)題的機(jī)器上Netty相關(guān)jar包的順序，這里我們使用ls -f命令（只關(guān)注和問(wèn)題相關(guān)的jar包）：

$ 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參數(shù)的含義可以通過(guò)man手冊(cè)看到：

-f do not sort, enable -aU, disable -ls --color

意思是直接使用系統(tǒng)調(diào)用getdents的返回，不再做排序。從man手冊(cè)可以看到，ls默認(rèn)排序方法是Sort entries alphabetically if none。

NoSuchMethodError的原因是：從netty-buffer-4.1.5.Final.jar中加載了io.netty.buffer.PoolThreadCache$MemoryRegionCache，這個(gè)類是會(huì)調(diào)用io.netty.util.internal.MathUtil.safeFindNextPositivePowerOfTwo這個(gè)方法的；從netty-all-4.1.4.Final.jar加載的io.netty.util.internal.MathUtil沒(méi)有這個(gè)方法。

對(duì)比看下啟動(dòng)正確的機(jī)器上的Netty相關(guān)jar包的順序：

$ 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相關(guān)的Class均從netty-all-4.1.4.Final.jar中加載，不會(huì)有不兼容的問(wèn)題產(chǎn)生。

要么問(wèn)題來(lái)了：為什么在ext4中，擁有相同目錄項(xiàng)的目錄，ls -f出來(lái)的順序是不一樣的呢？

這個(gè)問(wèn)題我暫時(shí)也回答不上來(lái)，至少我還沒(méi)有拿到令自己信服的代碼級(jí)別的解釋。

嗯，沒(méi)有代碼的解釋不是解釋，沒(méi)有deadline的任務(wù)不是任務(wù)，沒(méi)有流程圖或分享的源碼閱讀不是源碼閱讀，沒(méi)有報(bào)告的性能測(cè)試不是性能測(cè)試。

這里有一個(gè)基于現(xiàn)象的解釋，我覺(jué)得還比較靠譜：

On modern filesystems where directory data structures are based on a search tree or hash table, the order is practically unpredictable.

我們可以做的

事后諸葛亮?xí)r間 :) 開(kāi)玩笑的，遇事多review下才能少犯錯(cuò)誤。

• 基礎(chǔ)組件：多考慮失敗的情況，不吞異常；可能阻塞的操作考慮超時(shí)時(shí)間（自勉）
• 發(fā)布系統(tǒng)：能夠添加一些規(guī)則，哪些包不能共存，比如上述問(wèn)題中的netty-all和netty-common這些
• 容器隔離：隔離中間件使用的三方包和業(yè)務(wù)使用的三方包

總結(jié)

以上就是這篇文章的全部?jī)?nèi)容了，希望本文的內(nèi)容對(duì)大家的學(xué)習(xí)或者工作能帶來(lái)一定的幫助，如果有疑問(wèn)大家可以留言交流，謝謝大家對(duì)腳本之家的支持。

最新評(píng)論