过程

最近写的 IM 项目中，要实现一个类似 TCP 消息缓冲区来保证通信消息的时序性。实现完成后，我编写了测试代码进行测试，发现测试过程中时不时会出现程序阻塞情况，连着好几天的排查，最终找到了问题所在。

首先，先是使用 VisualVM 工具，查看程序阻塞时 JVM 的内存状况，发现内存基本上稳定没有变化。然后通过 jstack 查看当前运行的 Java 进行，也排查了死锁的可能。为了进一步分析，将线程的快照输出到文件。
image.png
通过线程的快照文件（thread dump）可以看到，线程池中的所有线程都处于 WAITING 状态，且是在 BlockingQueue 的 take 位置处阻塞的，也就是说队列是空的，没有任务要执行。使用到线程池的地方是在测试代码中：

  1. // 这里是测试代码，使用线程池是为了模拟并发操作
  2. threadPool.execute({ ->
  3.     try {
  4.         Thread.sleep(4)
  5.         def f = clientAckWindow.offer(c.getId(),
  6.                                       Internal.InternalMsg.Module.CLIENT,
  7.                                       Internal.InternalMsg.Module.CONNECTOR,
  8.                                       ctx, c, { processMsg.add(it) })
  9.         f.thenApply({
  10.             println "--- count down one, msgId=" + finalI
  11.             countDownLatch.countDown()
  12.         })
  13.     } catch (Exception e) {
  14.         println e.printStackTrace()
  15.     }

这里是想模拟多个用户发送消息，所以用线程池来模拟并发的状况，然后 clientWindow 中的 offer 操作内部本身会开多一个线程进行逻辑的处理，来达到异步处理的效果。
image.png
所以问题应该出现在 offer 函数的内部设计中，offer 的逻辑处理使用的是 CompletableFuture 来创建异步任务来达到并发处理的目的，CompletableFuture 中默认情况下使用的就是 ForkJoinPool 来执行任务，所以进一步需要关注线程快照中与 ForkJoinPool 相关的信息。
image.png
thread dump 中出现了 7 个 ForkJoinPool 的 worker 线程，每一个的状态都是和上边一样。可以发现 worker 也是空闲的，没有任务要执行。我就奇了怪了，既然没有任务要执行，那么程序到底在等什么，为什么不退出？到此，我感觉自己应该简化一下这个情况，说不定更能够看清状况，然后我就写了一个类似功能的 demo

  1. public class Test {
  3.     public AtomicInteger ai = new AtomicInteger(0);
  5.     public static void main(String[] args) {
  6.         Test src = new Test();
  7.         int n = 100;
  8.         ExecutorService pool1 = Executors.newFixedThreadPool(2);
  9.         ExecutorService pool2 = Executors.newFixedThreadPool(2);
  10.         CountDownLatch latch = new CountDownLatch(n);
  12.         for (int i = 0; i < n; i++) {
  13.             pool1.execute(() -> { // 模拟多个消息同时发送
  14.                 pool2.execute(() -> { // 模拟异步处理每一个消息
  15.                     src.ai.incrementAndGet();
  16.                     latch.countDown();
  17.                 });
  18.             });
  19.         }
  20.         try {
  21.             latch.await();
  22.             System.out.println("【finish】result=" + src.ai.get());
  23.         } catch (InterruptedException e) {
  24.             e.printStackTrace();
  25.         }
  26.     }
  27. }

程序运行后，打印出正确的结果，但是程序也是不退出，成功复现了阻塞的情况。
image.png
我再看了一眼这个简化版的 demo，突然灵光一现：原来，我的线程池没有关闭！！！在 demo 的最后添加 pool1 和 pool2 的 shutdown 调用，程序终于成功完成后退出。然后我回到测试代码中在最后加上线程池的关闭操作，然后又反复用万级的消息数据测试了十多次，果然没有程序阻塞一直不结束的情况了。

总结

排查了这么久，耗费了我这么多精力，原来最终的问题竟然出现在我写的测试代码中，哎，真是有些心累呢。但是这个问题排查的过程对于我而言还是有一定意义的，总结一下就是：

  • 通过 VisualVM 查看实时的 JVM 内存状况，和线程的运行状态
  • 通过 jstack 查看线程的调用栈信息，看看是否有死锁的报告
  • 必要的时候，将整个问题简化成一个小的代码样例，方便分析
  • 如果以上都没有发现问题，那么问题可能不在当前这个程序本身，可能时本程序调用到的服务、资源出现的问题