一次生产“死锁“程序排查的经历

回忆，刚毕业时候找工作面试时候，面试官在面试多线程知识时候，都喜欢问

“你知道什么是死锁吗？”，如何手写一个死锁程序？

答：“死锁就是两个线程互为等待对方的资源，然后巴拉巴拉说一大堆”

后来对死锁也更深入理解了，死锁必要条件就是一个线程持有2把锁以上。

加锁解锁顺序不一致，等等就会造成死锁。

虽然知道了这些理论，但真实很多人在实际开发时候从来没有写过一次死锁程序，也许很多程序员每日都在CRUD，或许连多线程如何使用都快忘记了。

而我竟然在生产写了死锁的程序了，虽然最后是排查且解决的死锁的问题，但是我没有真正找到死锁的原因。

直接正题，项目系统功能就是，程序使用线程查询数据库某表，将表数据进行消费，发送到其他线程池多线程并发执行，简单来说就是一个使用数据库实现的消息中间件的功能，主要为解决业务请求能异步高性能处理。这里涉及了多线程问题

因项目系统某个功能因资源占用过多和性能问题(涉及公司源码不贴)

我对原本程序做了修改优化，然后上线在生产运行，没跑几天，整个对应的程序功能发现入队的消息无法消费了。现场客服人员说系统出问题啦，我心想会不会死锁了(其实开发时候，我都会盯着eclipse的debug所有线程执行信息的窗口，感觉有发生过死锁，就像有一个画面，可再次尝试却消失不见，我以为是我错觉，就没太在意了),

直接让生产运维人员导出jboss的jstack日志，具体步骤如下:

1. jboss的机器打开cmd，输入 jps -lv 找到jboss 的进程号PID
2. jstack PID >>e:\e.txt 导出线程信息

得到了jstack日志后分析（不暴露类名等信息，我都替换了），最后找到关键的一行Found one Java-level deadlock 死锁了，如下:

Found one Java-level deadlock:
=============================
"线程号-pool-33-thread-31":
  waiting to lock monitor 0x000000001ed0f0a0 (object 0x00000000aa74b648, a 包名类名),
  which is held by "线程号-pool-31-thread-35"
"线程号-pool-31-thread-35":
  waiting for ownable synchronizer 0x00000000aa74b848, (a java.util.concurrent.locks.ReentrantLock$NonfairSync),
  which is held by "线程号-pool-31-thread-32"
"线程号-pool-31-thread-32":
  waiting to lock monitor 0x000000001ed0f0a0 (object 0x00000000aa74b648, a 包名类名),
  which is held by "线程号-pool-31-thread-35"

Java stack information for the threads listed above:
===================================================
"线程号-pool-33-thread-31":
    at 包名类名(类名.java:278)
    - waiting to lock <0x00000000aa74b648> (a 包名类名)
    at 包名类名(类名.java:186)
    at 包名类名.run(类名.java:172)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
    at java.lang.Thread.run(Thread.java:619)
"线程号-pool-31-thread-35":
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000aa74b848> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:747)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:778)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1114)
    at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:186)
    at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:262)
    at java.util.concurrent.ThreadPoolExecutor.getActiveCount(ThreadPoolExecutor.java:1591)
    at 包名.类名.notifyCustomTask(类名.java:45)
    at 包名.类名.executeTask(类名.java:178)
    - locked <0x00000000aa74b648> (a 包名类名)
    at 包名.类名.executeTask(类名.java:66)
    at 包名类名.run(类名.java:170)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
    at java.lang.Thread.run(Thread.java:619)
"线程号-pool-31-thread-32":
    at 包名.类名.executeTask(类名.java:178)
    - waiting to lock <0x00000000aa74b648> (a 包名类名)
    at 包名.类名.executeTask(类名.java:66)
    at 包名类名.run(类名.java:170)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
    at java.lang.Thread.run(Thread.java:619)

Found 1 deadlock.

可以发现两条线程都在等待  waiting to lock <0x00000000aa74b648> 该地址的锁资源信息，而对应获取前者锁资源的线程却 parking to wait for  <0x00000000aa74b848> 也在等待，但奇怪的是我在整个jstack日志中找不到0x00000000aa74b848地址的资源了

所以我最终无法知道是哪里的线程持有该锁资源，导致了死锁。

最后我跟踪源码，发现了我在通知线程池处理，在线程池内部发现了一个锁，而我调用执行线程任务时候使用了synchronized同步块(主要是修改代码时候忘记删除了)，最终简单模拟下伪代码(真实代码太过于复杂，且代码不外露)

synchronized (thread) {
	threadPool.execute(this);
}

 

在跟踪源码可以发现execute方法内部有一个ReentrantLock 锁，如下:

  private void ensureQueuedTaskHandled(Runnable command) {
        final ReentrantLock mainLock = this.mainLock;
        mainLock.lock();
        boolean reject = false;
        Thread t = null;
        try {
            int state = runState;
            if (state != RUNNING && workQueue.remove(command))
                reject = true;
            else if (state < STOP &&
                     poolSize < Math.max(corePoolSize, 1) &&
                     !workQueue.isEmpty())
                t = addThread(null);
        } finally {
            mainLock.unlock();
        }
        if (reject)
            reject(command);
        else if (t != null)
            t.start();
    }

此时我就见鬼了，加锁顺序是一致的，解锁顺序是一致的为什么能死锁(也可能真实不是如我描述的一般)，最终我将外层的 synchronized代码块修饰给去除了，我破坏了死锁必要条件，那么程序没有死锁了。

事情也过去很久了(写这篇时候，距发生时间已经好多个月了)，现在回忆这段程序，感觉还是个迷，主要是jstack日志并没有完全显示死锁资源占用问题。

虽然死锁问题我解决了，可我还是无法确定真实的原因，我也自己去手写一个死锁程序， 就是让两个线程互相等待对方资源，此时jstack日志是能显示死锁的资源被谁占用的，

最后，我猜测，会不会有一种可能，那就是死锁的0x00000000aa74b848地址锁资源被另外一条线程占用了，而那条线程可能已经死亡了(或者躲起来了)，jstack日志并没有找到该线程的信息(系统是十几年前的老系统了，很复杂，ejb，等多个工程一起部署)，

哎，最终记录此篇，如冰冻人一样，希望多年后我还能回忆模拟找到真相。