一次类加载死锁问题排查

上半年遇到了一次类加载死锁的问题,花了挺长时间才定位到具体原因,因此做个记录,以便下次遇到类似问题时可以快速定位。

问题背景

上半年的一个周五的夜晚,像往常一样上线发布服务,当发到中间某一台的时候突然出现告警,大量接口请求出现超时,从监控上看告警全部来自最后发布的那台机器,说明只是一台机器存在问题,遂将其从 rpc 服务列表中拉出。

通常情况下一台机器出现问题,大概率是这台机器本身或依赖的资源存在问题,于是排查了机器网络流量、磁盘IO、CPU占用率等监控数据,没有发现异常。查看服务依赖的 redis、数据库等资源监控,也都正常。

既然外部影响因素都排除了,没有发现问题点,那就需要看下是否是内部因素导致的。关于这次发布的变更点,只是新增了一个 rpc 接口,因为调用方还没发布,也就没有流量进来,排除是代码变更因素。接下来就是排查 jvm 情况,在服务拉出后,已经使用 jstack 命令获取到线程堆栈,通过分析发现线程大多数是 runnable 状态,除了线程数偏多外并未发现其他异常。

关于 java 线程 dump 分析的工具,https://fastthread.io/ 是一个不错的选择,各种线程的状态一目了然,最有意思的是,它提示从这次的堆栈中发现在一个问题,但是需要付费才能查看 🤣

后来机器重启后正常了,因为时间紧迫需要继续发布,当天并未定位到具体原因。

问题排查

问题排查还要从线程堆栈分析起来

线程堆栈

原始的线程堆栈不适合贴在这里,因此我写了个 demo,用来模拟当时的情况。下面是这个 demo 执行时的堆栈

1
2
3
4
5
6
"B" #12 prio=5 os_prio=31 tid=0x00007fd4e289e800 nid=0x3b03 in Object.wait() [0x000070000497c000]
java.lang.Thread.State: RUNNABLE
at com.gorden5566.demos.clazz.ClassLoadDeadLock$B.check(ClassLoadDeadLock.java:41)
at com.gorden5566.demos.clazz.ClassLoadDeadLock$B.<clinit>(ClassLoadDeadLock.java:35)
at com.gorden5566.demos.clazz.ClassLoadDeadLock$1.run(ClassLoadDeadLock.java:14)
at java.lang.Thread.run(Thread.java:748)

从这里可以看到以下几点:

  1. java 线程的状态为 RUNNABLE,说明它正在运行中
  2. in Object.wait() 表示在 wait set 中等待 moitor 锁
  3. 还有很重要的一点是, ClassLoadDeadLock$B.<clinit> 表明它正在执行类的初始化代码,这是在 jvm 加载完类之后并初始化时调用的

如果不熟悉各种 java 线程状态的堆栈展示情况或者印象有些模糊,只看上面的堆栈很难发现问题点。因此我们来回顾下几种常见的线程状态堆栈

几种常见的线程状态堆栈

在 java 中,通过执行一些调用可以改变线程的状态

Thread.sleep(10)

执行 Thread.sleep 可使当前线程处于 TIMED_WAITING 状态并等待指定时间,在这期间线程并不会释放持有的 monitor 锁。它的堆栈如下:

1
2
3
4
5
"main" #1 prio=5 os_prio=31 tid=0x00007f9f6b01b800 nid=0x2703 waiting on condition [0x000070000acca000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at com.gorden5566.demos.clazz.Wait.sleep(Wait.java:13)
at com.gorden5566.demos.clazz.Wait.main(Wait.java:9)

waiting on condition 表示线程在等待某种事件,这里是等待超时

TIMED_WAITING(sleeping) 表示是线程状态是 TIMED_WAITING,并且是 sleep 调用引起的

LockSupport.park()

LockSupport.park() 用于挂起当前线程,它会检测是否有许可证(permit),如果有则直接消费掉许可并继续执行,否则进入 WAITING 状态,等待 LockSupport.unpark() 生成许可。它的堆栈如下:

1
2
3
4
5
6
"main" #1 prio=5 os_prio=31 tid=0x00007ff98e800800 nid=0xd03 waiting on condition [0x0000700003078000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:304)
at com.gorden5566.demos.clazz.Wait.park(Wait.java:20)
at com.gorden5566.demos.clazz.Wait.main(Wait.java:12)

waiting on condition 表示线程在等待某种事件,这里是等待 unpark 操作生成许可证

WAITING(parking) 表示是线程状态是 WAITING,并且是 park 调用引起的

synchronized

synchronized 是 java 内置的锁机制使用的关键字,通过它可以实现临界资源的互斥访问。在等待进入 synchronized 代码块时的线程栈如下:

1
2
3
4
5
6
"Thread-0" #12 prio=5 os_prio=31 tid=0x00007fdc059c4800 nid=0x3e03 waiting for monitor entry [0x000070000aa36000]
java.lang.Thread.State: BLOCKED (on object monitor)
at com.gorden5566.demos.clazz.Wait.syn(Wait.java:27)
- waiting to lock <0x000000079591ec98> (a java.lang.Class for com.gorden5566.demos.clazz.Wait)
at com.gorden5566.demos.clazz.Wait$$Lambda$1/440434003.run(Unknown Source)
at java.lang.Thread.run(Thread.java:748)

waiting for monitor entry 表示在 monitor 的 entry set 中等待

BLOCKED (on object monitor) 表示线程状态是 BLOCKED 阻塞状态,on object monitor 说明是在 monitor 锁上等待

Object.wait()

Object.wait()Object.notify() 用于实现线程间的协作,调用 Object.wait() 时的堆栈如下

1
2
3
4
5
6
7
8
"main" #1 prio=5 os_prio=31 tid=0x00007fe2cc013000 nid=0x2803 in Object.wait() [0x0000700000b98000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x000000079591e3c0> (a java.lang.Class for com.gorden5566.demos.clazz.Wait)
at java.lang.Object.wait(Object.java:502)
at com.gorden5566.demos.clazz.Wait.wait1(Wait.java:34)
- locked <0x000000079591e3c0> (a java.lang.Class for com.gorden5566.demos.clazz.Wait)
at com.gorden5566.demos.clazz.Wait.main(Wait.java:15)

in Object.wait() 表示在 wait set 中等待

WAITING (on object monitor) 表示线程状态是 BLOCKED 阻塞状态,on object monitor 说明是在 monitor 锁上等待

Runnable

Runnable 并不是一个调用,它是线程的一个状态,对应堆栈栈如下:

1
2
3
4
5
"Thread-0" #12 prio=5 os_prio=31 tid=0x00007fba05191800 nid=0x4003 runnable [0x000070001115c000]
java.lang.Thread.State: RUNNABLE
at com.gorden5566.demos.clazz.Wait.runnable(Wait.java:43)
at com.gorden5566.demos.clazz.Wait$$Lambda$1/440434003.run(Unknown Source)
at java.lang.Thread.run(Thread.java:748)

runnable 表明是运行状态

RUNNABLE 表明线程状态是 RUNNABLE

问题堆栈分析

了解了常见的线程状态对应的堆栈后,再回过头来看下前面的问题堆栈

1
2
3
4
5
6
"B" #12 prio=5 os_prio=31 tid=0x00007fd4e289e800 nid=0x3b03 in Object.wait() [0x000070000497c000]
java.lang.Thread.State: RUNNABLE
at com.gorden5566.demos.clazz.ClassLoadDeadLock$B.check(ClassLoadDeadLock.java:41)
at com.gorden5566.demos.clazz.ClassLoadDeadLock$B.<clinit>(ClassLoadDeadLock.java:35)
at com.gorden5566.demos.clazz.ClassLoadDeadLock$1.run(ClassLoadDeadLock.java:14)
at java.lang.Thread.run(Thread.java:748)

第 2 行显示 java 线程状态为 RUNNABLE

从第 4 行显示当前正在执行类加载过程中的类初始化逻辑

结合这两点,我们可以猜想,当前线程正在执行类加载,我们刚好取到了这一时刻的线程快照,这也是当时排查问题时首先想到的。

再看第 1 行,这里就有些诡异了,它的显示是 in Object.wait(),表明线程正在 wait set 中等待,这与执行 Object.wait() 时的堆栈比较类似。

一个疑问是:一个线程不应该既在运行,又在 monitor 对象的 wait set 上等待,这不合理。

说到类的加载,顺便说一下,java 虚拟机是通过执行类构造器的 <clinit> 方法完成初始化的,在这个过程中会自动加锁,以保证类只会被初始化一次。

一次尝试

我们尝试下在类加载代码中加入 Object.wait() 逻辑,查看下堆栈,如下是测试代码:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
public class ClassLoadDeadLock {
public static void main(String[] args) {
A.check();
}

private static class A {
public synchronized static void check() {
try {
A.class.wait();
} catch (InterruptedException e) {
e.printStackTrace();
}
}
}
}

对应堆栈如下:

1
2
3
4
5
6
7
8
"main" #1 prio=5 os_prio=31 tid=0x00007fdfd0813800 nid=0x1703 in Object.wait() [0x000070000a549000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000007959268e8> (a java.lang.Class for com.gorden5566.demos.clazz.ClassLoadDeadLock$A)
at java.lang.Object.wait(Object.java:502)
at com.gorden5566.demos.clazz.ClassLoadDeadLock$A.check(ClassLoadDeadLock.java:15)
- locked <0x00000007959268e8> (a java.lang.Class for com.gorden5566.demos.clazz.ClassLoadDeadLock$A)
at com.gorden5566.demos.clazz.ClassLoadDeadLock.main(ClassLoadDeadLock.java:9)

可以看到 java 线程状态是 WAITING,与问题堆栈并不一样

Runnable 状态

假如说线程正在执行类加载过程中,那么 java 线程状态会是 RUNNABLE,不过这并不好模拟。更重要的是,即使是模拟出来,第一行也应该显示为 runnable

这就用到了 https://fastthread.io/ 的统计功能,因为不止一个线程处于类似的问题状态,这说明并不是我们运气好取到了类加载过程的快照,而是类在加载过程中卡在了这里。

查看相关代码,发现类的静态块里有比较多的逻辑,其中还涉及到从磁盘读取文件的操作,猜测可能是磁盘IO抖动导致类加载变慢,但并没有相关证据。后续的一次发布又出现了同样的问题,而且问题机器并不相同,因此可以排除磁盘抖动的可能性。

类加载死锁

事实上是类加载死锁导致的服务无响应,我们来看下 demo 代码

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
public class ClassLoadDeadLock {
public static void main(String[] args) {
new Thread(new Runnable() {
@Override
public void run() {
B.check();
}
}, "B").start();

A.check();
}

private static class A {
static {
check();
}

public static void check() {
// 这里触发B类的加载
B b = new B();
sleep();
}
}

private static class B {
static {
check();
}

public static void check() {
sleep();
// 这里触发A类的加载
A a = new A();
}
}

private static void sleep() {
try {
TimeUnit.SECONDS.sleep(2);
} catch (InterruptedException e) {
e.printStackTrace();
}
}
}

这里有两个类:A 和 B。类 A 有一个静态块,它内部会触发类 B 的加载。类 B 内也有一个静态块,它内部则会触发类 A 的加载。

main 方法中先会通过启动线程的方式触发类 B 的 check 方法,然后再在主线程中调用类 A 的 check 方法。

main线程B线程
B.check
sleep
A.check
加载B
B.check
加载A
A.check

可以看到 main 线程卡在了加载 B 的过程中,B 线程卡在了加载 A 的过程中,两个线程相互等待,导致无法完成类的加载

关于线程堆栈显示不一致问题

前面提到类加载死锁的堆栈中,第 1 行的 in Object.wait() 与第 2 行的 RUNNABLE 不一致,这应该是 jdk 的一个 bug。不过,正因为这个特征,我们也可以用于快速发现类加载死锁问题。

解决方法

上述场景中的循环加载依赖是产生死锁的必要条件,去掉循环依赖即可解决此问题。

此外还可以调整程序执行顺序,让类加载有序进行,避免并发导致的竞争问题。

对于本次问题,我们是通过调整代码的顺序解决的,调整后如下:单线程执行完 A.check() 方法,从而完成类 A、B 的加载

1
2
3
4
5
6
7
8
9
10
public static void main(String[] args) {
A.check();

new Thread(new Runnable() {
@Override
public void run() {
B.check();
}
}, "B").start();
}

上面还有一个点没有提到,就是死锁的问题不是必现,而是在某些情况下出现。这是因为在实际项目中,我们的线程 B 不是在主线程中直接启动的,它实际是 mq 的消费者在消费到消息的时候间接启动的。此外,代码执行的过程中也没有 demo 中的 sleep 逻辑。也就是说,当启动时消息消费的 qps 比较高,出现类加载死锁的概率就比较大。这也解释了为什么服务发布过程中偶尔会有一台无响应。

如何快速定位类加载死锁问题

这个才是我们的目的,就是当服务无响应的时候,如何确认是类加载死锁造成的?

如果容易重现,可以在 jvm 启动命令上添加参数 -verbose:class,用于打印类加载日志,这样在启动后你会看到类似如下的日志

1
2
[Loaded com.gorden5566.demos.clazz.ClassLoadDeadLock$B from file:/Users/gorden5566/github/demo/target/classes/]
[Loaded com.gorden5566.demos.clazz.ClassLoadDeadLock$A from file:/Users/gorden5566/github/demo/target/classes/]

然后卡在此处不再打印日志

更进一步,启动后使用 jstack -l <pid> 命令打印 java 线程堆栈,搜索 <clinit> 关键字,查看对应的线程状态,看是否具有如下特征

1
2
"B" #12 prio=5 os_prio=31 tid=0x00007fd4e289e800 nid=0x3b03 in Object.wait() [0x000070000497c000]
java.lang.Thread.State: RUNNABLE

到这里就可以确定是类加载死锁