线程池运用不当的一次线上事故
共 3982字，需浏览 8分钟
·
2021-11-19 15:22
在高并发、异步化等场景，线程池的运用可以说无处不在。线程池从本质上来讲，即通过空间换取时间，因为线程的创建和销毁都是要消耗资源和时间的，对于大量使用线程的场景，使用池化管理可以延迟线程的销毁，大大提高单个线程的复用能力，进一步提升整体性能。
今天遇到了一个比较典型的线上问题，刚好和线程池有关，另外涉及到死锁、jstack命令的使用、JDK不同线程池的适合场景等知识点，同时整个调查思路可以借鉴，特此记录和分享一下。
01 业务背景描述
该线上问题发生在广告系统的核心扣费服务，首先简单交代下大致的业务流程，方便理解问题。
绿框部分即扣费服务在广告召回扣费流程中所处的位置，简单理解：当用户点击一个广告后，会从C端发起一次实时扣费请求(CPC，按点击扣费模式)，扣费服务则承接了该动作的核心业务逻辑：包括执行反作弊策略、创建扣费记录、click日志埋点等。
12月2号晚上11点左右，我们收到了一个线上告警通知：扣费服务的线程池任务队列大小远远超出了设定阈值，而且队列大小随着时间推移还在持续变大。详细告警内容如下：
相应的，我们的广告指标：点击数、收入等也出现了非常明显的下滑，几乎同时发出了业务告警通知。其中，点击数指标对应的曲线表现如下：
该线上故障发生在流量高峰期，持续了将近30分钟后才恢复正常。
下面详细说下整个事故的调查和分析过程。
第2步：然后进一步排查了扣费服务依赖的存储资源（mysql、redis、mq），外部服务，发现了事故期间存在大量的数据库慢查询。
上述慢查询来自于事故期间一个刚上线的大数据抽取任务，从扣费服务的mysql数据库中大批量并发抽取数据到hive表。因为扣费流程也涉及到写mysql，猜测这个时候mysql的所有读写性能都受到了影响，果然进一步发现insert操作的耗时也远远大于正常时期。
第3步：我们猜测数据库慢查询影响了扣费流程的性能，从而造成了任务队列的积压，所以决定立马暂定大数据抽取任务。但是很奇怪：停止抽取任务后，数据库的insert性能恢复到正常水平了，但是阻塞队列大小仍然还在持续增大，告警并未消失。
第4步：考虑广告收入还在持续大幅度下跌，进一步分析代码需要比较长的时间，所以决定立即重启服务看看有没有效果。为了保留事故现场，我们保留了一台服务器未做重启，只是把这台机器从服务管理平台摘掉了，这样它不会接收到新的扣费请求。
果然重启服务的杀手锏很管用，各项业务指标都恢复正常了，告警也没有再出现。至此，整个线上故障得到解决，持续了大概30分钟。
下面再详细说下事故根本原因的分析过程。
第1步：第二天上班后，我们猜测那台保留了事故现场的服务器，队列中积压的任务应该都被线程池处理掉了，所以尝试把这台服务器再次挂载上去验证下我们的猜测，结果和预期完全相反，积压的任务仍然都在，而且随着新请求进来，系统告警立刻再次出现了，所以又马上把这台服务器摘了下来。
第2步：线程池积压的几千个任务，经过1个晚上都没被线程池处理掉，我们猜测应该存在死锁情况。所以打算通过jstack命令dump线程快照做下详细分析。
#找到扣费服务的进程号
$ jstack pid > /tmp/stack.txt
# 通过进程号dump线程快照，输出到文件中
$ jstack pid > /tmp/stack.txt
在jstack的日志文件中，立马发现了：用于扣费的业务线程池的所有线程都处于waiting状态，线程全部卡在了截图中红框部分对应的代码行上，这行代码调用了countDownLatch的await()方法，即等待计数器变为0后释放共享锁。
第3步：找到上述异常后，距离找到根本原因就很接近了，我们回到代码中继续调查，首先看了下业务代码中使用了newFixedThreadPool线程池，核心线程数设置为25。针对newFixedThreadPool，JDK文档的说明如下：
创建一个可重用固定线程数的线程池，以共享的无界队列方式来运行这些线程。如果在所有线程处于活跃状态时提交新任务，则在有可用线程之前，新任务将在队列中等待。
1、最大线程数 = 核心线程数，当所有核心线程都在处理任务时，新进来的任务会提交到任务队列中等待；
2、使用了无界队列：提交给线程池的任务队列是不限制大小的，如果任务被阻塞或者处理变慢，那么显然队列会越来越大。
所以，进一步结论是：核心线程全部死锁，新进的任务不对涌入无界队列，导致任务队列不断增加。
/**
* 执行扣费任务
*/
public Result executeDeduct(ChargeInputDTO chargeInput) {
ChargeTask chargeTask = new ChargeTask(chargeInput);
bizThreadPool.execute(() -> chargeTaskBll.execute(chargeTask ));
return Result.success();
}
/*
* 扣费任务的具体业务逻辑
*/
public class ChargeTaskBll implements Runnable {
public void execute(ChargeTask chargeTask) {
// 第一步：参数校验
verifyInputParam(chargeTask);
// 第二步：执行反作弊子任务
executeUserSpam(SpamHelper.userConfigs);
// 第三步：执行扣费
handlePay(chargeTask);
// 其他步骤：点击埋点等
...
}
}
/**
* 执行反作弊子任务
*/
public void executeUserSpam(List configs) {
if (CollectionUtils.isEmpty(configs)) {
return;
}
try {
CountDownLatch latch = new CountDownLatch(configs.size());
for (SpamUserConfigDO config : configs) {
UserSpamTask task = new UserSpamTask(config,latch);
bizThreadPool.execute(task);
}
latch.await();
} catch (Exception ex) {
logger.error("", ex);
}
}
通过上述代码，大家能否发现死锁是怎么发生的呢？根本原因在于：一次扣费行为属于父任务，同时它又包含了多次子任务：子任务用于并行执行反作弊策略，而父任务和子任务使用的是同一个业务线程池。当线程池中全部都是执行中的父任务时，并且所有父任务都存在子任务未执行完，这样就会发生死锁。下面通过1张图再来直观地看下死锁的情况：
假设核心线程数是2，目前正在执行扣费父任务1和2。另外，反作弊子任务1和3都执行完了，反作弊子任务2和4都积压在任务队列中等待被调度。因为反作弊子任务2和4没执行完，所以扣费父任务1和2都不可能执行完成，这样就发生了死锁，核心线程永远不可能释放，从而造成任务队列不断增大，直到程序OOM crash。
死锁原因清楚后，还有个疑问：上述代码在线上运行很长时间了，为什么现在才暴露出问题呢？另外跟数据库慢查询到底有没有直接关联呢？
暂时我们还没有复现证实，但是可以推断出：上述代码一定存在死锁的概率，尤其在高并发或者任务处理变慢的情况下，概率会大大增加。数据库慢查询应该就是导致此次事故出现的导火索。
05 解决方案
弄清楚根本原因后，最简单的解决方案就是：增加一个新的业务线程池，用来隔离父子任务，现有的线程池只用来处理扣费任务，新的线程池用来处理反作弊任务。这样就可以彻底避免死锁的情况了。
06 问题总结
回顾事故的解决过程以及扣费的技术方案，存在以下几点待继续优化：
推荐阅读：
欢迎关注微信公众号：互联网全栈架构，收取更多有价值的信息。