【Java类初始化死锁】记一次Cassandra死锁问题排查

简介： 背景最近压测Cassandra的时候，发现一个Cassandra进程一直没有完成初始化。经过排查后发现是死锁问题，这篇文章将会带领大家回顾整个排查过程，学习如何排查Java死锁问题，是一个非常值得学习的经验。

背景

最近压测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/<pid>/task/<tid>/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状态，并不能表示线程就在运行，虽然大多数时候是。

购买下单