前言
最近在某应用更新代码后部分机器发布失败，发布失败的机器上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 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一起启动：
|
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.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加载的日志：
|
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 nettynetty-buffer-4.1.5.Final.jarnetty-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.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下才能少犯错误。
- 基础组件：多考虑失败的情况，不吞异常；可能阻塞的操作考虑超时时间（自勉）
- 发布系统：能够添加一些规则，哪些包不能共存，比如上述问题中的netty-all和netty-common这些
- 容器隔离：隔离中间件使用的三方包和业务使用的三方包
总结
以上就是这篇文章的全部内容了，希望本文的内容对大家的学习或者工作能带来一定的帮助，如果有疑问大家可以留言交流，谢谢大家对服务器之家的支持。
原文链接：http://sel-fish.net/2017/04/12/tomcat-startup-hang/
