大家好，我是五阳。

1. 故障背景

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

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

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

1.1 疑点

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

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

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 请求在排队，增加了处理耗时，所以监控平均耗时大幅增长。

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

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

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

• 
  
• 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线程池不断增加新线程来处理新的请求，直到达到最大线程数。线程池达到最大容量后，无法再接收新的请求，导致大量的后续请求被线程池拒绝。

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

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

4. 思考总结

4.1 八股文不是完全无用，有些八股文是有用的

有人质疑面试为什么要问八股文？ 也许大部分情况下，大部分八股文是没有用的，然而在排查问题时，多知道一些八股文是有助于排查问题的。

例如要明白线程池的原理、要明白 RPC 的请求处理过程、要知道影响接口耗时的可能性有哪些，这样才能带着疑问去追踪线索。

4.2 可靠好用的监控系统，能提高排查效率

这个问题排查花了我 1.5 小时，大部分时间是在扒拉代码，实际查看监控只用了半小时。如果没有全面、好用的监控，线上出了问题真的很难快速定位根源。

此外应该熟悉公司的监控系统。他们因为不清楚公司监控系统，误认为接口监控耗时包含了线程池排队时间，忽略了 接口性能恶化 这个关键结论，所以得出错误结论。

4.2 排查问题时，要像侦探一样，不放过任何线索，确保证据链完整，逻辑通顺。

故障发生后第一时间应该是止损，其次才是排查问题。

出现故障后，故障制造者的心理往往处于慌乱状态，逻辑性较差，会倾向于为自己开脱责任。这次故障后，他们给定的结论就是：因为请求量大幅上涨，所以线程池被打满。 这个结论逻辑不通。没有推导过程，跳过了很多推导环节，所以得出错误结论，掩盖了问题的根源~

其他人作为局外人，逻辑性会更强，可以保持冷静状态，这是老板们的价值所在，他们可以不断地提出问题，在回答问题、质疑、继续排查的循环中，不断逼近事情的真相。

最终一定要重视证据链条的完整。别放过任何线索。

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

我是五阳，关注我，追踪更多我在大厂的工作经历和大型翻车现场。