1. 故障背景

昨天晚上，我刚到家里打开公司群，就看见群里有人讨论：线上环境出现大量RPC请求报错，异常原因：被线程池拒绝。虽然异常量很大，但是异常服务非核心服务，属于系统旁路，服务于数据核对任务，即使有大量异常，也没有实际的影响。

原来有人在线上刷数据，产生了大量 binlog，数据核对任务的请求量大幅上涨，导致线程池被打满。因为并非我负责的工作内容，也不熟悉这部分业务，所以没有特别留意。

第二天我仔细思考了一下，觉得疑点很多，推导过程过于简单，证据链不足，最终结论不扎实，问题根源也许另有原因。

1.1 疑点

• 请求量大幅上涨， 上涨前后请求量是多少？
• 线程池被打满， 线程池初始值和最大值是多少，线程池队列长度是多少？
• 线程池拒绝策略是什么？
• 影响了哪些接口，这些接口的耗时波动情况？
• 服务的 CPU 负载和 GC情况如何？
• 线程池被打满的原因仅仅是请求量大幅上涨吗？

带着以上的几点疑问，第二天一到公司，我就迫不及待地打开各种监控大盘，开始排查问题，最后还真叫我揪出问题根源了。

因为公司的监控系统有水印，所以我只能陈述结论，不能截图了。

2. 排查过程

2.1 请求量的波动情况

• 单机 RPC的 QPS从 300/s 涨到了 450/s。
• Kafka 消息 QPS 50/s 无 明显波动。
• 无其他请求入口和 无定时任务。

这也能叫请求量大幅上涨，请求量增加 150/s 能打爆线程池？就这么糊弄老板…… ，由此我坚定了判断：故障另有根因

2.2 RPC 线程池配置和监控

线上的端口并没有全部被打爆，仅有 1 个 RPC 端口 8001 被打爆。所以我特地查看了8001 的线程池配置。

• 初始线程数 10
• 最大线程数 1024（数量过大，配置的有点随意了）
• 队列长度 0
• 拒绝策略是抛出异常立即拒绝。
• 在 20:11到 20:13 分，线程从初始线程数10，直线涨到了1024 。

2.3 思考

QPS 450次/秒 需要 1024 个线程处理吗？按照我的经验来看，只要接口的耗时在 100ms 以内，不可能需要如此多的线程，太蹊跷了。

2.4 接口耗时波动情况

接口 平均耗时从 5.7 ms，增加到 17000毫秒。

接口耗时大幅增加。后来和他们沟通，他们当时也看了接口耗时监控。他们认为之所以平均耗时这么高，是因为RPC 请求在排队，增加了处理耗时，所以监控平均耗时大幅增长。

这是他们的误区，错误的地方有两个。

• 此RPC接口线程池的队列长度为 0，拒绝策略是抛出异常。当没有可用线程，请求会即被拒绝，请求不会排队，所以无排队等待时间。
• 公司的监控系统分服务端监控和调用端监控，服务端的耗时监控不包含 处理连接的时间，不包含 RPC线程池排队的时间。仅仅是 RPC 线程池实际处理请求的耗时。RPC 调用端的监控包含 RPC 网络耗时、连接耗时、排队耗时、处理业务逻辑耗时、服务端GC 耗时等等。

他们误认为耗时大幅增加是因为请求在排队，因此忽略了至关重要的这条线索：接口实际处理阶段的性能严重恶化，吞吐量大幅降低，所以线程池大幅增长，直至被打满。

接下来我开始分析，接口性能恶化的根本原因是什么？

• CPU 被打满？导致请求接口性能恶化？
• 频繁GC ，导致接口性能差？
• 调用下游 RPC 接口耗时大幅增加 ？
• 调用 SQL，耗时大幅增加？
• 调用 Redis，耗时大幅增加
• 其他外部调用耗时大幅增加？

2.5 其他耗时监控情况

我快速的排查了所有可能的外部调用耗时均没有明显波动。也查看了机器的负载情况，cpu和网络负载 均不高，显然故障的根源不在以上方向。

• CPU 负载极低。在故障期间，cpu.busy 负载在 15%，还不到午高峰，显然根源不是CPU 负载高。
• gc 情况良好。无 FullGC，youngGC 1 分钟 2 次（younggc 频繁，会导致 cpu 负载高，会使接口性能恶化）
• 下游 RPC 接口耗时无明显波动。我查看了服务调用 RPC 接口的耗时监控，所有的接口耗时无明显波动。
• SQL 调用耗时无明显波动。
• 调用 Redis 耗时无明显波动。
• 其他下游系统调用无明显波动。（如 Tair、ES 等）

2.6 开始研究代码

为什么我一开始不看代码，因为这块内容不是我负责的内容，我不熟悉代码。

直至打开代码看了一眼，恶心死我了。代码非常复杂，分支非常多，嵌套层次非常深，方法又臭又长，堪称代码屎山的珠穆朗玛峰，多看一眼就能吐。接口的内部分支将近 10 个，每个分支方法都是一大坨代码。

这个接口是上游 BCP 核对系统定义的 SPI接口，属于聚合接口，并非单一职责的接口。看了 10 分钟以后，还是找不到问题根源。因此我换了问题排查方向，我开始排查异常 Trace。

2.7 从异常 Trace 发现了关键线索

我所在公司的基建能力还是很强大的。系统的异常 Trace 中标注了各个阶段的处理耗时，包括所有外部接口的耗时。如SQL、 RPC、 Redis等。

我发现确实是内部代码处理的问题，因为 trace 显示，在两个 SQL 请求中间，系统停顿长达 1 秒多。不知道系统在这 1 秒执行哪些内容。我查看了这两个接口的耗时，监控显示：SQL 执行很快，应该不是SQL 的问题

机器也没有发生 FullGC，到底是什么原因呢？

前面提到，故障接口是一个聚合接口，我不清楚具体哪个分支出现了问题，但是异常 Trace 中指明了具体的分支。

我开始排查具体的分支方法……， 然而捏着鼻子扒拉了半天，也没有找到原因……

2.8 山穷水复疑无路，柳暗花明又一村

这一坨屎山代码看得我实在恶心，我静静地冥想了 1 分钟才缓过劲。

• 没有外部调用的情况下，阻塞线程的可能性有哪些？
• 有没有加锁? Synchiozed 关键字？

于是我按着关键字搜索Synchiozed关键词，一无所获，代码中基本没有加锁的地方。

马上中午了，肚子很饿，就当我要放弃的时候。随手扒拉了一下，在类的属性声明里，看到了 Guava限流器。

激动的心，颤抖的手

private static final RateLimiter RATE_LIMITER = RateLimiter.create(10, 20, TimeUnit.SECONDS);

限流器：1 分钟 10次调用。

于是立即查看限流器的使用场景，和异常 Trace 阻塞的地方完全一致。

嘴角出现一丝很容易察觉到的微笑。

破案了，真相永远只有一个。

3. 问题结论

Guava 限流器的阈值过低，每秒最大请求量只有10次。当并发量超过这个阈值时，大量线程被阻塞，RPC线程池不断增加新线程来处理新的请求，直到达到最大线程数。线程池达到最大容量后，无法再接收新的请求，导致大量的后续请求被线程池拒绝。

于是我开始建群、摇人。把相关的同学，还有老板们，拉进了群里。把相关截图和结论发到了群里。

由于不是紧急问题，所以我开开心心的去吃午饭了。后面的事就是他们优化代码了。

出现问题不要慌张，也不要吃瓜嗑瓜子。行动起来，此时是专属你的柯南时刻