诊断错误使用CountDownLatch和Future 造成的死锁

最近开发人员查看他们应用的监控数据, 发现有个数据指标出现异常. 这个数据指标表示当前tomcat正在忙的线程数目, 之前这个指标一直在0~3徘徊, 可是最近一周, 它已经缓慢的到达了30多, 这引起了他们的注意. 虽然没有造成任何问题, 但是还是想一探究竟.

背景介绍

这是一个内部服务, 它提供一些API供其它应用使用. 应用服务器的数目也不多, 消耗的CPU, 内存等都在很低的水平. 查看他们最近一段时间的 tomcat正在忙的线程数这个指标, 显示的情况如下:

首先, 这个tomcat正在忙的线程数表示当采集数据的时候, 都在忙, 也就是在处理业务请求, 不是在等任务的 tomcat 线程的数目. 它的多少表示当前应用服务器线程的忙碌程度.

从上面图中可以看到, 一开始它一直是一个稳定的数值, 并且值比较低, 但从某个时刻起, 它的数值就逐渐增多.

初步分析

看到服务线程数增加, CPU和内存使用量都没有增加, 难道是业务量增加了? 于是我们查看处理的业务的 TPS 数据, 发现业务流量稳定. 那么这些 tomcat 服务线程到底在忙啥?

带着这个问题, 我们查看 thead dump, 发现有很多 tomcat 业务线程都停在了这:

"DefaultThreadPool-40" #414 daemon prio=5 os_prio=0 tid=0x00007fc23401b800 nid=0x1dc waiting on condition [0x00007fc225dfd000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for   (a java.util.concurrent.CountDownLatch$Sync)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:837)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:999)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1308)
	at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:231)
	at com.tianxiaohui.demo.BusinessStakeholderBaseHandler.getParallelResponse(BusinessStakeholderBaseHandler.java:290)

从上面的代码栈看, 是在等待一个 CountDownLatch, 再结合上面的业务代码, 我们可以看到, 在这段业务逻辑中, 有一些并发的请求, 每一个请求都是单独一个线程在处理, 所以它想等这些单独的请求都执行完之后, 然后把结果合并到一块.

业务代码大概如下:

public Response getParallelResponse(List requests) {
    CountDownLatch countDownLatch = new CountDownLatch(requests.size());
    Future futureTaskList = new ArrayList();
    for (Request request : requests) {
        Request thatReq = request;
        futureTaskList.add(taskExecutor.add(new Callable(){
            public SingleResponse call(){
                doSomething(thatReq);
                countDownLatch.countDown();
            }
        }));
    }
    
    countDownLatch.await();
    SingleResponse rsps = null;
    for (Future future : futureTaskList) {
        try {
            rsps = future.get(600, TimeUnit.MILLISECONDS);
            doSomeProcessing(rsps);
        } catch (Exception e) {
            //error handling 
        }
    }
    
    ... 省略 ...
}

上面的业务代码有简略, 但大概框架如上.

总的来看不复杂, 先是分别去处理每一个子任务, 然后再等每个子任务都结束了再做合并.

从拿到的信息看, 我们的主线程卡在了 countDownLatch.await(), 也就是说: 它等待的子任务没有全部结束.

所以问题变成了: 哪个(些)子任务没有结束, 它为什么没有结束. 如果找到了这些答案, 问题就解决了.

查找线索

根据上面的初步分析, 这些没结束的子任务大概有2种情况:

对于第一种可能, 我们可以查看执行子任务的线程, 通过线程名字很快能确确认一组线程, 然后再观察这些线程的运行状态, 就能很快确定他们是不是一直在执行某个特定的未完成的任务, 还是任务已经结束. 经确认, 没有一直卡着的子任务. 所以第一种可能性排除.

所以, 我们很怀疑第二种可能性, 并且对于第二种, 我们见过很多次这样事情. 于是按照第二种情况去查找.

如果是第二种情况, 那么通常是由于发生了异常, 导致没有正常执行到 countDown() 方法. 照此推理, 如果发生了异常, 一般我们会打印出错日志和出错栈. 于是我们对我们所有的各种日志根据已有的信息去查找可能的出错栈. 但是最终一无所获. 也就是说, 它很有可能出错了, 但是没有打印出错栈.

查找陷入僵局.

进一步分析

于是我们重新分析这段代码, 对于这种线程池执行任务的方式, 假如发生了异常, 有2种可能:

对于上面第二种可能, 如果业务代码在 doSomething() 里面发生异常, 那么我们的 countDown() 一定会被执行, 所以就不可能出现这种问题. 所以很有可能是第一种方式.

对于第一种方式, 当线程池里的线程处理 Callable 的 call()的时候, 如果出现异常, 这时候, 它会记录异常, 并且当后面主线程尝试通过 get() 方法获得结果的时候, 它会抛出记录的异常, 这样主线程就知道子线程发生了异常.

再看我们的代码, 其实这里出现了一个矛盾点:

所以, 针对上面的这种情况, 主线程等待所有子线程都全部完成, 所以等待. 子线程发生了异常, 它希望通过主线程通过get()感知异常. 然而主线程需要执行完await()之后才能执行get(), 所以无法感知. 所以造成了死锁.

所以, 我们看到主线程等在了 countDownLatch.await() 方法, 子线程出错已经运行完.

如果我们进一步分析, 会发现其实这个 CountDownLatch 是不需要的, 因为这段代码的意图是想子线程分别去执行, 主线程等结果, 主线程通过各个 Future.get() 照样能等待各个子线程完成. 所以, 这个CountDownLatch 完全是多此一举, 并且如果没有这个 CountDownLatch 倒是不会出这个问题.

原因总结

CountDownLatch 本身可以实现多线程信息通信, 然后可以让等待的其它事件都先发生, 然后再执行某些动作. 同样 Future 也能实现多个线程之间的通信, 等待某些事情先发生, 然后再执行某些动作.

对于CountDownLatch无论是不是发生了异常, 都要 countDown 否则等待的结果都可能无法完成. 对于 Future 当发生了异常, 可以通过异常来通知等待的线程.

当我们处理多线程协调通信的时候, 一定要理清楚在各种情况下可能发生的情况, 不要出现死锁.