前言
Dubbo是一个阿里开源的一款RPC框架，底层网络通信基于Netty，并且分离了业务线程池和IO线程池，本次问题就是业务线程池积压爆满导致线程池拒绝接受新的请求。
问题
由于网络抖动，请求的流量激增，各项指标出现了很高的锯齿状，同时Kibana日志里大量出现了Dubbo线程繁忙的错误。
[DUBBO] Thread pool is EXHAUSTED! Thread Name: DubboServerHandler-10.1.26.158:20880,
Pool Size: 200 (active: 200, core: 200, max: 200, largest: 200), Task: 138833487 (completed: 138833287), Executor status:(isShutdown:false, isTerminated:false, isTerminating:false),
in dubbo://10.1.26.158:20880!, dubbo version: 2.7.3, current host: 10.1.26.158
分
分析
出现这种情况有以下几种情况
- 服务提供者执行业务耗时长，同时有超过200个线程（Dubbo默认线程数）同时在执行，导致线程池无法分配出新的线程资源来处理新请求
- FullGC的stop-the-world 时间过长，导致所有线程处于等待状态，只有GC线程处于Runnable清理垃圾
- Dubbo业务线程对同一资源有访问，并且有锁，无法并发访问，导致排队从而影响性能
- and soon...
排查思路
- 首先看了一下Grafana上服务的GC时间，发现并没有长时间的GC消耗，内存回收有点频繁，但是可以接受。
- 以前也没有排查过这种问题，就去阅读了一下Dubbo源码，发现Dubbo竟然还有如此的骚操作，会打印当时出错的线程栈信息
// Dubbo的线程池拒绝策略
public class AbortPolicyWithReport extends ThreadPoolExecutor.AbortPolicy {
// 当线程池无法接受新的请求，拒绝时执行该方法
@Override
public void rejectedExecution(Runnable r, ThreadPoolExecutor e) {
String msg = String.format("Thread pool is EXHAUSTED!" +
" Thread Name: %s, Pool Size: %d (active: %d, core: %d, max: %d, largest: %d), Task: %d (completed: "
+ "%d)," +
" Executor status:(isShutdown:%s, isTerminated:%s, isTerminating:%s), in %s://%s:%d!",
threadName, e.getPoolSize(), e.getActiveCount(), e.getCorePoolSize(), e.getMaximumPoolSize(),
e.getLargestPoolSize(),
e.getTaskCount(), e.getCompletedTaskCount(), e.isShutdown(), e.isTerminated(), e.isTerminating(),
url.getProtocol(), url.getIp(), url.getPort());
logger.warn(msg);
// 关键一步 这里会dumpJStack，把当时的线程堆栈信息输出到home目录下的Dubbo_JStack.log中（在没有自定义目录的前提下，输出在home目录下）
dumpJStack();
dispatchThreadPoolExhaustedEvent(msg);
throw new RejectedExecutionException(msg);
}
}
-
进入k8s pod，copy出了日志文件拿到idea分析，通过分析发现有这么文件中有大量的线程状态是 TIME_WAITING，Dubbo的200个线程处于 TIME_WAITING 中。继续排查发现大量等待是在一个调用一个下游的Dubbo服务。
线程堆栈分析图
-
继续跟踪下游服务，也出现了Dubbo线程池爆满，导出日志分析，得到结果如下，Dubbo线程有189个都被BLOCKED。
线程堆栈分析图
-
排查BLOCKED日志，最终定位到DefaultJvmCacheFactory在查缓存的时候，由于锁使用不当，导致线程进行了排队处理，并且内部有一些耗时的操作。
线程堆栈之一
-
修改锁条件，优化代码。
Conclusion
像生产上出现这种问题，有时候是某一段时间发生的，后面又恢复正常，所以无法拿到那时候的线程栈日志，所以不好定位问题。所幸Dubbo还有这种骚操作，在出现问题时打印了线程堆栈信息，能够很方便的定位到问题。
其实可以在代码里挂钩子，当达到某个条件时，执行钩子程序打印堆栈日志，可以参考Dubbo的做法。但是频繁输出jStack对性能也有损耗哦，所以最好有一份数据能用来分析就好，如果要有多份，记得控制好输出频率。
网友评论