死锁案例分享

小灰灰 2020-05-14 15:52 858阅读 0赞

1、生产环境下的死锁问题可遇不可求，绝对是软件生涯中的一笔宝贵财富

在实际开发中，死锁的案例可遇不可求。有些人可能开发了5年甚至10年，也没有在生产环境下遇到过死锁案例。如果真的遇到了死锁问题，你应该庆幸，先不要担心能不能解决，毫无疑问的一点是在解决死锁问题的过程中，你对多线程的认识将会得到默大的提升。

2、生产环境下的死锁问题通常是很复杂的

不过生产环境下的死锁问题的解决回比你写一个demo演示的死锁问题复杂的多，会有很多额外的干扰因素。

- 死锁日志不全
- 锁都不是自己编写的，而是因为误使用导致的
- 其他的锁的干扰
- JDK版本问题
- ...

本文分享笔者在实际开发中遇到过的一个死锁问题的解决历程和需要注意的问题。

该死锁问题是一个消息推送服务上遇到的，我按照自己在实际过程中解决死锁的步骤一步一步讲解。

1、死锁日志是如何获取到的

2、获取详细的死锁日志

3、如何定位两段导致死锁问题的代码位置

4、如何分析不同线程运行的代码为什么会导致死锁

5、JDK版本对分析问题的影响。

**一、死锁日志的获取**

通常情况下，为了监控服务在运行时候的状况，我们通常会进行监控，没有监控，程序就是裸奔，监控程序一般都是使用JMX的API获取的。通过JMX，我们可以不断检测程序中出现的各种问题，包括但不局限于死锁。当检测到问题的时候，以短信或者邮件的方式通知开发人员，这样就能够让开发人员及时的了解程序运行中遇到的问题。以下是笔者公司中收到的通过JMX检测到线程死锁信息邮件主要内容：

```shell
deadLockedThreadCount:2

deadLockedThreadInfo:

"MonitoringThread-2598" Id=2102062 WAITING on java.util.concurrent.locks.ReentrantLock$NonfairSync@59a7a6a0 owned by "apns-pool-thread-10" Id=1045

at sun.misc.Unsafe.park(Native Method)

-  waiting on java.util.concurrent.locks.ReentrantLock$NonfairSync@59a7a6a0

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.acquireQueued(AbstractQueuedSynchronizer.java:867)

at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1197)

at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:214)

at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:290)

at sun.security.ssl.SSLSocketImpl.writeRecord(SSLSocketImpl.java:799)

...

"apns-pool-thread-10" Id=1045 BLOCKED on sun.security.ssl.SSLSocketImpl@3ba6de2b owned by "MonitoringThread-2598" Id=2102062

at sun.security.ssl.SSLSocketImpl.getConnectionState(SSLSocketImpl.java:649)

-  blocked on sun.security.ssl.SSLSocketImpl@3ba6de2b

at sun.security.ssl.SSLSocketImpl.isClosed(SSLSocketImpl.java:1446)

at java.net.Socket.getTcpNoDelay(Socket.java:965)

at sun.security.ssl.BaseSSLSocketImpl.getTcpNoDelay(BaseSSLSocketImpl.java:345)

at sun.security.ssl.SSLSocketImpl.writeRecordInternal(SSLSocketImpl.java:819)

at sun.security.ssl.SSLSocketImpl.writeRecord(SSLSocketImpl.java:801)

at sun.security.ssl.AppOutputStream.write(AppOutputStream.java:122)

-  locked sun.security.ssl.AppOutputStream@381f1f07

at java.io.OutputStream.write(OutputStream.java:75)

...

Number of locked synchronizers = 2

- java.util.concurrent.ThreadPoolExecutor$Worker@1efa3571

- java.util.concurrent.locks.ReentrantLock$NonfairSync@59a7a6a0
```

首先死锁问题在这个邮件中已经描述出来。即MonitoringThread-2598线程在等待一个ReentrantLock锁，apns-pool-thread-10在阻塞在一个SSLSocketImpl对象锁上面。以下是分析过程：

**问题1、导致死锁的原因**

通过简单分析就可以知道导致死锁的原因是：

MonitoringThread-2598线程获取到了SSLSocketImpl对象锁，但是需要ReentrantLock锁

apns-pool-thread-10获取到ReentrantLock，需要SSLSocketImpl对象锁。

**问题2、获取更详细的死锁线程栈信息**

分析完了死锁的原因，我们希望定位导致死锁的代码出现的地方。不过，读者可以看到，两个死锁线程的线程栈信息显示的API都是jdk中自带的包中API，无法定位在我们的代码中到底是哪些类最终调用了这些方法。这并不是笔者有意删除了部分栈信息，而是因为通过JMX获取到线程栈信息默认只会打印8行，根本原因是因为JMX使用的是ThreadInfo这个类获取栈内容，而默认情况下只能获取8行(可以通过覆写toString方法打印全部的信息)。

虽然，在创建线程的时候，我们指定了线程名称的前缀，apns-pool-thread-10，MonitoringThread-2598中红色部分是线程名称前缀。理论上，我们可以通过这两个关键字，在自己的代码中搜索，从而定位导致死锁的代码。不过这个难度太大，笔者虽然进行了尝试，但是以失败告终。

幸运的是，在一个星期之后，这个问题又复现了，笔者有机会获取到另外一份更详细的线程栈信息。在收到报警时，通过jstack命令获取到死锁日志(之前因为收到报警立即重启了服务器，导致无法使用jstack命令获取到详细的日志)。

```shell
Found one Java-level deadlock:

=============================

"MonitoringThread-1703":

waiting for ownable synchronizer 0x00000007b56bc020, (a java.util.concurrent.locks.ReentrantLock$NonfairSync),

which is held by "apns-pool-thread-10"

"apns-pool-thread-10":

waiting to lock monitor 0x00007f9799a9e758 (object 0x00000007b29c1b88, a sun.security.ssl.SSLSocketImpl),

which is held by "MonitoringThread-1703"

Java stack information for the threads listed above:

===================================================

"MonitoringThread-1703":

at sun.misc.Unsafe.park(Native Method)

- parking to wait for  <0x00000007b56bc020> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)

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.acquireQueued(AbstractQueuedSynchronizer.java:867)

at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1197)

at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:214)

at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:290)

at sun.security.ssl.SSLSocketImpl.writeRecord(SSLSocketImpl.java:799)

at sun.security.ssl.SSLSocketImpl.writeRecord(SSLSocketImpl.java:672)

at sun.security.ssl.SSLSocketImpl.sendAlert(SSLSocketImpl.java:2005)

at sun.security.ssl.SSLSocketImpl.fatal(SSLSocketImpl.java:1879)//同步方法

- locked <0x00000007b29c1b88> (a sun.security.ssl.SSLSocketImpl)

at sun.security.ssl.SSLSocketImpl.fatal(SSLSocketImpl.java:1842)//同步方法

- locked <0x00000007b29c1b88> (a sun.security.ssl.SSLSocketImpl)

at sun.security.ssl.SSLSocketImpl.handleException(SSLSocketImpl.java:1806)//同步方法

- locked <0x00000007b29c1b88> (a sun.security.ssl.SSLSocketImpl)

at sun.security.ssl.SSLSocketImpl.handleException(SSLSocketImpl.java:1751)

at sun.security.ssl.AppInputStream.read(AppInputStream.java:113)//同步方法，这是一个干扰

- locked <0x00000007b9b8eb38> (a sun.security.ssl.AppInputStream)

at java.io.DataInputStream.read(DataInputStream.java:149)

at com.pajk.archery.iospush.impl.ApnsConnectionImpl$2.readPacket(ApnsConnectionImpl.java:233)

at com.pajk.archery.iospush.impl.ApnsConnectionImpl$2.run(ApnsConnectionImpl.java:138)

at java.lang.Thread.run(Thread.java:744)

"apns-pool-thread-10":

at sun.security.ssl.SSLSocketImpl.getConnectionState(SSLSocketImpl.java:649)

- waiting to lock <0x00000007b29c1b88> (a sun.security.ssl.SSLSocketImpl)

at sun.security.ssl.SSLSocketImpl.isClosed(SSLSocketImpl.java:1446)

at java.net.Socket.getTcpNoDelay(Socket.java:965)

at sun.security.ssl.BaseSSLSocketImpl.getTcpNoDelay(BaseSSLSocketImpl.java:345)

at sun.security.ssl.SSLSocketImpl.writeRecordInternal(SSLSocketImpl.java:819)

at sun.security.ssl.SSLSocketImpl.writeRecord(SSLSocketImpl.java:801)

at sun.security.ssl.AppOutputStream.write(AppOutputStream.java:122)

- locked <0x00000007b9b83e10> (a sun.security.ssl.AppOutputStream)

at java.io.OutputStream.write(OutputStream.java:75)

at com.pajk.archery.iospush.impl.ApnsConnectionImpl.sendMessage(ApnsConnectionImpl.java:307)

- eliminated <0x00000007ad5541b0> (a com.pajk.archery.iospush.impl.ApnsConnectionImpl)

at com.pajk.archery.iospush.impl.ApnsConnectionImpl.sendMessage(ApnsConnectionImpl.java:292)

- locked <0x00000007ad5541b0> (a com.pajk.archery.iospush.impl.ApnsConnectionImpl)

at com.pajk.archery.iospush.impl.ApnsPooledConnection$2.call(ApnsPooledConnection.java:57)

at com.pajk.archery.iospush.impl.ApnsPooledConnection$2.call(ApnsPooledConnection.java:55)

at java.util.concurrent.FutureTask.run(FutureTask.java:262)

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)

at java.lang.Thread.run(Thread.java:744)

Found 1 deadlock.
```

这是两个完整的线程栈信息，判断依据很简单，因为线程都是从run方法开始运行的，我们可以看到这两个线程日志最后的显示的都是run方法。

**MonitoringThread-1703线程调用顺序分析：**

此时，我们可以知道MonitoringThread-1703线程是因为我们自己编写的类的方法调用顺序：

ApnsConnectionImpl类的readPacket方法-->...-->SSLSocketImpl.handleException(获取到SSLSocketImpl对象锁)-->SSLSocketImpl.fatal(1842行：重入)-->SSLSocketImpl.fatal(1879行:重入)-->SSLSocketImpl.writeRecord-->ReentrantLock.lock.--> parking to wait for... ReentrantLock$NonfairSync(等待)。

可以看到获取到SSLSocketImpl对象锁之后，进行了几次重入，调用了writeRecord方法，而由于在writeRecord方法中想要调用ReentrantLock.lock，因为没有获取到锁，所以进入了等待。

ReentrantLock是一种可重入的独占锁，其底层是通过AQS实现，AQS是又是LockSupport和Unsafe实现，ReentrantLock.lock方法最终调用的是Unsafe.park方法，这会阻塞当前线程。因此最终有这样的线程栈日志

at sun.misc.Unsafe.park(Native Method)	- parking to wait for  <0x00000007b56bc020> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)

简单分析之后，需要通过源代码确认：

```java
//DataInputStream in是将SSLSocketImpl类获取到的InputStream进行了封装
private boolean readPacket(final DataInputStream in,
      final byte[] bytes) throws IOException {
   final int len = bytes.length;
   int n = 0;
   while (n < len) {
      try {
         int count = in.read(bytes, n, len - n);//问题代码
         if (count < 0) {
            throw new EOFException("EOF after reading " + n
                  + " bytes of new packet.");
         }
         n += count;
      } catch (IOException ioe) {
         if (n == 0) {
            log.warn("read packet count is zero "+ ioe.getMessage());
            return false;
         }
         throw new IOException("Error after reading " + n
               + " bytes of packet", ioe);
      }
   }
   return true;
}
```

其中问题代码就是这一行：

```java
int count = in.read(bytes, n, len - n);
```

in是DataInputStream类型，将SSLSocketImpl类获取到的InputStream进行了封装。因此in的read方法最终还是调用的是SSLSocketImpl.getInputStream方法获取到的。in.read在内部会依次调用-->DataInputStream.read-->AppInputStream.read-->SSLSocketImpl.handleException-->....-->SSLSocketImpl.writeRecord(SSLSocketImpl.java:799)-->...

我们刚才说了，SSLSocketImpl.writeRecord调用了ReentrantLock.lock方法，此时我们通过源码确认：

```java
void writeRecord(OutputRecord var1, boolean var2) throws IOException {
    while(true) {
        .....
 
        if(!var1.isEmpty()) {
            if(var1.isAlert((byte)0) && this.getSoLinger() >= 0) {
                ....
            } else {
                this.writeLock.lock();//加锁，writeLock类型为ReentrantLock。
 
                try {
                    this.writeRecordInternal(var1, var2);
                } finally {
                    this.writeLock.unlock();//解锁
                }
            }
        }
 
        return;
    }
```

通过代码分析，我们已经确认了MonitoringThread-1703是先获取到SSLSocketImpl对象锁，然后在 this.writeLock.lock()时被阻塞。此时我们分析另外一个线程。