一次类加载死锁问题排查

发表于 分类于 Waline： 阅读次数：

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

问题背景

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

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

相关文章
  • 2019-02-21
    Java 线程状态

    Java 线程共有 6 种状态，在任意时刻只能处于其中一种状态，随着代码的执行状态也会发生变化。