背景
最近压测Cassandra的时候,发现一个Cassandra进程一直没有完成初始化。经过排查后发现是死锁问题,这篇文章将会带领大家回顾整个排查过程,学习如何排查Java死锁问题,是一个非常值得学习的经验。
调查过程
1.问题发现
首先是启动后,通过Cassandra命令nodetool netstats观察何时进入NORMAL状态。如下图所示:
但是过了很久都没有进入NORMAL,一直处于STARTING状态。
2.jstack排查
想要知道为啥一直处于STARTING状态,当然是用Jstack去观察进程到底在做什么。
jstack显示主线程处于WAITING状态。这符合我们观察到的现象,因为确实一直卡在STARTING状态没有走下去。使主线程卡住的地方是AbstractCommitLogSegmentManager.awaitAvailableSegment(),这时候需要去看具体的源码。看看这个wait调用会由谁通知解开。
3.分析源码
源码分析后得知:awaitAvailableSegment()在等待另一个线程创建Segment,也就是等待生产者创建好对应资源。
而这个生产者的线程叫COMMIT-LOG-ALLOCATOR。所以我们再去看一眼刚才的jstack,看看这个线程在做什么。预想中的情况应该是这个生产者线程也卡在某个地方,或者因为未知异常退出了(退出时候没能通知等在awaitAvailableSegment()上的线程)。
4.排查问题线程
在jstack中找到COMMIT-LOG-ALLOCATOR:
乍一看,蒙圈了。这个线程处于RUNNABLE状态,完全不符合我们预想中的情况。那这个线程明明在“运行”,为何没有把对应的Segment资源生产出来呢?一种可能是死循环了,逻辑没有往下走。通过多次jstack发现,stack总是在133这行。并且通过cat /proc//task//stat确认,这个线程确实没有在运行,卡在133这行。
这里获取tid的方法是通过将jstack中16进制的nid转换成10进制,printf %d 0x4b7f。输出:19327
然后我们继续,看133这行代码:
133这行代码,是非常简单的一个静态函数调用CommitLog.handleCommitError(),没有涉及任何锁。为何会卡死在这行上?为何jstack看到的状态却是RUNNABLE?
Java层面的工具已经不能解决问题了。这时候通过pstack命令,查看堆栈:
我们发现线程实际卡在JVM的InstanceKlass::initialize调用上,也就是卡在类初始化上了。第一反应就是类初始化死锁问题,回顾下133这行代码,调用了CommitLog.handleCommitError(),也就是访问到了CommitLog这个类。然后我们再去jstack里看一下,哪个线程在负责CommitLog的初始化,并且一直没初始化好。没错就是最开始我们看到卡住的主线程!
jstack中的clinit是表示进入类初始化。
5.水落石出
主线程 -> 进入CommitLog初始化流程 -> 调用awaitAvailableSegment() -> 等待 COMMIT-LOG-ALLOCATOR 完成资源生产
此时CommitLog类还没有初始化完成,主线程持有CommitLog类的锁。
COMMIT-LOG-ALLOCATOR -> 生产资源 -> 遇到异常,走到catch逻辑(133行)-> 133行访问CommitLog类 -> CommitLog仍然在初始化 -> 死锁产生
总结
Java类初始化死锁,往往是由于多个静态类相互之间的关系设计不好,互相访问,导致可能出现初始化时候死锁。排查这类问题,一般都是jstack,然后再结合代码分析。顺便提一下,前面提到的RUNNABLE状态,并不能表示线程就在运行,虽然大多数时候是。
Thread state for a runnable thread. A thread in the runnable state is executing in the Java virtual machine but it may be waiting for other resources from the operating system such as processor.
摘自:
https://docs.oracle.com/javase/8/docs/api/java/lang/Thread.State.html
后续
最后这个问题,已经贡献到社区 CASSANDRA-15295 。如果你想使用稳定的Cassandra服务,欢迎试用阿里云Cassandra服务。如果你对Cassandra感兴趣,也欢迎加入社区讨论,扫描下方二维码进入。
钉钉扫码加入Cassandra社区大群