这个代码的逻辑非常简单首先我们搞了一个线程池然后起一个 for 循环往线程池里面仍了 5 个任务这是核心逻辑。对于这几个任务我们的这个自定义线程池处理起来不能说得心应手吧至少也是手拿把掐。其他的 StopWatch 是为了统计运行时间用的。 至于 CountDownLatch你可以理解为在业务流程中需要这五个任务都执行完成之后才能往下走所以我搞了一个 CountDownLatch。这个代码运行起来是没有任何问题的我们在日志中搜索“执行完成”也能搜到 5 个这个结果也能证明程序是正常结束的同时可以看到运行时间是 4s。示意图大概是这样的然后歪师傅看着这个代码发现了一个可以优化的地方这个地方从数据库捞出来的数据它们之间是没有依赖关系的也就是说它们之间也是可以并行执行的。所以歪师傅把代码改成了这样在异步线程里面去处理这部分从数据库中捞出来的数据并行处理加快响应速度。对应到图片大概就是这个意思把程序运行起来之后日志变成了这样我们搜索“执行完成”也能搜到 5 个对应输出。而且我们就拿“任务2”来说当前线程pool-1-thread-3,—【任务2】开始执行—当前线程pool-1-thread-3,—【任务2】执行完成—当前线程pool-1-thread-1,【任务2】开始处理数据1当前线程pool-1-thread-2,【任务2】开始处理数据2从日志输出来看任务 2 需要处理的两个数据确实是在不同的异步线程中处理数据也实现了我的需求。但是程序运行直接就是到了 9.9ms这个优化这么牛逼的吗从 4s 到了 9.9ms稍加分析你会发现这里面是有问题的。那么问题就来了到底是啥问题呢你也分析分析大概是啥问题别老是想着直接找答案啊。问题就是由于转异步了所以 for 循环里面的任务中的 countDownLatch 很快就减到 0 了。于是 await 继续执行所以很快就输出了程序运行时间。然而实际上子任务还在继续执行程序并没有真正完成。9.9ms 只是任务提交到线程池的时间每个任务的数据处理时间还没算呢从日志输出上也可以看出在输出了 StopWatch 的日志后各个任务还在处理数据。这样时间就显得不够真实。那么我们应该怎么办呢很简单嘛需要子任务真正执行完成后父任务的 countDownLatch 才能进行 countDown 的动作。具体实现上就是给子任务再加一个 countDownLatch 栅栏我们希望的运行结果应该是这样的当前线程pool-1-thread-3,—【任务2】开始执行—当前线程pool-1-thread-1,【任务2】开始处理数据1当前线程pool-1-thread-2,【任务2】开始处理数据2当前线程pool-1-thread-3,—【任务2】执行完成—即子任务全部完成之后父任务才能算执行完成这样统计出来的时间才是准确的。思路清晰非常完美再次运行观察日志我们会发现呃怎么回事日志怎么不输出了是的就是不输出了。不输出了就是踩到这个坑了。不论你重启多少次都是这样日志不输出了程序就像是卡着了一样。坑在哪儿上面这个 Demo 已经是我基于遇到的生产问题极力简化后的版本了。现在这个坑也已经呈现在你眼前了。我们一起来分析一波。首先我问你真的在线上遇到这种程序“假死”的问题你会怎么办早几年歪师傅的习惯是抱着代码慢慢啃试图从代码中找到端倪。这样确实是可以但是通常来说效率不高。现在我的习惯是直接把现场 dump 下来分析现场。比如在这个场景下我们直观上的感受是“卡住了”那就 dump 一把线程管它有枣没枣打一杆子再说通过 Dump 文件可以发现线程池的线程都在 MainTest 的第 30 行上 parking 处于等待状态那么第 30 行是啥玩意这行代码在干啥countDownLatchSub.await();是父任务在等待子任务执行结束运行 finally 代码把 countDownLatchSub 的计数 countDown 到 0才会继续执行所以现在的现象就是子任务的 countDownLatchSub 把父任务的拦住了。换句话说就是父任务被拦住是因为子任务的 finally 代码中的 countDownLatchSub.countDown() 方法没有被执行。好那么最关键的问题就来了为什么没有执行
这个代码的逻辑非常简单首先我们搞了一个线程池然后起一个 for 循环往线程池里面仍了 5 个任务这是核心逻辑。对于这几个任务我们的这个自定义线程池处理起来不能说得心应手吧至少也是手拿把掐。其他的 StopWatch 是为了统计运行时间用的。 至于 CountDownLatch你可以理解为在业务流程中需要这五个任务都执行完成之后才能往下走所以我搞了一个 CountDownLatch。这个代码运行起来是没有任何问题的我们在日志中搜索“执行完成”也能搜到 5 个这个结果也能证明程序是正常结束的同时可以看到运行时间是 4s。示意图大概是这样的然后歪师傅看着这个代码发现了一个可以优化的地方这个地方从数据库捞出来的数据它们之间是没有依赖关系的也就是说它们之间也是可以并行执行的。所以歪师傅把代码改成了这样在异步线程里面去处理这部分从数据库中捞出来的数据并行处理加快响应速度。对应到图片大概就是这个意思把程序运行起来之后日志变成了这样我们搜索“执行完成”也能搜到 5 个对应输出。而且我们就拿“任务2”来说当前线程pool-1-thread-3,—【任务2】开始执行—当前线程pool-1-thread-3,—【任务2】执行完成—当前线程pool-1-thread-1,【任务2】开始处理数据1当前线程pool-1-thread-2,【任务2】开始处理数据2从日志输出来看任务 2 需要处理的两个数据确实是在不同的异步线程中处理数据也实现了我的需求。但是程序运行直接就是到了 9.9ms这个优化这么牛逼的吗从 4s 到了 9.9ms稍加分析你会发现这里面是有问题的。那么问题就来了到底是啥问题呢你也分析分析大概是啥问题别老是想着直接找答案啊。问题就是由于转异步了所以 for 循环里面的任务中的 countDownLatch 很快就减到 0 了。于是 await 继续执行所以很快就输出了程序运行时间。然而实际上子任务还在继续执行程序并没有真正完成。9.9ms 只是任务提交到线程池的时间每个任务的数据处理时间还没算呢从日志输出上也可以看出在输出了 StopWatch 的日志后各个任务还在处理数据。这样时间就显得不够真实。那么我们应该怎么办呢很简单嘛需要子任务真正执行完成后父任务的 countDownLatch 才能进行 countDown 的动作。具体实现上就是给子任务再加一个 countDownLatch 栅栏我们希望的运行结果应该是这样的当前线程pool-1-thread-3,—【任务2】开始执行—当前线程pool-1-thread-1,【任务2】开始处理数据1当前线程pool-1-thread-2,【任务2】开始处理数据2当前线程pool-1-thread-3,—【任务2】执行完成—即子任务全部完成之后父任务才能算执行完成这样统计出来的时间才是准确的。思路清晰非常完美再次运行观察日志我们会发现呃怎么回事日志怎么不输出了是的就是不输出了。不输出了就是踩到这个坑了。不论你重启多少次都是这样日志不输出了程序就像是卡着了一样。坑在哪儿上面这个 Demo 已经是我基于遇到的生产问题极力简化后的版本了。现在这个坑也已经呈现在你眼前了。我们一起来分析一波。首先我问你真的在线上遇到这种程序“假死”的问题你会怎么办早几年歪师傅的习惯是抱着代码慢慢啃试图从代码中找到端倪。这样确实是可以但是通常来说效率不高。现在我的习惯是直接把现场 dump 下来分析现场。比如在这个场景下我们直观上的感受是“卡住了”那就 dump 一把线程管它有枣没枣打一杆子再说通过 Dump 文件可以发现线程池的线程都在 MainTest 的第 30 行上 parking 处于等待状态那么第 30 行是啥玩意这行代码在干啥countDownLatchSub.await();是父任务在等待子任务执行结束运行 finally 代码把 countDownLatchSub 的计数 countDown 到 0才会继续执行所以现在的现象就是子任务的 countDownLatchSub 把父任务的拦住了。换句话说就是父任务被拦住是因为子任务的 finally 代码中的 countDownLatchSub.countDown() 方法没有被执行。好那么最关键的问题就来了为什么没有执行
