Skip to content

Commit 68c17c7

Browse files
committed
线程池生产问题
1 parent 20b69f5 commit 68c17c7

1 file changed

Lines changed: 146 additions & 0 deletions

File tree

Lines changed: 146 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,146 @@
1+
在高并发、异步化等场景,线程池的运用可以说无处不在。线程池从本质上来讲,即通过空间换取时间,因为线程的创建和销毁都是要消耗资源和时间的,对于大量使用线程的场景,使用池化管理可以延迟线程的销毁,大大提高单个线程的复用能力,进一步提升整体性能。
2+
3+
今天遇到了一个比较典型的线上问题,刚好和线程池有关,另外涉及到死锁、jstack命令的使用、JDK不同线程池的适合场景等知识点,同时整个调查思路可以借鉴,特此记录和分享一下。
4+
5+
### 01 业务背景描述
6+
7+
该线上问题发生在广告系统的核心扣费服务,首先简单交代下大致的业务流程,方便理解问题。
8+
9+
![](https://user-gold-cdn.xitu.io/2020/5/16/1721c846df1f475c?w=867&h=595&f=png&s=54867)
10+
绿框部分即扣费服务在广告召回扣费流程中所处的位置,简单理解:当用户点击一个广告后,会从C端发起一次实时扣费请求(CPC,按点击扣费模式),扣费服务则承接了该动作的核心业务逻辑:包括执行反作弊策略、创建扣费记录、click日志埋点等。
11+
12+
### 问题现象和业务影响
13+
12月2号晚上11点左右,我们收到了一个线上告警通知:扣费服务的线程池任务队列大小远远超出了设定阈值,而且队列大小随着时间推移还在持续变大。详细告警内容如下:
14+
15+
![](https://user-gold-cdn.xitu.io/2020/5/16/1721c850a5df4320?w=680&h=707&f=png&s=53613)
16+
相应的,我们的广告指标:点击数、收入等也出现了非常明显的下滑,几乎同时发出了业务告警通知。其中,点击数指标对应的曲线表现如下:
17+
18+
![](https://user-gold-cdn.xitu.io/2020/5/16/1721c855a6de5cdb?w=1080&h=412&f=png&s=234814)
19+
20+
该线上故障发生在流量高峰期,持续了将近30分钟后才恢复正常。
21+
22+
### 03 问题调查和事故解决过程
23+
24+
下面详细说下整个事故的调查和分析过程。
25+
26+
第1步:收到线程池任务队列的告警后,我们第一时间查看了扣费服务各个维度的实时数据:包括服务调用量、超时量、错误日志、JVM监控,均未发现异常。
27+
28+
第2步:然后进一步排查了扣费服务依赖的存储资源(mysql、redis、mq),外部服务,发现了事故期间存在大量的数据库慢查询。
29+
30+
![](https://user-gold-cdn.xitu.io/2020/5/16/1721c8603d6d92c4?w=1080&h=282&f=png&s=76572)
31+
32+
上述慢查询来自于事故期间一个刚上线的大数据抽取任务,从扣费服务的mysql数据库中大批量并发抽取数据到hive表。因为扣费流程也涉及到写mysql,猜测这个时候mysql的所有读写性能都受到了影响,果然进一步发现insert操作的耗时也远远大于正常时期。
33+
34+
![](https://user-gold-cdn.xitu.io/2020/5/16/1721c8649c804151?w=1080&h=264&f=png&s=102892)
35+
36+
第3步:我们猜测数据库慢查询影响了扣费流程的性能,从而造成了任务队列的积压,所以决定立马暂定大数据抽取任务。但是很奇怪:停止抽取任务后,数据库的insert性能恢复到正常水平了,但是阻塞队列大小仍然还在持续增大,告警并未消失。
37+
38+
第4步:考虑广告收入还在持续大幅度下跌,进一步分析代码需要比较长的时间,所以决定立即重启服务看看有没有效果。为了保留事故现场,我们保留了一台服务器未做重启,只是把这台机器从服务管理平台摘掉了,这样它不会接收到新的扣费请求。
39+
40+
果然重启服务的杀手锏很管用,各项业务指标都恢复正常了,告警也没有再出现。至此,整个线上故障得到解决,持续了大概30分钟
41+
### 04 问题根本原因的分析过程
42+
43+
下面再详细说下事故根本原因的分析过程。
44+
45+
第1步:第二天上班后,我们猜测那台保留了事故现场的服务器,队列中积压的任务应该都被线程池处理掉了,所以尝试把这台服务器再次挂载上去验证下我们的猜测,结果和预期完全相反,积压的任务仍然都在,而且随着新请求进来,系统告警立刻再次出现了,所以又马上把这台服务器摘了下来。
46+
47+
第2步:线程池积压的几千个任务,经过1个晚上都没被线程池处理掉,我们猜测应该存在死锁情况。所以打算通过jstack命令dump线程快照做下详细分析。
48+
49+
```
50+
#找到扣费服务的进程号
51+
$ jstack pid > /tmp/stack.txt
52+
53+
# 通过进程号dump线程快照,输出到文件中
54+
$ jstack pid > /tmp/stack.txt
55+
```
56+
在jstack的日志文件中,立马发现了:用于扣费的业务线程池的所有线程都处于waiting状态,线程全部卡在了截图中红框部分对应的代码行上,这行代码调用了countDownLatch的await()方法,即等待计数器变为0后释放共享锁。
57+
58+
![](https://user-gold-cdn.xitu.io/2020/5/16/1721c879cee5024e?w=1080&h=575&f=png&s=746973)
59+
第3步:找到上述异常后,距离找到根本原因就很接近了,我们回到代码中继续调查,首先看了下业务代码中使用了newFixedThreadPool线程池,核心线程数设置为25。针对newFixedThreadPool,JDK文档的说明如下:
60+
61+
```
62+
创建一个可重用固定线程数的线程池,以共享的无界队列方式来运行这些线程。如果在所有线程处于活跃状态时提交新任务,则在有可用线程之前,新任务将在队列中等待。
63+
```
64+
关于newFixedThreadPool,核心包括两点:
65+
66+
```
67+
1、最大线程数 = 核心线程数,当所有核心线程都在处理任务时,新进来的任务会提交到任务队列中等待;
68+
69+
2、使用了无界队列:提交给线程池的任务队列是不限制大小的,如果任务被阻塞或者处理变慢,那么显然队列会越来越大。
70+
```
71+
72+
所以,进一步结论是:核心线程全部死锁,新进的任务不对涌入无界队列,导致任务队列不断增加。
73+
74+
第4步:到底是什么原因导致的死锁,我们再次回到jstack日志文件中提示的那行代码做进一步分析。下面是我简化过后的示例代码
75+
76+
```
77+
/**
78+
 * 执行扣费任务
79+
 */
80+
public Result<Integer> executeDeduct(ChargeInputDTO chargeInput) {
81+
  ChargeTask chargeTask = new ChargeTask(chargeInput);
82+
  bizThreadPool.execute(() -> chargeTaskBll.execute(chargeTask ));
83+
  return Result.success();
84+
}
85+
86+
/*
87+
 * 扣费任务的具体业务逻辑
88+
 */
89+
public class ChargeTaskBll implements Runnable {
90+
91+
  public void execute(ChargeTask chargeTask) {
92+
     // 第一步:参数校验
93+
     verifyInputParam(chargeTask);
94+
95+
     // 第二步:执行反作弊子任务
96+
     executeUserSpam(SpamHelper.userConfigs);
97+
98+
     // 第三步:执行扣费
99+
     handlePay(chargeTask);
100+
101+
     // 其他步骤:点击埋点等
102+
     ...
103+
  }
104+
}
105+
106+
/**
107+
 * 执行反作弊子任务
108+
 */
109+
public void executeUserSpam(List<SpamUserConfigDO> configs) {
110+
  if (CollectionUtils.isEmpty(configs)) {
111+
    return;
112+
  }
113+
114+
  try {
115+
    CountDownLatch latch = new CountDownLatch(configs.size());
116+
    for (SpamUserConfigDO config : configs) {
117+
      UserSpamTask task = new UserSpamTask(config,latch);
118+
      bizThreadPool.execute(task);
119+
    }
120+
    latch.await();
121+
  } catch (Exception ex) {
122+
    logger.error("", ex);
123+
  }
124+
}
125+
```
126+
127+
通过上述代码,大家能否发现死锁是怎么发生的呢?根本原因在于:一次扣费行为属于父任务,同时它又包含了多次子任务:子任务用于并行执行反作弊策略,而父任务和子任务使用的是同一个业务线程池。当线程池中全部都是执行中的父任务时,并且所有父任务都存在子任务未执行完,这样就会发生死锁。下面通过1张图再来直观地看下死锁的情况:
128+
129+
![](https://user-gold-cdn.xitu.io/2020/5/16/1721c8931f5898d0?w=880&h=378&f=png&s=75278)
130+
假设核心线程数是2,目前正在执行扣费父任务1和2。另外,反作弊子任务1和3都执行完了,反作弊子任务2和4都积压在任务队列中等待被调度。因为反作弊子任务2和4没执行完,所以扣费父任务1和2都不可能执行完成,这样就发生了死锁,核心线程永远不可能释放,从而造成任务队列不断增大,直到程序OOM crash。
131+
132+
死锁原因清楚后,还有个疑问:上述代码在线上运行很长时间了,为什么现在才暴露出问题呢?另外跟数据库慢查询到底有没有直接关联呢?
133+
134+
暂时我们还没有复现证实,但是可以推断出:上述代码一定存在死锁的概率,尤其在高并发或者任务处理变慢的情况下,概率会大大增加。数据库慢查询应该就是导致此次事故出现的导火索。
135+
136+
### 05 解决方案
137+
138+
弄清楚根本原因后,最简单的解决方案就是:增加一个新的业务线程池,用来隔离父子任务,现有的线程池只用来处理扣费任务,新的线程池用来处理反作弊任务。这样就可以彻底避免死锁的情况了。
139+
140+
### 06 问题总结
141+
142+
回顾事故的解决过程以及扣费的技术方案,存在以下几点待继续优化:
143+
144+
1、使用固定线程数的线程池存在OOM风险,在阿里巴巴Java开发手册中也明确指出,而且用的词是『不允许』使用Executors创建线程池。 而是通过ThreadPoolExecutor去创建,这样让写的同学能更加明确线程池的运行规则和核心参数设置,规避资源耗尽的风险。
145+
146+
2、广告的扣费场景是一个异步过程,通过线程池或者MQ来实现异步化处理都是可选的方案。另外,极个别的点击请求丢失不扣费从业务上是允许的,但是大批量的请求丢弃不处理且没有补偿方案是不允许的。后续采用有界队列后,拒绝策略可以考虑发送MQ做重试处理。

0 commit comments

Comments
 (0)