“卡死”,说的比较口语化,换个视角就有思路了:卡死就是线程阻塞了。
说一下背景,项目都是 Java 应用,容器是 tomcat,应用发布就是 tomcat shutdown,然后 tomcat start,一般看启动日志 catalina.out 能看到启动时 spring ApplicationContext 启动过程中的各种日志,中间件的加载也会输出日志。所以启动卡死,看到的现象就是:打印了几行日志,就不往下继续打印了,应用一直处于不可用状态,直到发布超时。
从线程角度考虑,此时就是线程阻塞住了,就需要知道各个线程是在做什么,找出可疑的线程,顺藤摸瓜,看它在干什么。
一个实例
一直卡住,马上现场定位, 执行ps -ef | grep java
找出 tomcat 进程的 pid,然后执行 jstack [pid]
,因为 tomcat 是应用程序以 nobody
的身份启动的,所以提示权限不足,联系运维开通权限之后以 root 身份执行即可。
tomcat 发布启动的时候卡住,那就是主线程阻塞了,直接定位到以下线程堆栈:
"main" prio=10 tid=0x00007f99e0012800 nid=0x5246 waiting on condition [0x00007f99e74c5000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000e5a16058> (a java.util.concurrent.CountDownLatch$Sync)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:834)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:994)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1303)
at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:236)
at com.xyz.client.http.domain.PollFuture.get(PollFuture.java:54)
at com.xyz.client.http.PollWorker.get(PollWorker.java:107)
- locked <0x00000000e2901da8> (a com.xyz.client.http.PollWorker)
at com.xyz.client.http.ProjectManager.load(ProjectManager.java:200)
可以看到线程此刻处于 waiting 状态,在等待什么呢?waiting on condition [0x00007f99e74c5000]
条件等待,继续看堆栈,跟 CountDownLatch 有关,继续往栈下层看,com.xyz.client.http.domain.PollFuture.get
就是内部中间件的代码了,证明在 get 的时候阻塞在了 CountDownLatch.await()
方法上了。
到这一步,基本可以拿着堆栈找中间件相关的同事定位了,一般还可以找到此时中间件相关的一些日志,注意 ERROR
级别的日志,帮助他们更快找到问题。
作为思考,想想为什么阻塞在 await 了?了解 CountDownLatch
的原理就可以想到,一定是某个地方没有执行 latch.countDown()
操作,或者执行的次数不够。看 PollFuture
相关的代码,有如下声明,this.latch = new CountDownLatch(1);
这就更好定位了,证明 countdown 一次没执行成功,搜索执行 countdown 操作的地方,只有一处,如下:
public void setResult(Object result) {
this.result = result;
if(result == null) {
// no changes
return;
}
// do something
latch.countDown();
}
于是可以知道,这里 result == null
成立,往上层继续排查就是了。
最终定位下来,某个极端条件下,setResult()
前一步的请求出错,返回 error 信息,于是处理出来的 result 为空。
另一个例子
上面的例子是启动完全阻塞,永远不会继续。这个例子的现象是 tomcat 启动超时,表现就是断断续续输出日志,部分机器启动能成功,部分不成功,其实也不是完全不会启动,只是超过了timeout = 50000ms
的启动超时时长,发布系统就提示启动失败。
一样的思路,重新发布超时的机器,然后登录上去,jstack [pid]
输出若干线程信息,但是只看到有些线程 waiting ,多执行几次命令,又发现有时会继续执行。
联系架构的同事,也是一样的操作,执行若干次命令之后,观察几次输出的差异,看到有个线程会 sleep,这个线程此时的动作是:去远程拿一批服务注册项信息。顺着堆栈信息进一步定位发现,这个是 RPC 框架调用内部另一个组件的接口拿注册项信息,该接口的处理是:获取超时就 sleep 3s,然后再获取,重试 n 次。多番定位之后,升级组件解决问题。
由此可以看出,定位线程阻塞问题,一次输出甚至多次输出可能还不够,对引入的组件代码不熟悉,可能也无法确认问题。熟悉代码的人大致知道哪些地方,哪些后台线程可能阻塞。还有赖于平时多积累,遇到问题多请教。
总结
记得两年前,同事遇到过一次定时任务发布的时候启动卡死的问题,当时直觉可能跟线程死锁有关,不过我们都没有想到怎么入手排查。当时所有排查问题的思路都局限于“看代码”、设置断点、加日志,差别无非是,测试环境可以调试,就靠断点,生产环境要求严格、不能影响服务,所以只能靠日志和代码,总的来说,都局限在自己维护的业务代码中,进了断点,什么都好说,这类不知道怎么加断点的问题,就束手无策。
从线程阻塞类问题可以认识到,有时候要从整个运行时体系去考虑,甚至要从部署结构考虑,转换视角能发现更多问题,也会有更多方法。